RE: pasynOctetSyncIO error reading image status=4

[Mark Rivers via Tech-talk <tech-talk at aps.anl.gov>]

Hi Michael,

 

If you look at your previous message you see things like this:

 

2023/03/02 16:51:48.603 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117503, maxRead=1, nRead=1959

2023/03/02 16:51:55.552 PSL:getImage: error reading image, status=1, dataLen=12117504, nCopied=8333289, maxRead=2048, nRead=0

2023/03/02 16:52:05.499 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117502, maxRead=2, nRead=1603

2023/03/02 16:52:10.847 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117502, maxRead=2, nRead=51

 

I think that dataLen is the expected number of bytes to received, and nCopied is the number actually received so far.  Note that in 3 of the cases it is just 1 or 2 bytes short.  maxRead is the number of bytes it is trying to read.  But it then gets a broken connection.

 

Mark

 

 

From: Sintschuk, Michael <michael.sintschuk at bam.de>
Sent: Friday, March 3, 2023 11:59 AM
To: Mark Rivers <rivers at cars.uchicago.edu>; tech-talk <tech-talk at aps.anl.gov>
Subject: AW: pasynOctetSyncIO error reading image status=4

 

Hi Mark,

 

thanks for the explanation. With enabling the asynTraces it is visible that sometimes indeed the connection crashes. Here are the last output lines when an image was acquired without an error (and the exposure time was then set to 2.5s):

 

2023/03/03 16:22:16.650 hzb1.exp.helmholtz-berlin.de:50000 read 952

\305\000\310\000\304\000\303\000\306\000\312\000\273\000\271\000\273\000\313\000\277\000\303\000\306\000\307\000\303\000\312\000\270\000\304\000\314\000\300\000\315\000\304\000\272\000\324\000\311\000\274\000\311\000\320\000\307\000\307\000\323\000\305\000\275\000\307\000\302\000\303\000\303\000\312\000\307\000\273\000

2023/03/03 16:22:16.650 hzb1.exp.helmholtz-berlin.de:50000 read 1536

\305\000\301\000\304\000\277\000\314\000\301\000\322\000\304\000\316\000\314\000\312\000\304\000\276\000\314\000\273\000\316\000\276\000\307\000\300\000\276\000\303\000\304\000\272\000\261\000\311\000\275\000\307\000\301\000\321\000\276\000\310\000\310\000\307\000\271\000\324\000\277\000\334\000\301\000\313\000\312\000

2023/03/03 16:22:23.727 hzb1.exp.helmholtz-berlin.de:50000 write 15

SetExpoMS;2500\n

 

And here are the last output lines when an image was acquired with the described error:

 

2023/03/03 16:22:59.989 hzb1.exp.helmholtz-berlin.de:50000 read 952

\304\000\313\000\300\000\275\000\310\000\306\000\310\000\302\000\306\000\302\000\310\000\314\000\300\000\270\000\311\000\317\000\273\000\311\000\305\000\276\000\305\000\316\000\304\000\276\000\304\000\305\000\301\000\312\000\277\000\303\000\322\000\300\000\306\000\305\000\304\000\303\000\312\000\313\000\276\000\326\000

2023/03/03 16:22:59.989 hzb1.exp.helmholtz-berlin.de:50000 read 1536

\303\000\277\000\322\000\310\000\304\000\306\000\301\000\302\000\273\000\301\000\313\000\312\000\313\000\312\000\304\000\300\000\310\000\263\000\315\000\312\000\265\000\317\000\312\000\322\000\305\000\315\000\301\000\311\000\276\000\325\000\302\000\315\000\316\000\275\000\267\000\306\000\303\000\312\000\305\000\314\000

2023/03/03 16:23:00.004 hzb1.exp.helmholtz-berlin.de:50000 read 0

 

In that case „read 0“ always appears.

Here is the last output when setting “asynSetTraceMask("PSLServer",0,255)”, to show everything:

 

2023/03/03 16:17:32.587 hzb1.exp.helmholtz-berlin.de:50000 read.

2023/03/03 16:17:32.587 hzb1.exp.helmholtz-berlin.de:50000 read 952

