LUCIFER Com 3, Night 2
UT 2009 January 11

Observers: N.Ageorges, W.Seifert, M.Juette, V.Knierem, R.Gredel, D.Thompson (@LBT)
Telescope Operator: A.Ceranski
SW Support: T.Sargent in Tucson until 2:15am

Summary:

  • Rotator repaired, dome open at 21:45. Lost 5:00
  • AGW problem, not able to home motors. Lost another 1:00. See IT#1949
    • We found a work around
    • This is apparently now fixed
  • Panic at 4:39, same reason as last night? FCINs were zero. Recovered easily.
  • Several more SW problems that we let run well past 5 minute timeouts, details below.

Details:

18:00 Work continuing on the rotator. T=-2.7, RH=12.5, Wind ~13m/s average. Photometric.

21:45 Dome open. Polaris monitor shows 4 arcsec FWHM and stable.

22:15 AGW started OK but when we tried to "home -m 20" we got this message:
"Call failed while checking bits on UMAC: RPC: timed out"
A stopAGW or startAGW at this point only returns: "AGW1: General Error"
A reboot of the agw-control computer did not fix the problem. Called Torsten. With his help found that the /etc/init.d/ch4np script was not executable. We changed that (chmod +x ch4np) and rebooted again, same problem. It looks like "check4nports" and "owfs" are not started, but the oacserver is running. Called Norm. We could only find an office number for Thomas Hahn.

22:36 Trying Jesper's cell number. No answer, but he called back in a couple minutes.

23:22 Manually ran /usr/local/bin/check4nport.20080716a and got an OK back. Restarted oacserver and homed motors and it worked! Preset worked. There must be a bug in the current startup script.

Correct pointing and collimation: IE changed from -15.0 to 10. , CA from -5.0 to -24.5. Coma and focus seen on LUCIFER.

Initial preset failed. Star is there, but failed because the seeing is very poor. On to a brighter star and it worked.

LUCIFER is getting only intermittent updates through the IIF. We see the requests coming in every second, but nothing is going out. Top on 102 shows the following:
527 telescop 24 0 815m 557m 3244 S 1.3 55.1 72:43.84 IIF
We think it is a memory leak on IIF, will restart shortly.

We "Stop"ed IIF and got:
Sat Jan 10 23:51:28.866 2009 subsystem shut down
Then we "Kill"ed it and got:
Sat Jan 10 23:51:35.970 2009 IIF wouldn't stop. a "ps -ef" showed an IIF still on 102, so we "kill -9"ed it and then restarted IIF from the TCS GUI. Sat Jan 10 23:54:21.610 2009 Success.

A Preset from LUCIFER after the restart worked: Sat Jan 10 23:56:09.999 2009 Preset command complete for left LUCIFER mode ACTIVE from IIF
but the subsequent stepfocus they sent does not show up in the IIFGUI log panel and the syslog says.
Jan 10 23:56:10 lbtmu102 LBT_IIF: Invalid handle to block: RPCERROR
Jan 10 23:56:10 lbtmu102 LBT_IIF: free unknown handle RPCERROR

A subsequent preset to the same object, with nothing done on the TCS side, worked.

Quiet for a while, then...

01:29:57.864 2009 Stepfocus command started for left LUCIFER
that has not completed for 13 minutes. The GetMultiDDEntry requests continued throughout the hang.

In the IIF syslog entries:
Jan 11 01:29:57 lbtmu102 LBT_IIF: IIF:StepFocus executed
but there are no more IIF entries in the syslog until...
Jan 11 01:48:04 lbtmu102 LBT_IIF: IIF:StepFocus execution time: 1086630 ms at 1231663684492
Jan 11 01:48:11 lbtmu102 LBT_IIF: IIF Thread Stopped
Jan 11 01:48:11 lbtmu102 LBT_IIF: IIF Exiting
Which corresponds to when we stopped IIF.

