1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 2022 <2023> 2024 | Index | 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 2022 <2023> 2024 |
<== Date ==> | <== Thread ==> |
---|
Subject: | RE: pasynOctetSyncIO error reading image status=4 |
From: | Mark Rivers via Tech-talk <tech-talk at aps.anl.gov> |
To: | "Sintschuk, Michael" <michael.sintschuk at bam.de>, tech-talk <tech-talk at aps.anl.gov> |
Date: | Fri, 3 Mar 2023 18:39:47 +0000 |
You could also try increasing the timeout on the read operations, but I sort of doubt if that is the problem. Mark From: Sintschuk, Michael <michael.sintschuk at bam.de> 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>
Hi Michael, The message is printed here: The status is the return from pasynOctetSyncIO->read in this line: pasynOctetSyncIO->read is here, and it just returns the status from pasynOctet->read(). The asynStatus enums are defined here: 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 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 |