\315\000\304\000\300\000\310\000\271\000\310\000\306\000\315\000\306\000\305\000\325\000\310\000\312\000\312\000\307\000\311\000\302\000\313\000\303\000\266\000\316\000\271\000\302\000\313\000\310\000\313\000\307\000\311\000\302\000\315\000\307\000\311\000\300\000\303\000\305\000\310\000\303\000\277\000\307\000\272\000

2023/03/03 16:17:32.587 PSLServer read 952 bytes eom=0

\315\000\304\000\300\000\310\000\271\000\310\000\306\000\315\000\306\000\305\000\325\000\310\000\312\000\312\000\307\000\311\000\302\000\313\000\303\000\266\000\316\000\271\000\302\000\313\000\310\000\313\000\307\000\311\000\302\000\315\000\307\000\311\000\300\000\303\000\305\000\310\000\303\000\277\000\307\000\272\000

2023/03/03 16:17:32.587 asynOctetSyncIO read:

\000\313\000\306\000\320\000\301\000\267\000\306\000\312\000\313\000\305\000\303\000\301\000\305\000\275\000\323\000\325\000\317\000\307\000\274\000\315\000\303\000\313\000\301\000\305\000\312\000\275\000\300\000\312\000\304\000\313\000\302\000\303\000\264\000\303\000\304\000\301\000\301\000\276\000\303\000\310\000\305

2023/03/03 16:17:32.587 PSLServer queueUnlockPort

2023/03/03 16:17:32.587 PSLServer asynManager::queueUnlockPort waiting for event

2023/03/03 16:17:32.587 PSLServer queueUnlockPort unlock mutex 0x7f34ac000c90 complete.

2023/03/03 16:17:32.587 PSLServer asynManager::queueLockPort locking port

2023/03/03 16:17:32.587 PSLServer asynManager::queueLockPort taking mutex 0x7f34ac000c90

2023/03/03 16:17:32.587 PSLServer asynManager::queueLockPort queueing request

2023/03/03 16:17:32.587 PSLServer addr -1 queueRequest priority 0 not lockHolder

2023/03/03 16:17:32.587 PSLServer schedule queueRequest timeout in 2.000000 seconds

2023/03/03 16:17:32.587 PSLServer asynManager::queueLockPort waiting for event

2023/03/03 16:17:32.587 asynManager::portThread port=PSLServer callback

2023/03/03 16:17:32.587 PSLServer asynManager::queueLockPortCallback signaling begin event

2023/03/03 16:17:32.587 PSLServer asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2023/03/03 16:17:32.587 PSLServer asynManager::queueLockPort got event from callback

2023/03/03 16:17:32.587 hzb1.exp.helmholtz-berlin.de:50000 read.

2023/03/03 16:17:32.587 hzb1.exp.helmholtz-berlin.de:50000 read 1536

\267\000\312\000\301\000\310\000\300\000\315\000\305\000\310\000\314\000\266\000\303\000\301\000\306\000\271\000\274\000\315\000\303\000\317\000\277\000\275\000\304\000\277\000\271\000\303\000\312\000\304\000\322\000\314\000\313\000\304\000\303\000\273\000\315\000\316\000\306\000\300\000\302\000\303\000\271\000\311\000

2023/03/03 16:17:32.587 PSLServer read 1536 bytes eom=0

\267\000\312\000\301\000\310\000\300\000\315\000\305\000\310\000\314\000\266\000\303\000\301\000\306\000\271\000\274\000\315\000\303\000\317\000\277\000\275\000\304\000\277\000\271\000\303\000\312\000\304\000\322\000\314\000\313\000\304\000\303\000\273\000\315\000\316\000\306\000\300\000\302\000\303\000\271\000\311\000

2023/03/03 16:17:32.587 hzb1.exp.helmholtz-berlin.de:50000 read.

2023/03/03 16:17:32.605 hzb1.exp.helmholtz-berlin.de:50000 read 0

2023/03/03 16:17:32.605 Closing hzb1.exp.helmholtz-berlin.de:50000 connection (fd 3): Read from broken connection

2023/03/03 16:17:32.605 PSLServer read 0 bytes eom=4

2023/03/03 16:17:32.605 asynOctetSyncIO read:

\000\303\000\314\000\311\000\305\000\304\000\304\000\317\000\303\000\307\000\300\000\317\000\275\000\302\000\304\000\310\000\300\000\303\000\313\000\305\000\311\000\331\000\302\000\300\000\307\000\311\000\272\000\300\000\307\000\304\000\305\000\300\000\301\000\302\000\307\000\303\000\310\000\310\000\307\000\276\000\276