So, we stopped IIF, then Stopped GCS, then Killed GCS, then had to do a "kill -9" on GCS, then restarted in the opposite direction.
Sun Jan 11 01:48:11.998 2009 IIF stopped.
Sun Jan 11 01:48:30.376 2009 GCSL wouldn't stop.
Sun Jan 11 01:48:44.756 2009 GCSL not running.
Sun Jan 11 01:49:51.155 2009 Success.
Sun Jan 11 01:49:58.009 2009 Success.

The initial preset after this from LUCIFER returned an "invalid buffer error", but we just sent another preset and it completed without complaint.

An offset from LUCIFER is taking a long time to complete...
Sun Jan 11 04:13:15.713 2009 Offset command started for left LUCIFER from IIF

GCS was not logging any activity until we got:
Jan 11 04:17:35 lbtmu107 LBT_left_GCS: WWPA failed, ESO errcode: 0
reporting no guide star found. Nothing obvious in the logs, and to not interrupt what LUCIFER needed to do we used the command line to home the AGW stages and turn off guiding and WFSing on the GCSGUI.

Panic at 4:39, same reason as last night? FCINs are 0 so we should be working in "normal" mode and not bending spherical .
Cleared c00 and raised mirror to recover.

*05:46:52.437 2009 Preset command started for left LUCIFER mode ACTIVE*
It looks like the telescope moved to where it was supposed to go, and GCS got hung up waiting for something back from the AZcam server. The last message in the IIF/PCS log is:
Jan 11 05:46:22 lbtmu102 LBT_PCS: setNewTarget. mcspuFS: LFBG rotIndex: 6
after which the GCS log shows the following:
Jan 11 05:46:22 lbtmu107 LBT_left_GCS: GCSL:stopGuiding executed
Jan 11 05:46:22 lbtmu107 LBT_left_GCS: GCSL:stopGuiding execution time: 15 ms at 1231677982543
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: GCSL:setGuidestarList executed
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: selectAGW(AIP_LUCIFER):
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: didn't create a new instance of AGWUnitAIP as the types are the same
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: selecting AGW unit AIP_LUCIFER and intializing it with /lbt/tcs/current/etc/../etc/GCS//AIP_L.cfg
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: setting GCS server IP for AzCams to 10.144.0.107
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: initalizing AIP AGW unit from pathname '/lbt/tcs/current/etc/../etc/GCS//AIP_L.cfg'
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: readfile: 0
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: reading Configuration for AIP_LUCIFER:L from: /lbt/tcs/current/etc/../etc/GCS//AIP_L.cfg
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: name = AIPAGW3
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: oacontrol_IP = 10.144.0.64
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: focus = 35.350
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: sfpRotation = 179.70
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_1_name = B
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_1_wl = 440
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_2_name = V
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_2_wl = 520
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_3_name = r'
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_3_wl = 630
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_4_name = empty
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_4_wl = 0
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_5_name = empty
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: filter_5_wl = 0
Jan 11 05:46:23 lbtmu107 LBT_left_GCS: AGWUnit configured, calling init() ...
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: init() successful, now initializing cameras
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: checking _azcam member
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: deleting _azcam instance
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ~azcam: stopping IST...
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ImageServerThread ended
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: IST: closing open socket
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: IST: socket closed
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ~azcam: waiting for IST to stop...
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ~azcam: sending 'closeConnection'
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ~azcam: done.
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: creating _azcam instance
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ImageServerThread created. instance = 2
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: setting up imageserver IP
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: init and connect ...
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: IST: connect accepted!
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: checking _azcam member
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: deleting _azcam instance
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ~azcam: stopping IST...
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: ImageServerThread ended
Jan 11 05:46:27 lbtmu107 LBT_left_GCS: IST: closing open socket
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: IST: socket closed
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: ~azcam: waiting for IST to stop...
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: ~azcam: sending 'closeConnection'
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: ~azcam: done.
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: creating _azcam instance
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: ImageServerThread created. instance = 3
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: setting up imageserver IP
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: init and connect ...
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: IST: connect accepted!
Jan 11 05:46:28 lbtmu107 LBT_left_GCS: reading GuidingThread configuration from '/lbt/tcs/current/etc/../etc/GCS//AIP_L.cfg'
Jan 11 05:46:29 lbtmu107 LBT_left_GCS: AGW auto selection succeeded.  Instrument: LUCIFER, AGWtype: AIP_LUCIFER, read from file '/lbt/tcs/current/etc/../etc/GCS//Instrument2AGW.cfg'
Jan 11 05:46:29 lbtmu107 LBT_left_GCS: GuideStar set to RA/DEC: 2.61967, 0.640649
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: selectAGW(AIP_LUCIFER):
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: didn't create a new instance of AGWUnitAIP as the types are the same
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: AGW auto selection succeeded.  Instrument: LUCIFER, AGWtype: AIP_LUCIFER, read from file '/lbt/tcs/current/etc/../etc/GCS//Instrument2AGW.cfg'
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: setGuidestarList (and conversion):
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: RA/DEC = 2.619670, 0.640649
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: converted into SFP by PCS (x,y) = -2967129.380275, -7741352.097363 mm
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: best focus determined to be -33178753106.39 mm (including off-axis offset)
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: off axis focus compensation is -33178753141.74 mm
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: AGWUnitAIP: SFP position to move to: -2967129.380275, -7741352.097363 mm
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: AGWUnitAIP: rotation of the AGW coords system in relation to SFP: 179.70 degrees
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: AGWUnitAIP: internal transformation to AGW native coords: 3007625.764174, 7726322.230118 mm
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: AGWUnitAIP: external transformation to AGW native coords: 2869123.894706, 7751933.780321 mm (oacontrol)
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: AGWUnitAIP: moving probe to native coords: 3007625.764174, 7726322.230118 mm using internal transformations
Jan 11 05:46:30 lbtmu107 LBT_left_GCS: AGWUnitAIP::doSetProbePosition: calling oacontrol::setxy(10.144.0.64, 0, x:3007625.764174 y:7726322.230118, 23.000000, 0) ...
Jan 11 05:46:31 lbtmu107 LBT_left_GCS: [E] AIP AGW unit error: AGW1: Requested position is Out of Range
Jan 11 05:46:31 lbtmu107 LBT_left_GCS: AGW::setxy(3007625.8, 7726322.2) returned 255
Jan 11 05:46:31 lbtmu107 LBT_left_GCS: error: setProbePosition: couldn't move probe to position (SFP) (x,y,z): -2967129.380275, -7741352.097363, -33178753106.386253 mm.

