APACHE POINT OBSERVATORY SDSS 2.5M OBSERVING LOG Thursday January 17, 2002 (MJD 52292) ---=== OBSERVING TEAM ===--- SWING: Pete Newman NIGHT: Atsuko Nitta Kleinman Jurek Krzesinski ---=== OBSERVING PLAN ===--- Spectroscopy. ---=== OBSERVING SUMMARY ===--- We opened, but got no science data due to the software problems and clouds. We could have finished one plate, but got ptvme errors in the middle of exposures, so two exposures were lost due to that reason. We also had gcam problems on twilight, but Criag solved it before the end of twilight, so there was no science time lose. Then clouds covered the sky and we were waiting for some clear sky to the end of the night. Cloud camera window needed to be defrosted a few time tonight. ---=== OBSERVING LOG ===--- Afternoon checkout ok. 00:20 telescope open, cart 1 plt 802 mounted. gotoField - stars found with no problem. 01:15 We've got a problem with the focus loop. First loop passed with no problems, then we changed integration times and got flat fwhm vs. focus plot. It appeared, that there were no new gcma images created and all fwhm analysis was done on the lat gcam image. To get rid off that problem we closed the sop window causing the problem and opened another sop window. Tried gcam, but the problem remained See the problem section. Meanwhile we found out that the plate 802 can be declared as done, but the message about it was sent only to those observers who asked to verify "if the plate can be declared done" - so please, do send such messages to all observers if possible, next time. Another problem with landru - It happened after all above, that all windows on landru were frozen. We had to reset the xwindow. And reopen everything since the beginning. 01:05 Landru problem resolved -all necessary windows opened and active. Criag was asked for help with the gcam ... He find out, the mac's nfs client has lost connection with the host. So we rebooted the mac and started gcam software again, then everything was fine. 02:20 We are back in business, but waitng for clouds to disapear. 04:45 We mounted cart 7 plt 830 on the telescope, clouds ar3e not very thick, so maybe we can do some sciene? Stars found via fk5. 05:35 After 20 minutes of exposure we lost the relay server. Sop window together with startupGui, saoDisplay, and pgplot windows were lost too. This is a ptvme error - see ptvme error problem section. We had to restart servers, then reset ptvme: ptvmeMode -R Waited about 10 minutes, opened the sop window, tried goStare -bias and was able to read out the bias. 06:12 Then we started another 30 minutes science exposure. It went ok. up to the reading out moment, when it failed to read the frame (at about 06:42). We recovered again by: 1. closing sop window, 2. restarting ptvme from host: (ptvmeMode -R), 3. waiting 8-10 minutes 4. opening sop window and checking sanity of the system by taking bias: goStare -bias. It looks like it is important to wait more than 5 minutes after reseting ptvme, to get rid off the problem. See endStare error in the problem section. Unfortunately this time because of clouds, we couldn't find any stars. 08:43 We started 5 minutes science exposure on clouds, to see if we really recovered from the ptvme problem. It went ok. including reading out. ... Again we are waiting for clouds to disapear. ============================================================================= Cloud camera ------------ It's a real problem now, since we have to fill it up more often than before and in addition to that, we have to use a heat gun time to time to defrost the camera window. ============================================================================= 11:00 We closed the telescope (dew point difference was too low). endNight finished without problems. ---=== IMAGING RUN SUMMARY ===--- ---=== IMAGING RUN DETAILS ===--- ---=== SKIPPY RESULTS ===--- ---=== LTMATCH RESULTS ===--- ---=== SPECTROSCOPY DATA SUMMARY ===--- ----- sequence 12698, plate -9999 ------- 01:25 12698 0.0 bias ----- sequence 12699, plate 802 ------- 01:57 12699 0.0 bias ----- sequence 12700, plate 830 ------- 05:08 12700 10.0 flat 05:10 12701 2.0 arc ----- sequence 12702, plate -9999 ------- 05:57 12702 0.0 bias ----- sequence 12703, plate -9999 ------- 06:03 12703 0.0 bias ----- sequence 12704, plate -9999 ------- 07:14 12704 0.0 bias ----- sequence 12705, plate 830 ------- 07:49 12705 301.0 target - this was a test exposure. ---=== TELESCOPE OFFSETS AND SCALE I ===--- 22:25 7 0 1011331536 0.002230 0.000507 -0.026868 1.000220 ---=== TELESCOPE OFFSETS AND SCALE II ===--- ---=== DATA TAPE SUMMARY ===--- Goes: none Stays: none ---=== FOCUS LOG ===--- setmir piston Temp Wind Time Inst scale M1 M2 Foc Az Alt (C) MPH Dir filt fwhm 22:24 7 830 1.00022 -2171 -686 -50 117 56.5 1.4 15 239 gdr 1.5 ---=== WEATHER LOG ===--- 17:18 33 22 18 223 (SW) 373 - 17:50 32 24 22 217 (SW) 371 - 18:23 33 24 15 261 (W) 397 - 18:54 33 24 14 259 (W) 393 - 19:27 33 23 9 259 (W) 329 - 20:01 34 24 13 238 (WSW) 302 - 20:32 33 25 13 241 (WSW) 388 - 21:02 34 25 19 257 (WSW) 290 - 21:32 34 25 16 254 (WSW) 317 - 22:03 34 26 13 247 (WSW) 360 - 22:38 34 26 12 231 (SW) 397 - 23:11 34 25 20 231 (SW) 288 - 23:41 34 25 12 237 (WSW) 283 - 00:16 34 25 13 218 (SW) 271 - 00:47 34 26 12 254 (WSW) 292 - 01:20 34 26 20 218 (SW) 293 - 01:52 34 26 15 226 (SW) 290 - 02:24 33 26 18 221 (SW) 328 - 02:56 32 26 17 252 (WSW) 322 - 03:29 33 27 19 247 (WSW) 181 - 03:59 32 27 21 244 (WSW) 219 - 04:33 32 26 20 256 (WSW) 192 - ---=== TELESCOPE STATUS ===--- 00:20 telescope opened (fans were on for 1/2 hour already). 11:00 telescope closed, fans off, hoses hooked up. ---=== SOFTWARE USED ===--- IOP/SOP: v3_64_3c Watcher: v2_13_2a MCP: v5_8_7 TPM: v2_4_5 AstroDa: v14_40 TCC: 2.5.5 sdssProcedures: v1_37 ---=== MIRROR NUMBERS ===--- PRIMARY: -------- Scale: 1.000000 MIGS TONIGHT NOMINAL Axial A 0.0750 0.0750 Axial B 0.8040 0.8020 Axial C 0.0740 0.0710 Trans D -1.4990 -1.4860 Lateral E 1.8280 1.8540 Lateral F 1.4120 1.4240 GALILS Commanded: 5400. -3700. 900. -200. 31550. 30650. Actual: 5400. -3700. 900. -200. 31550. 30650. SETMIR VALUES PriDesOrient: 0.00 -11.80 23.00 1256.90 642.10 PriOrient: 0.00 -12.16 22.81 1257.41 642.19 SECONDARY: ---------- Focus: 0.00 Air Temp.: 0.3 Alt.: 29.980633 MIGS TONIGHT NOMINAL Axial A 1.5430 1.5500 Axial B 1.2200 1.2260 Axial C 1.2440 1.2480 Trans D 0.2080 0.2320 GALILS Commanded: 1599649. 1565186. 1586603. -10395. -9766. Actual: 1599620. 1565254. 1586350. -10395. -9766. SETMIR VALUES SecDesOrient: 1257.00 -3.40 -10.00 0.00 133.82 SecOrient: 1257.06 -3.50 -10.01 0.00 133.89 ---=== PROBLEMS IN DETAIL ===--- SOP guider: ----------------- Problems with a focus loop. After first loop, which runned properly, we tried another one with a longer integration time and we got a problem. There was no new gcam image created and all analysis went on the same frame. We started another focus loop to repeat the problem and below there is cut and paste message from tcc: 01:14:36 guiderFocus 175 7 50 20 2 0 0 I GCamReply='could not open file: guider images:gimg0400.fits; error: No Error' WHAT is that strange message error: No Error? We were suppose to get gimg0400.fit in that focus loop, but we never saw image gimg0400.fit We closed the sop window causing the problem and opened a new one, than tried gcam... and had simila/the same problem (cut and paste from tcc): 0 15 > Started; Text="command queued"; Cmd='gcam doread 15' 0 15 I Text="command executing" 0 0 I GCamCmd="doread 15.00 2 2 192.0 128.0 0.0 0.0" 0 0 I TCCStatus="TTT","NNN"; TCCPos=21.10,55.33,197.62; AxePos=21.10,55.33,197.61 0 0 I SpiderInstAng = 17.697253, -0.005763, 4518034235.03241 0 0 I TCCStatus="TTT","NNN"; TCCPos=21.03,55.34,197.56; AxePos=21.03,55.34,197.56 0 0 I SpiderInstAng = 17.639605, -0.005767, 4518034245.03241 0 0 I GCamReply='could not open file: guider images:gimg0400.fits; error: No Error' 0 15 : PTVME error ------------ After 20 min exposure we lost Relay Serves and got ptvme error:************************************************** ====>>>>>>RELAY SERVER FAILED TO START!!!!<<<===== ************************************************** requestListen spectro: Neither 30310 nor 30307 appears to exist ************************************************** Dropping at exit Access to shared data area at 0x18000000 lost (errno=0x10 Resource busy) Read failed from PT icc40 CSB=0x00000000 rmt=0x18000000 cnt=0x0009ABE8 ******************************************************************************** * * * Backplane communications between the ICC/OAC are no longer possible. * * * * Perform the following steps until operations are possible. * * * * 1. Check connections between the machines. * * 2. Reboot (reset) the ICC. * * 3. Restart this (OAC) program. * * 4. Reset the local PT-VME940 (ptvmeMode -R). * * 5. Power-cycle the VMEbus crates. * * 6. Reboot the local machine (host). * * ******************************************************************************* Before resetting ptvme, we checked what is going on: A:Host>ptvmeTest -n 1 -a 0x18000000 PID: 29651827 IOPB size: 64 bytes ping: no operation: read loopCnt: 1 (defaulted) 100 loops per dot LWordCnt: 0x00000001 (defaulted) controller: 0 (defaulted) remNode: 1 --> /dev/ptvme0n1 remAddr: 0x18000000 (defaulted) IxferMode: 0x00 (defaulted) TxferMode: 0x00 (defaulted) errno = 0: open ("/dev/ptvme0n1", O_RDWR) = 3 errno = 0: ioctl (fd=3, PT_IOCTL_GET_PRIORITY, &ptPriority) = 0 ptPriority = 0x03 errno = 0: ioctl (fd=3, PT_IOCTL_GET_VECTOR, &ptVector) = 0 ptVector = 0x01 errno = 0: ioctl (fd=3, PT_IOCTL_GET_TIMEOUT, &ptTimeoutSave) = 0 ptTimeout = 900 ticks errno = 0: ioctl (fd=3, PT_IOCTL_GET_OP_MODE, &ptOpMode) = 0 ptOpMode = 1 SINGLE_IO errno = 0: ioctl (fd=3, PT_IOCTL_GET_DEBUG_MODE, &ptDebugMode) = 0 ptDebugMode = 0 NORMAL errno = 0: ioctl (fd=3, PT_IOCTL_GET_DEBUG, &ptDebugSave) = 0 ptDebug = 0x00000000 errno = 5: ioctl (fd=3, PT_IOCTL_GET_NODE_ID, 0) = 0xFFFFFFFF (I/O error) . 0 2 ms 22:36 errno = 16: read (fd=3, 0x7F7F2B10, 0x00000004) = -1 (Resource busy) CSB status: 0x00000000 AUX = (unknown) CMP = (Never Used) INNA = 0 errno = 0: lseek (fd=3, 0x00000000, SEEK_CUR) = 0x00000000 00000000: 00 01 02 03 04 05 06 07 08 09 0A 0B 0C 0D 0E 0F <................> 00000010: 10 11 12 13 14 15 16 17 18 19 1A 1B 1C 1D 1E 1F <................> 00000020: 20 21 22 23 24 25 26 27 28 29 2A 2B 2C 2D 2E 2F < !"#$%&'()*+,-./> 00000030: 30 31 32 33 34 35 36 37 38 39 3A 3B 3C 3D 3E 3F <0123456789:;<=>?> This wasn't very informative for us, but for others it might be ;) So, we reset ptvme: ~ A:Host>ptvmeReset ptvmeMode: INFO: controller 0 reset (/dev/ptvme0n0) ptvmeMode: INFO: cur debug mode: 0 NORMAL ptvmeMode: INFO: cur debug: 0x00000000 ptvmeMode: INFO: cur timeout: 900 ticks ptvmeMode: INFO: def T/I xfer mode: 0x22 A32:D32 Program, Non-Privileged / A32:D32 Program, Non-Privileged ptvmeMode: INFO: op mode: 1 SINGLE_IO ptvmeMode: INFO: VMEbus priority: 0x03 ptvmeMode: INFO: VMEbus vector: 0x01 ptvmeMode: INFO: intern sem val: 1 ptvmeMode: INFO: user sem val: 1 ptvmeMode: INFO: PT-VME940 node: 0 then restarted servers, which has gone meanwhile, closed sop and opened it again, but we still couldn't resume hunged exposure (mechSend showed that shutters are opened). And we were confused by differend command giving a different status of the exposure: endStare gaved: Error: No Exposure is in progress goStare 0 -bias -init -plateId -9999 gaved: Error: There is an ongoing exposure on sp1 But see for yourself the whole error informations: resume gives: ------------- "Error: can't read "schedled (wait_for_endStare)":no such element in array can't read "scheduled(wait_for_endStare)": no such element in array while executing "proc_atexit schedule wait_for_endStare $scheduled(wait_for_endStare)..." (procedure "resumeStare" line 29) invoked from within "resumeStare $opt" (procedure "GUIresumeStare" line 16) invoked from within "GUIresumeStare $GUIresumeOpt" invoked from within ".expgui.resumestare.button invoke" ("uplevel" body line 1) invoked from within "uplevel #0 [list $w invoke]" invoked from within "if {($w == $tkPriv(window)) && ([$w cget -state] != "disabled")} { uplevel #0 [list $w invoke] }" invoked from within "if {$w == $tkPriv(buttonWindow)} { set tkPriv(buttonWindow) "" $w config -relief $tkPriv(relief) if {($w == $tkPriv(window)) && ([$w cget -state] ..." (procedure "tkButtonUp" line 3) invoked from within "tkButtonUp .expgui.resumestare.button" (command bound to event) endStare gives: --------------- Error: No Exposure is in progress No exposure is in progress while executing "error "No exposure is in progress"" invoked from within "if !$force { error "No exposure is in progress" } " invoked from within "if ![info exists exposureDuration] { if !$force { error "No exposure is in progress" } }" (procedure "endStare" line 20) invoked from within "endStare -abort" ("eval" body line 1) invoked from within "eval "endStare $opt"" (procedure "GUIendStare" line 18) invoked from within "GUIendStare -abort" ("eval" body line 1) invoked from within "eval "GUIendStare $GUIendOpt"" invoked from within ".expgui.endstare.button invoke" ("uplevel" body line 1) invoked from within "uplevel #0 [list $w invoke]" invoked from within "if {($w == $tkPriv(window)) && ([$w cget -state] != "disabled")} { uplevel #0 [list $w invoke] }" invoked from within "if {$w == $tkPriv(buttonWindow)} { set tkPriv(buttonWindow) "" $w config -relief $tkPriv(relief) if {($w == $tkPriv(window)) && ([$w cget -state] ..." (procedure "tkButtonUp" line 3) invoked from within "tkButtonUp .expgui.endstare.button" (command bound to event) goStare 0 -bias -init -plateId -9999 ----------------------------------------- gives: Error: There is an ongoing exposure on sp1 There is an ongoing exposure on sp1 while executing "error $msg" invoked from within "if $force { echo $msg } else { error $msg }" ("1" arm line 3) invoked from within "switch -- [mechExposing $cam] { -1 { error "Cannot attach to $cam mechanicals to verify state" } 0 { ; # OK ..." ("foreach" body line 2) invoked from within "foreach cam [activeInstruments] { switch -- [mechExposing $cam] { -1 { error "Cannot attach to $cam mechanicals to verify state" ..." invoked from within "if {[cameraType] == "spectro"} { foreach cam [activeInstruments] { switch -- [mechExposing $cam] { -1 { error "Cannot attach to $ca ..." invoked from within "if $resume { set expTime [expr $expTime - $exposureDuration] } else { # # if spectro, check whether there is an exposure ongoing ..." (procedure "goStare" line 199) invoked from within "goStare 0 -bias -init -plateId -9999" ("eval" body line 1) invoked from within "eval "goStare $exposure $biasflag $initflag -plateId $plate"" (procedure "GUIgoStare" line 23) invoked from within "GUIgoStare -bias -init" ("eval" body line 1) invoked from within "eval GUIgoStare $GUIgoStareType $GUIgoStareInit" invoked from within ".setupgui.gostare.button invoke" ("uplevel" body line 1) invoked from within "uplevel #0 [list $w invoke]" invoked from within "if {($w == $tkPriv(window)) && ([$w cget -state] != "disabled")} { uplevel #0 [list $w invoke] }" invoked from within "if {$w == $tkPriv(buttonWindow)} { set tkPriv(buttonWindow) "" $w config -relief $tkPriv(relief) if {($w == $tkPriv(window)) && ([$w cget -state] ..." (procedure "tkButtonUp" line 3) invoked from within "tkButtonUp .setupgui.gostare.button" (command bound to event) After doing "ptvmeMode -R" couple times, then we finally were able to take exposure again: sp1> SOPGUI: eval goStare 0 -bias -init -plateId -9999 Thu Jan 17 22:56:17 MST 2002: Choosing staring readout mode Thu Jan 17 22:56:17 MST 2002: Set frames to Rows=(2048+21) and Cols/2=(20+1024+20) Binning=(1,1) sp1 camstat {} t-g-sdss-2.apo.nmsu.edu 2100 sp2 camstat {} t-g-sdss-2.apo.nmsu.edu 2200 setupCamera {SPEC1 27FEB01 $Name: v4_7 $ } t-g-sdss-2.apo.nmsu.edu 2100 sp1 setupCamera {} t-g-sdss-2.apo.nmsu.edu 2100 setupCamera {SPEC2 27FEB01 $Name: v4_7 $ } t-g-sdss-2.apo.nmsu.edu 2200 sp2 setupCamera {} t-g-sdss-2.apo.nmsu.edu 2200 Thu Jan 17 22:56:33 MST 2002: Setting sp1 up for data taking Thu Jan 17 22:56:33 MST 2002: Setting sp2 up for data taking Thu Jan 17 22:56:34 MST 2002: Setting group(=run) to 52292 and frame to 12701 sp1 cameraNag {} t-g-sdss-2.apo.nmsu.edu 2100 sp2 cameraNag {} t-g-sdss-2.apo.nmsu.edu 2200 Flushing charge for 15 sec mcpPut: SYSTEM.STATUS mcpPut: version mcpPut: SYSTEM.STATUS mcpPut: USER.ID ank@sdsshost 27575391 appending BEGIN appending END EXPOSURE TIME is: 0 sp1 cameraNag {} t-g-sdss-2.apo.nmsu.edu 2200 sp2 cameraNag {} t-g-sdss-2.apo.nmsu.edu 2200 sp1 camstat {} t-g-sdss-2.apo.nmsu.edu 2100 sp2 camstat {} t-g-sdss-2.apo.nmsu.edu 2200 1011333428 1011333428 Thu Jan 17 22:57:24 MST 2002: scheduling gangs2Unix transfers The old teamster, PID 29699836, appears to have died; restarting Thu Jan 17 22:57:24 MST 2002: finished with iccExec -riskyOn data -async sd1 readoutBegin sp1 cameraStart {} t-g-sdss-2.apo.nmsu.edu 2100 sp2 cameraStart {} t-g-sdss-2.apo.nmsu.edu 2200 Waiting for read to finish Seq 12702 Exp 12702 Frame 12702 Do not schedule startFlushCharge sp1 200 Do not schedule startFlushCharge sp2 200 endStare error: ---------------- After all above problems with ptvme, when goStare -bias went succesfuly, we started a new science exposure, but it failed on endStare: =====endStare: beginning read out ============================= appending END EXPOSURE TIME is: 1800 sp1 cameraNag {} t-g-sdss-2.apo.nmsu.edu 2100 sp2 cameraNag {} t-g-sdss-2.apo.nmsu.edu 2200 Thu Jan 17 23:43:15 MST 2002: sp1 is not idle...aborting beginData has failed: sp1 is not idle...aborting /data/spectro/guider/gimg0127.fits I cannot find the sky from the fibres you suggested Sky values: 68 68 OP running as Backup Relay Server requestListen: listening Exposure is Paused, this is camHandler running Thu Jan 17 23:46:59 MST 2002 9 sp1 camcheck Thu Jan 17 23:46:59 MST 2002 9 sp1 SHOWREADVOLTS sp1: list element in quotes followed by ":" instead of space invoked from within "camHandler" invoked from within "if {[exposureRemaining -quiet] < 0 } { echo "Exposure is Paused, this is camHandler running" camHandler return }" (procedure "camHandler_maybe" line 7) invoked from within "camHandler_maybe 60" ("eval" body line 1) invoked from within "eval $procname $args" camHandler_maybe is scheduled, further errors sent to murmur Exposure is Paused, this is daHandler running When we tried to do a bias: SOPGUI: eval goStare 0 -bias -init -plateId 830 Thu Jan 17 23:50:42 MST 2002: Choosing staring readout mode Thu Jan 17 23:50:42 MST 2002: Set frames to Rows=(2048+21) and Cols/2=(20+1024+20) Binning=(1,1) sp1 camstat {} t-g-sdss-2.apo.nmsu.edu 2100 sp2 camstat {} t-g-sdss-2.apo.nmsu.edu 2200 setupCamera {error writing "file9": Bad file number} t-g-sdss-2.apo.nmsu.edu 2100 sp1 setupCamera {} t-g-sdss-2.apo.nmsu.edu 2100 setupCamera {SPEC2 27FEB01 $Name: v4_7 $ } t-g-sdss-2.apo.nmsu.edu 2200 sp2 setupCamera {} t-g-sdss-2.apo.nmsu.edu 2200 Then few min. later, sp1> Exposure is Paused, this is camHandler running So we did "ptvmeMode -R" again on HOST (with iop setuped) and waited for 5 min. But, ptvmeMode -R does not print any message, so we issued the same command from sp1> and got the following: sp1> ptvmeMode -R Error: Auto execution of Unix commands only supported as interactive commands. Use "exec" to execute "ptvmeMode" sp1> Exposure is Paused, this is camHandler running Thu Jan 17 23:55:03 MST 2002 9 sp1 camcheck Thu Jan 17 23:55:03 MST 2002 9 sp1 SHOWREADVOLTS Thu Jan 17 23:55:03 MST 2002 23 sp2 camcheck Thu Jan 17 23:55:05 MST 2002 23 sp2 mechstat Exposure is Paused, this is daHandler running IOP running as Backup Relay Server requestListen: listening Exposure is Paused, this is camHandler running Thu Jan 17 23:57:08 MST 2002 9 sp1 camcheck Thu Jan 17 23:57:08 MST 2002 9 sp1 SHOWREADVOLTS sp1: list element in quotes followed by ":" instead of space invoked from within "camHandler" invoked from within "if {[exposureRemaining -quiet] < 0 } { echo "Exposure is Paused, this is camHandler running" camHandler return }" (procedure "camHandler_maybe" line 7) invoked from within "camHandler_maybe 60" ("eval" body line 1) invoked from within "eval $procname $args" camHandler_maybe is scheduled, further errors sent to murmur Exposure is Paused, this is daHandler running Thu Jan 17 23:57:15 MST 2002: registered (addr7) listener sdsshost:observer:30795101 and something like this: sp1 cannot stop scanning ( sorry, not exact message) and the stacktrace said: riv(window)) && ([$w cget -state] ..." (procedure "tkButtonUp" line 3) invoked from within "tkButtonUp .setupgui.gostare.button" (command bound to event)