2023/03/03 16:17:32.605 PSLServer queueUnlockPort

2023/03/03 16:17:32.605 PSLServer asynManager::queueUnlockPort waiting for event

2023/03/03 16:17:32.605 PSLServer queueUnlockPort unlock mutex 0x7f34ac000c90 complete.

2023/03/03 16:17:32.605 PSLServer asynManager::queueLockPort locking port

2023/03/03 16:17:32.605 PSLServer asynManager::queueLockPort taking mutex 0x7f34ac000c90

2023/03/03 16:17:32.605 PSLServer asynManager::queueLockPort queueing request

2023/03/03 16:17:32.610 PSLServer addr -1 queueRequest priority 3 not lockHolder

2023/03/03 16:17:32.610 asynManager connect queueCallback port:PSLServer

2023/03/03 16:17:32.610 Attempting to connect to hzb1.exp.helmholtz-berlin.de:50000  reason:0  fd:-1

2023/03/03 16:17:32.611 Opened connection OK to hzb1.exp.helmholtz-berlin.de:50000

 

But for me there is no additional info in that output. Only that the connection is opened again after it broke…

Today I tried to get rid of that error by putting some epicsThreadSleeps in different code-places before actually reading the image but without luck. Next week I try to vary the size of “fromServer_[MAX_MESSAGE_SIZE]”.

But if there are some hints from you or someone else, I’m happy to try them!

 

Michael

 

Von: Mark Rivers <rivers at cars.uchicago.edu>
Gesendet: Donnerstag, 2. März 2023 18:43
An: Sintschuk, Michael <michael.sintschuk at bam.de>; tech-talk <tech-talk at aps.anl.gov>
Betreff: RE: pasynOctetSyncIO error reading image status=4

 

SICHERHEITSHINWEIS: Diese E-Mail wurde von außerhalb an die BAM gesendet. Bitte klicken Sie nicht auf Links oder öffnen Anhänge, bevor Sie nicht den Absender verifiziert haben und sicher sind, dass der Inhalt vertrauenswürdig ist.
This message was sent from outside of BAM. Please do not click links or open attachments unless you recognize the sender and know the content is trustworthy.

Hi Michael,

 

The message is printed here:

 

https://github.com/areaDetector/ADPSL/blob/b1924604516eca006cab8a63b7c9fc094df35fe2/pslApp/src/PSL.cpp#L589

 

The status is the return from pasynOctetSyncIO->read in this line:

https://github.com/areaDetector/ADPSL/blob/b1924604516eca006cab8a63b7c9fc094df35fe2/pslApp/src/PSL.cpp#L585

 

pasynOctetSyncIO->read is here, and it just returns the status from pasynOctet->read().

https://github.com/epics-modules/asyn/blob/3434727d5a1ba090bb423b4c7395fdb77a57eebd/asyn/interfaces/asynOctetSyncIO.c#L218

 

The asynStatus enums are defined here:

https://github.com/epics-modules/asyn/blob/3434727d5a1ba090bb423b4c7395fdb77a57eebd/asyn/asynDriver/asynDriver.h#L48

 

status=4 thus means asynDisconnected.  That seems to indicated that the socket between the IOC and the PSL server has disconnected.

 

You can turn on asynTraceIODriver on that socket and see exactly what is being sent and received.  You can uncomment and change these lines in your st.cmd:

 

asynSetTraceIOMask("PSLServer",0,ESCAPE)

asynSetTraceMask("PSLServer",0,ERROR|DRIVER)

asynSetTraceFile("PSLServer", 0, "PSLServer.out")

 

The last line will send the output to a file, which may be more convenient.  You may also need to add this line:

 

asynSetTraceIOTruncateSize(“PSLServer”, 0, 10000000) so that you do not limit the output to just 80 bytes.

 

Mark

 

 

 

 

From: Tech-talk <tech-talk-bounces at aps.anl.gov> On Behalf Of Sintschuk, Michael via Tech-talk
Sent: Thursday, March 2, 2023 11:20 AM
To: tech-talk <tech-talk at aps.anl.gov>
Subject: pasynOctetSyncIO error reading image status=4

 

Hi all,

 

like announced in this tech-talk:

https://epics.anl.gov/tech-talk/2021/msg02173.php

I’m now trying to setup a FDS camera from Photonic Science with the ADPSL module. After adding some slightly changes to the Keywords that are send to the PSViewer-server or received from it, I can communicate with the camera without any IOC-crashes. I forked the ADPSL-module here:

https://github.com/MichaS-git/ADPSL

 

However, from time to time I receive some deprecated images (some lines show ~50k counts, although it is a darkfield image and the rest image has ~200 counts) and the IOC shows this error code:

 

2023/03/02 16:51:43.266 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117503, maxRead=1, nRead=1453

 

In the PSViewer (the vendor software that runs parallel) the image appears fine. It seems to appear random but I have the feeling that it happens more often when I increase the exposure time to higher than ~2s. Can anyone say what that error with status=4 actually means?

 

Here is my complete IOC-start with the errors:

 

#!../../bin/linux-x86_64/PSLioc

## You may have to change PSLioc to something else

## everywhere it appears in this file

< envPaths

epicsEnvSet("IOC","PSLioc")

epicsEnvSet("TOP","/mnt/soft-bam01/epics/IOC/PSLioc")

epicsEnvSet("SUPPORT","/soft/epics/inst-3.15.7")

epicsEnvSet("ASYN","/soft/epics/inst-3.15.7/asyn/4-40-1")

epicsEnvSet("BUSY","/soft/epics/inst-3.15.7/busy/1-7-2")

epicsEnvSet("CALC","/soft/epics/inst-3.15.7/calc/3-7-4")

epicsEnvSet("SSCAN","/soft/epics/inst-3.15.7/sscan/2-11-3")

epicsEnvSet("AUTOSAVE","/soft/epics/inst-3.15.7/autosave/5-10-1")

epicsEnvSet("AREA_DETECTOR","/soft/epics/inst-3.15.7/areaDetector-R3-11")

epicsEnvSet("ADCORE","/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore")

epicsEnvSet("ADSUPPORT","/soft/epics/inst-3.15.7/areaDetector-R3-11/ADSupport")

epicsEnvSet("ADPSL","/soft/epics/inst-3.15.7/areaDetector-R3-11/ADPSL")

epicsEnvSet("EPICS_BASE","/soft/epics/base")

## Register all support components

dbLoadDatabase("../../dbd/PSLioc.dbd",0,0)

PSLioc_registerRecordDeviceDriver(pdbbase)

epicsEnvSet("PREFIX", "XRFDS:")

epicsEnvSet("PORT",   "PSL")

epicsEnvSet("QSIZE",  "20")

epicsEnvSet("XSIZE",  "2744")

epicsEnvSet("YSIZE",  "2208")

epicsEnvSet("NCHANS", "2048")

#epicsEnvSet("CBUFFS", "500")

# The search path for database files

epicsEnvSet("EPICS_DB_INCLUDE_PATH", "/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore/db")

###

# Create the asyn port to talk to the PSL server on port 50000

drvAsynIPPortConfigure("PSLServer","hzb1.exp.helmholtz-berlin.de:50000", 0, 0, 0)

asynOctetSetOutputEos("PSLServer", 0, "\n")

asynOctetSetInputEos("PSLServer", 0, "\n")

#asynSetTraceIOMask("PSLServer",0,2)

#asynSetTraceMask("PSLServer",0,255)

#asynSetTraceFile("PSLServer", 0, "PSLServer.out")

# PSLConfig(const char *portName, const char *serverPort,

#          int maxBuffers, size_t maxMemory,

#          int priority, int stackSize)

PSLConfig("PSL", "PSLServer", 0, 0)

#asynSetTraceIOMask("$(PORT)",0,2)

#asynSetTraceMask("$(PORT)",0,9)

dbLoadRecords("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore/db/ADBase.template","P=XRFDS:,R=cam1:,PORT=PSL,ADDR=0,TIMEOUT=1")

dbLoadRecords("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore/db/NDFile.template","P=XRFDS:,R=cam1:,PORT=PSL,ADDR=0,TIMEOUT=1")

dbLoadRecords("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADPSL/db/PSL.template",   "P=XRFDS:,R=cam1:,PORT=PSL,ADDR=0,TIMEOUT=1")

# Create a standard arrays plugin

NDStdArraysConfigure("Image1", 5, 0, "PSL", 0, 0)