Note: the guide star coordinates reported by GCS were 10:00:23.04 00:38:26.34 but LUCIFER was trying to send 12:00:23.04. This could have been a typo on the LUCIFER UI, but normally this should return with a failure on a preset.

Sun Jan 11 06:11:52.727 2009 GCS restarted

An offset at the end of the night: Jan 11 06:52:39.131 2009 appears to have gone through all of the right motions.
Jan 11 06:47:25 lbtmu107 LBT_left_GCS: no guide star found, time till warning is 10.400000 seconds
Jan 11 06:47:31 lbtmu107 LBT_left_GCS: no guide star found, time till warning is 5.800000 seconds
Jan 11 06:47:36 lbtmu107 LBT_left_GCS: no guide star found, time till warning is 1.200000 seconds
Jan 11 06:47:41 lbtmu107 LBT_left_GCS: no guide star found, time till warning is -3.400000 seconds
Jan 11 06:47:52 lbtmu107 LBT_left_GCS: no guide star found, time till warning is -8.000000 seconds
Jan 11 06:48:00 lbtmu107 LBT_left_GCS: no guide star found, time till warning is -12.600000 seconds
ending with...
Jan 11 07:06:41 lbtmu107 LBT_left_GCS: no guide star found, time till warning is -891.200000 second

Torsten: did your countdown timer miss zero? For the 15 minutes before the block above started there were no similar messages, then the guiding cycle continues indefinitely after this (we stopped guiding manually after 7:00 because it was too bright to continue.

Twilight flats...
7:45 Closed dome

-- DavidThompson - 11 Jan 2009
Topic revision: r6 - 11 Jan 2009, DavidThompson
This site is powered by FoswikiCopyright © by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
Ideas, requests, problems regarding Foswiki? Send feedback