Subject: Re: [doravetz@apo.nmsu.edu: [sdss3-25mlog 1068] 2.5m obslog 20130214 (MJD 56338)] From: "John K. Parejko" Date: Fri, 15 Feb 2013 16:37:29 -0500 It looks like this is the same "netburner problem" as happened in spring = of 2010, 2011 and 2012. See logs for MJDs e.g., 55244, 55264, 56007, and = probably the closed tickets #475 and #895. On 15Feb 2013, at 12:28, Constance Rockosi wrote: > John or someone else who can, >=20 > If you'd pull the comm logs, I can help parse through what happened > with the sp1 communications. Ok, I think I've found what you would be looking for. The log chunk is = from /data/logs/actors/boss/2013-02-14T07:12:28.log Does this help? John First error (~05:57:45): 2013-02-15 05:57:44.540Z root 20 CamProtocol.py:29 sp1cam ok' 2013-02-15 05:57:44.541Z cmds 20 CommandLink.py:117 > 2 5107 = d text=3D"Completed message from sp1cam" 2013-02-15 05:57:44.541Z cmds 10 CommandLink.py:106 flushing = queue to all outputs... 2013-02-15 05:57:44.542Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5107 d text=3D"Completed message from sp1cam" 2013-02-15 05:57:44.542Z root 20 BaseProtocol.py:117 sp1cam = > 'FREAD' 2013-02-15 05:57:44.543Z cmds 20 CommandLink.py:117 > 2 5107 = d text=3D"Sending FREAD to sp1cam" 2013-02-15 05:57:44.544Z cmds 10 CommandLink.py:106 flushing = queue to all outputs... 2013-02-15 05:57:44.544Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5107 d text=3D"Sending FREAD to sp1cam" 2013-02-15 05:57:44.636Z root 20 DAQInterface.py:863 sp1daq: = Last Response: LINE=3D0:PIXEL=3D0:PIXCNT=3D2176 2013-02-15 05:57:44.658Z root 20 DAQInterface.py:980 sp1daq: = Pixel 0 for amp0: 2204 (89c) 2013-02-15 05:57:44.658Z root 20 DAQInterface.py:981 sp1daq: = Pixel 0 for amp1: 2328 (918) 2013-02-15 05:57:44.659Z root 20 DAQInterface.py:982 sp1daq: = Pixel 0 for amp2: 2190 (88e) 2013-02-15 05:57:44.659Z root 20 DAQInterface.py:983 sp1daq: = Pixel 0 for amp3: 2245 (8c5) 2013-02-15 05:57:44.659Z root 20 DAQInterface.py:984 sp1daq: = Pixel 0 for amp4: 2295 (8f7) 2013-02-15 05:57:44.660Z root 20 DAQInterface.py:985 sp1daq: = Pixel 0 for amp5: 2462 (99e) 2013-02-15 05:57:44.660Z root 20 DAQInterface.py:986 sp1daq: = Pixel 0 for amp6: 2487 (9b7) 2013-02-15 05:57:44.660Z root 20 DAQInterface.py:987 sp1daq: = Pixel 0 for amp7: 2673 (a71) 2013-02-15 05:57:44.864Z root 20 CamProtocol.py:29 sp1cam ok' 2013-02-15 05:57:44.866Z cmds 20 CommandLink.py:117 > 2 5107 = d text=3D"Completed message from sp1cam" 2013-02-15 05:57:44.867Z cmds 10 CommandLink.py:106 flushing = queue to all outputs... 2013-02-15 05:57:44.867Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5107 d text=3D"Completed message from sp1cam" 2013-02-15 05:57:57.350Z root 20 DAQInterface.py:863 sp2daq: = Last Response: LINE=3D500:PIXEL=3D0:PIXCNT=3D2176 2013-02-15 05:57:57.843Z root 20 DAQInterface.py:863 sp1daq: = Last Response: LINE=3D500:PIXEL=3D0:PIXCNT=3D2176 2013-02-15 05:58:09.584Z root 40 DAQInterface.py:893 sp1daq: = recv returns zero length string in receiveImage. 2013-02-15 05:58:09.584Z root 40 DAQInterface.py:903 Cannot = obtain pixel data wc data (Line 946, Pixel 182) Invalid response from = Netburner. 2013-02-15 05:58:09.585Z root 40 DAQInterface.py:665 sp1daq: = Exception in receiveImage. Transfer aborted. Message: Invalid response = from Netburner. 2013-02-15 05:58:09.599Z cmds 20 CommandLink.py:117 > 2 5107 = w text=3D"sp1daq readout failed: Invalid response from Netburner. = (>)." 2013-02-15 05:58:09.599Z cmds 10 CommandLink.py:106 flushing = queue to all outputs... 2013-02-15 05:58:09.600Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5107 w text=3D"sp1daq readout failed: Invalid response = from Netburner. (>)." =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D Second error (~06:22:30): 2013-02-15 06:22:29.588Z root 20 MechProtocol.py:51 = 'sp1mech': 'TempBlueCamBot 0.3 (0x)' 2013-02-15 06:22:29.588Z root 20 MechProtocol.py:51 = 'sp1mech': 'TempBlueCamTop 0.4 (0x)' 2013-02-15 06:22:29.588Z root 20 MechProtocol.py:51 = 'sp1mech': 'AD 1670 1294' 2013-02-15 06:22:29.589Z root 20 MechProtocol.py:51 = 'sp1mech': 'OK' 2013-02-15 06:22:29.589Z cmds 20 CommandLink.py:117 > 2 5110 = d text=3D"Completed message from sp1mech" 2013-02-15 06:22:29.590Z cmds 10 CommandLink.py:106 flushing = queue to all outputs... 2013-02-15 06:22:29.590Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 d text=3D"Completed message from sp1mech" 2013-02-15 06:22:29.591Z cmds 20 CommandLink.py:117 > 2 5110 = i text=3D"Response parsed." 2013-02-15 06:22:29.592Z cmds 10 CommandLink.py:106 flushing = queue to all outputs... 2013-02-15 06:22:29.592Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i text=3D"Response parsed." 2013-02-15 06:22:29.593Z cmds 20 CommandLink.py:117 > 2 5110 = d text=3D"Noting the status from sp1mech." 2013-02-15 06:22:29.593Z cmds 20 CommandLink.py:117 > 2 5110 = i sp1LastShutterTime=3D0.720,0.550 2013-02-15 06:22:29.594Z cmds 20 CommandLink.py:117 > 2 5110 = i sp1Humidity=3D22.1,28.1 2013-02-15 06:22:29.594Z cmds 20 CommandLink.py:117 > 2 5110 = i sp1Temp=3D0.3,0.2,0.8,0.4,0.0,0.3 2013-02-15 06:22:29.595Z cmds 20 CommandLink.py:117 > 2 5110 = i sp2LastShutterTime=3D0.690,0.610 2013-02-15 06:22:29.595Z cmds 20 CommandLink.py:117 > 2 5110 = i sp2Humidity=3D26.7,26.4 2013-02-15 06:22:29.595Z cmds 20 CommandLink.py:117 > 2 5110 = i sp2Temp=3D-0.1,-0.1,-0.3,0.0,-0.1,-0.7 2013-02-15 06:22:29.596Z cmds 20 CommandLink.py:117 > 2 5110 = i motorStatus=3D0x84,0x84,0x85,0x84,0x84,0x85 2013-02-15 06:22:29.596Z cmds 20 CommandLink.py:117 > 2 5110 = i motorPosition=3D26470,26892,26698,27365,26852,27536 2013-02-15 06:22:29.597Z cmds 20 CommandLink.py:117 > 2 5110 = i shutterStatus=3D0x02,0x02 2013-02-15 06:22:29.597Z cmds 20 CommandLink.py:117 > 2 5110 = i screenStatus=3D0x0a,0x0a 2013-02-15 06:22:29.597Z cmds 20 CommandLink.py:117 > 2 5110 = i slitIDs=3D13,13 2013-02-15 06:22:29.598Z cmds 20 CommandLink.py:117 > 2 5110 = i specMechVersion=3D3.0.1,3.0.1 2013-02-15 06:22:29.598Z cmds 20 CommandLink.py:117 > 2 5110 = i specMechProtocol=3D3,3 2013-02-15 06:22:29.598Z cmds 20 CommandLink.py:117 > 2 5110 = i text=3D"Actual exposure time for sp1 =3D 900.830" 2013-02-15 06:22:29.599Z cmds 20 CommandLink.py:117 > 2 5110 = i text=3D"Actual exposure time for sp2 =3D 900.870" 2013-02-15 06:22:29.599Z root 20 ExposureCmd.py:647 156581 : = Prepping the daq... 2013-02-15 06:22:29.600Z cmds 20 CommandLink.py:117 > 2 5110 = i text=3D"Prepping the daq..." 2013-02-15 06:22:29.600Z cmds 20 CommandLink.py:117 > 2 5110 = d text=3D"initializing daq, just cuz" 2013-02-15 06:22:29.601Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET DEBUG 0 to daq 2013-02-15 06:22:29.601Z root 40 DAQInterface.py:1434 = sp1daq: recv returns zero length string in getResponse. 2013-02-15 06:22:29.602Z root 40 DAQInterface.py:1406 = sp1daq: Cannot get response from command socket. Message: Invalid = response from Netburner. 2013-02-15 06:22:29.602Z root 40 DAQInterface.py:1408 = sp1daq: Resetting Data Sock 2013-02-15 06:22:29.603Z cmds 20 CommandLink.py:117 > 2 5110 = w text=3D'retrying readout prep. after DAQ connection re-established' 2013-02-15 06:22:29.603Z cmds 20 CommandLink.py:117 > 2 5110 = d text=3D"initializing daq, just cuz" 2013-02-15 06:22:29.603Z root 10 DAQInterface.py:223 = Connecting to data link on host 192.168.1.4, port 7889 2013-02-15 06:22:29.604Z root 10 DAQInterface.py:228 sp1daq: = Connected. 2013-02-15 06:22:29.605Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET DEBUG 0 to daq 2013-02-15 06:22:29.606Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:DEBUG=3D0 2013-02-15 06:22:29.606Z root 10 DAQInterface.py:1377 = sp1daq: Sending CLEAR to daq 2013-02-15 06:22:29.608Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DCLEAR:GCR=3D1:DSR=3D144 2013-02-15 06:22:29.608Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET READOUTMODE ON to daq 2013-02-15 06:22:29.610Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:GCR=3D1 2013-02-15 06:22:29.610Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET EXPID 1 to daq 2013-02-15 06:22:29.611Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:EXPID=3D1 2013-02-15 06:22:29.612Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET ROMODE 0 to daq 2013-02-15 06:22:29.613Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:ROMODE=3D0: 2013-02-15 06:22:29.614Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET EXPID 156581 to daq 2013-02-15 06:22:29.615Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:EXPID=3D156581 2013-02-15 06:22:29.615Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET LINES 2112 to daq 2013-02-15 06:22:29.617Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:LINES=3D2112:PIXELS=3D2176 2013-02-15 06:22:29.617Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET PIXELS 2176 to daq 2013-02-15 06:22:29.619Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:LINES=3D2112:PIXELS=3D2176 2013-02-15 06:22:29.619Z root 10 DAQInterface.py:1377 = sp1daq: Sending SET EXPOSURE ON to daq 2013-02-15 06:22:29.621Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DSET:EXPOSURE=3DON:GCR=3D129:DSR=3D128 ... 2013-02-15 06:22:29.643Z root 20 ExposureCmd.py:679 156581 : = Daq ready. 2013-02-15 06:22:29.644Z root 20 ExposureCmd.py:682 156581 : = Clocking the CCDs. 2013-02-15 06:22:29.645Z root 20 Exposure.py:53 = exposureState=3DREADING,69.7,0.0 2013-02-15 06:22:29.646Z cmds 20 CommandLink.py:117 > 2 5110 = i exposureState=3DREADING,69.7,0.0 2013-02-15 06:22:29.646Z cmds 20 CommandLink.py:117 > 2 5110 = i text=3D"Arming the daq..." 2013-02-15 06:22:29.647Z root 20 ExposureCmd.py:695 156581 : = Arming the daq... 2013-02-15 06:22:29.647Z root 20 DAQInterface.py:289 sp1daq: = Starting receiver! 2013-02-15 06:22:29.647Z root 10 DAQInterface.py:223 = Connecting to data link on host 192.168.1.4, port 7890 2013-02-15 06:22:29.648Z root 10 DAQInterface.py:228 sp1daq: = Connected. 2013-02-15 06:22:29.649Z root 20 DAQInterface.py:292 sp1daq: = reconnecting data sock 2013-02-15 06:22:29.650Z root 10 DAQInterface.py:1377 = sp1daq: Sending ARM to daq 2013-02-15 06:22:29.651Z root 20 DAQInterface.py:1450 = sp1daq: Received response: CMD=3DARM:STATUS=3DACCEPTED 2013-02-15 06:22:29.651Z root 40 DAQInterface.py:1434 = sp1daq: recv returns zero length string in getResponse. 2013-02-15 06:22:29.652Z root 20 DAQInterface.py:289 sp2daq: = Starting receiver! 2013-02-15 06:22:29.652Z root 40 DAQInterface.py:699 sp1daq: = Exception in receiveImage. Transfer Aborted. Message: Invalid response = from Netburner. 2013-02-15 06:22:29.653Z root 10 DAQInterface.py:1377 = sp2daq: Sending ARM to daq 2013-02-15 06:22:29.654Z root 40 DAQInterface.py:665 sp1daq: = Exception in receiveImage. Transfer aborted. Message: Invalid response = from Netburner. 2013-02-15 06:22:29.655Z root 20 DAQInterface.py:1450 = sp2daq: Received response: CMD=3DARM:STATUS=3DACCEPTED 2013-02-15 06:22:29.655Z root 20 ExposureCmd.py:711 156581 : = Daq armed. 2013-02-15 06:22:29.655Z cmds 20 CommandLink.py:117 > 2 5110 = i text=3D"Reading out..." 2013-02-15 06:22:29.656Z root 20 ExposureCmd.py:715 156581 : = Waiting for readout to complete. 2013-02-15 06:22:29.658Z cmds 20 CommandLink.py:117 > 2 5110 = w text=3D"sp1daq readout failed: Invalid response from Netburner. = (>)." 2013-02-15 06:22:29.658Z cmds 10 CommandLink.py:106 flushing = queue to all outputs... 2013-02-15 06:22:29.659Z root 20 DAQInterface.py:1450 = sp2daq: Received response: = EXPOSURE=3D156582:PIXCOUNT=3D36765696:LINES=3D2112:PIXPERLINE=3D2176 2013-02-15 06:22:29.660Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 d text=3D"Noting the status from sp1mech." 2013-02-15 06:22:29.661Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i sp1LastShutterTime=3D0.720,0.550 2013-02-15 06:22:29.660Z root 20 DAQInterface.py:717 sp2daq: = Exposure ID 156582, total pixel count 36765696, Lines 2112, Pixels per = line 2176 2013-02-15 06:22:29.661Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i sp1Humidity=3D22.1,28.1 2013-02-15 06:22:29.743Z root 10 DAQInterface.py:751 sp2daq: = Waiting for first line of exposure 156582 2013-02-15 06:22:29.744Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i sp1Temp=3D0.3,0.2,0.8,0.4,0.0,0.3 2013-02-15 06:22:29.745Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i sp2LastShutterTime=3D0.690,0.610 2013-02-15 06:22:29.745Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i sp2Humidity=3D26.7,26.4 2013-02-15 06:22:29.745Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i sp2Temp=3D-0.1,-0.1,-0.3,0.0,-0.1,-0.7 2013-02-15 06:22:29.746Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i motorStatus=3D0x84,0x84,0x85,0x84,0x84,0x85 2013-02-15 06:22:29.746Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i motorPosition=3D26470,26892,26698,27365,26852,27536 2013-02-15 06:22:29.746Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i shutterStatus=3D0x02,0x02 2013-02-15 06:22:29.747Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i screenStatus=3D0x0a,0x0a 2013-02-15 06:22:29.747Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i slitIDs=3D13,13 2013-02-15 06:22:29.747Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i specMechVersion=3D3.0.1,3.0.1 2013-02-15 06:22:29.748Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i specMechProtocol=3D3,3 2013-02-15 06:22:29.748Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i text=3D"Actual exposure time for sp1 =3D 900.830" 2013-02-15 06:22:29.748Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i text=3D"Actual exposure time for sp2 =3D 900.870" 2013-02-15 06:22:29.749Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i text=3D"Prepping the daq..." 2013-02-15 06:22:29.749Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 d text=3D"initializing daq, just cuz" 2013-02-15 06:22:29.749Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 w text=3D'retrying readout prep. after DAQ connection = re-established' 2013-02-15 06:22:29.750Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 d text=3D"initializing daq, just cuz" 2013-02-15 06:22:29.750Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 d text=3D"initializing daq, just cuz" 2013-02-15 06:22:29.750Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i exposureState=3DREADING,69.7,0.0 2013-02-15 06:22:29.751Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i text=3D"Arming the daq..." 2013-02-15 06:22:29.751Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 i text=3D"Reading out..." 2013-02-15 06:22:29.751Z cmds 10 CommandLink.py:110 flushing = queue line: 2 5110 w text=3D"sp1daq readout failed: Invalid response = from Netburner. (>)."=