dbLoadRecords("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore/db/NDPluginBase.template","P=XRFDS:,R=image1:,PORT=Image1,ADDR=0,TIMEOUT=1,NDARRAY_PORT=PSL,NDARRAY_ADDR=0")

# Make NELEMENTS in the following be a little bigger than 2744*2208

dbLoadRecords("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore/db/NDStdArrays.template", "P=XRFDS:,R=image1:,PORT=Image1,ADDR=0,TIMEOUT=1,NDARRAY_PORT=PSL,TYPE=Int16,FTVL=SHORT,NELEMENTS=6100000")

# Create a TIFF file saving plugin

NDFileTIFFConfigure("FileTIFF1", 20, 0, "PSL", 0)

dbLoadRecords("NDFileTIFF.template",  "P=XRFDS:,R=TIFF1:,PORT=FileTIFF1,ADDR=0,TIMEOUT=1,NDARRAY_PORT=PSL")

# Create 1 statistics plugins

NDStatsConfigure("STATS1", 20, 0, "PSL", 0, 0, 0, 0, 0, 5)

dbLoadRecords("NDStats.template",     "P=XRFDS:,R=Stats1:,  PORT=STATS1,ADDR=0,TIMEOUT=1,HIST_SIZE=256,XSIZE=2744,YSIZE=2208,NCHANS=2048,NDARRAY_PORT=PSL")

NDTimeSeriesConfigure("STATS1_TS", 20, 0, "STATS1", 1, 23)

dbLoadRecords("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore/db/NDTimeSeries.template",  "P=XRFDS:,R=Stats1:TS:, PORT=STATS1_TS,ADDR=0,TIMEOUT=1,NDARRAY_PORT=STATS1,NDARRAY_ADDR=1,NCHANS=2048,ENABLED=1")

# Load all other plugins using commonPlugins.cmd

#< $(ADCORE)/iocBoot/commonPlugins.cmd

set_savefile_path("/soft/epics/IOC/PSLioc/iocBoot/PSLioc/autosave")

set_requestfile_path("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADPSL/pslApp/Db")

set_requestfile_path("/soft/epics/IOC/PSLioc/iocBoot/PSLioc")

set_requestfile_path("/soft/epics/inst-3.15.7/areaDetector-R3-11/ADCore/ADApp/Db")

set_requestfile_path("/soft/epics/inst-3.15.7/calc/3-7-4/calcApp/Db")

set_pass1_restoreFile("auto_settings.sav")

iocInit()

Starting iocInit

############################################################################

## EPICS R3.15.7

## EPICS Base built Dec 20 2019

############################################################################

reboot_restore: entry for file 'auto_settings.sav'

reboot_restore: Found filename 'auto_settings.sav' in restoreFileList.

*** restoring from '/soft/epics/IOC/PSLioc/iocBoot/PSLioc/autosave/auto_settings.sav' at initHookState 7 (after record/device init) ***

reboot_restore: done with file 'auto_settings.sav'

 

iocRun: All initialization complete

# save things every thirty seconds

create_monitor_set("auto_settings.req", 30,"P=XRFDS:,D=cam1:")

epics> auto_settings.sav: 352 of 352 PV's connected

2023/03/02 16:48:49.460 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117502, maxRead=2, nRead=1377

 

epics>

epics> 2023/03/02 16:51:32.720 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117503, maxRead=1, nRead=1185

2023/03/02 16:51:43.266 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117503, maxRead=1, nRead=1453

2023/03/02 16:51:48.603 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117503, maxRead=1, nRead=1959

2023/03/02 16:51:55.546 PSL:writeReadServer, status=1, sent

Stop

2023/03/02 16:51:55.552 PSL:getImage: error reading image, status=1, dataLen=12117504, nCopied=8333289, maxRead=2048, nRead=0

2023/03/02 16:51:55.581 PSL:writeInt32: error, status=1 function=8, value=0

2023/03/02 16:51:55.581 XRFDS:cam1:Acquire devAsynInt32::processCallbackOutput process write error

2023/03/02 16:52:05.499 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117502, maxRead=2, nRead=1603

2023/03/02 16:52:10.847 PSL:getImage: error reading image, status=4, dataLen=12117504, nCopied=12117502, maxRead=2, nRead=51

 

Best Regards

Michael