Date: Sun, 21 May 2017 14:30:28 -0600 (MDT)
Subject: Re: [sloan-25mlog 3513] 2.5m obslog 20170520 (SJD 57894)
From: "Daniel Oravetz"
These gotoField failures that occur at the 'axis status'/'axis init' stage
(before the actual slew) have spiked in the last week or two. The sequence
goes:
'tcc axis status' is issued as part of the 'sop gotoField' to check the
status of the telescope axes;
'tcc axis init' gets issued after the 'tcc axis status' finishes (i.e.,
CmdDone) to initialize the axes for slewing;
Then there's the "Sub-command(s) failed" error message:
> "Sub-command(s) failed: :
> Sub-command(s) failed: : Sub-command(s) failed: STATUS: Cannot check
echo
> of
> command='STATUS': no replies; : Sub-command(s) failed: SET.TIME: Timed
out;
> STATUS: Cancelled on queue by immediate priority command 'INIT'; :
Sub-command(s) failed: SET.TIME: Timed out; STATUS: Cancelled on queue by
> immediate priority command 'INIT'"
When this happens the actor logs also show these "utc-time ... TIMEOUT"
failures (e.g., see the Problems in Details from the night log the last
two nights):
"failed to get time from utc-time.apo.nmsu.edu: S_sntpcLib_TIMEOUT"
After a search of the hub logs for the last couple weeks, these "failed to
get time from utc-time.apo.nmsu.edu ..." error messages started to show up
beginning on (UTC date) May 11th:
UTC Date     # of utc-time error messages
--------     ----------------------------
5/5          0
5/6          0
5/7          0
5/8          0
5/9          0
5/10         0
5/11         24
5/12         81
5/13         90
5/14         74
5/15         75
5/16         76
5/17         88
5/18         67
5/19         67
5/20         56
The appearance of these utc-time errors seems to coincide with the day
(during engineering time) sdss-hub was rebooted and the trouble with
plate-mapper began. Is there any reason to think that any of that work
could have affected the communications with utc-time.apo.nmsu.edu or is
the appearance of these error messages at that time merely a coincidence?
Dan
> We received the following error message after the first gotoField of the
night
> (note that the brakes were already clear):
>
> 02:20:22 .hub 0 cmds d
> CmdQueued=632560,1495333222.61,"OBSERVER.kgrabowski",26,"sop",1674,"gotoField
>    arcTime=4.0 flatTime=25.0 guiderFlatTime=0.5 guiderTime=5.0"
> 02:20:22 .hub 0 cmds d
> CmdQueued=632561,1495333222.71,"OBSERVER.kgrabowski.sop",593,"tcc",39316,"axis
status"
> 02:20:23 .hub 0 cmds d
> CmdQueued=632562,1495333223.06,"OBSERVER.kgrabowski.sop",594,"tcc",39317,"axis
init"
> 02:20:37 OBSERVER.kgrabowski.sop 594 tcc f text="Sub-command(s) failed:
:
> Sub-command(s) failed: : Sub-command(s) failed: STATUS: Cannot check
echo
> of
> command='STATUS': no replies; : Sub-command(s) failed: SET.TIME: Timed
out;
> STATUS: Cancelled on queue by immediate priority command 'INIT'; :
Sub-command(s) failed: SET.TIME: Timed out; STATUS: Cancelled on queue by
> immediate priority command 'INIT'"
> 02:20:37 CmdDone: OBSERVER.kgrabowski.sop 594 tcc axis init
> 02:20:37 OBSERVER.kgrabowski 26 sop e text="Cannot slew telescope:
failed
> tcc
> axis init."
> 02:20:37 OBSERVER.kgrabowski 26 sop e text="Cannot slew telescope: check
and
> clear interlocks?"
> ---- Problems in Detail ----
>
>
> 00:13:57 .mcp 582162 mcp d trace="INIT axis rotator: not running:
ABORT_EVENT"
> 00:13:57 .mcp 0 mcp i trace="Resetting amp for axis rotator: 4"
> 00:13:57 .mcp 582162 mcp d trace="set PID coeffs. axis=2, block=0"
00:13:57 .mcp 0 mcp i ab_status=0,14,14,0
> 00:13:57 .mcp 582162 mcp d trace="set PID coeffs. axis=2, block=1"
00:13:58 .mcp 0 mcp i trace="MGT: bad rot amp; aborting"
> 00:13:58 .mcp 582163 mcp d trace="INIT axis altitude: not running:
ABORT_EVENT"
> 00:13:58 .mcp 0 mcp i trace="Resetting amp for axis altitude: 2"
00:13:58 .mcp 582163 mcp d trace="set PID coeffs. axis=1, block=0"
00:13:58 .mcp 0 mcp i trace="Resetting amp for axis altitude: 3"
00:13:59 .mcp 582163 mcp d trace="set PID coeffs. axis=1, block=1"
00:14:00 .mcp 0 mcp i ab_status=0,14,1,14
> 00:14:00 .mcp 0 mcp i ab_I9_L0=0x004c0000
> 00:14:00 .mcp 0 mcp i ab_O12_L0=0x02060000
> 00:14:00 .mcp 582164 mcp d trace="INIT axis azimuth: not running:
ABORT_EVENT"
> 00:14:00 .mcp 0 mcp i trace="Resetting amp for axis azimuth: 0"
> 00:14:00 .mcp 582164 mcp d trace="set PID coeffs. axis=0, block=0"
00:14:00 .mcp 0 mcp i trace="Resetting amp for axis azimuth: 1"
> 00:14:01 .mcp 582164 mcp d trace="set PID coeffs. axis=0, block=1"
00:14:01 .mcp 0 mcp i trace="MGT: bad alt amp; aborting"
> 00:14:02 .mcp 0 mcp i ab_status=0,1,14,14
> 00:14:02 .mcp 0 mcp i ab_I9_L0=0x00040000
> 00:14:02 .mcp 0 mcp i ab_O12_L0=0x02090000
> 00:14:02 .mcp 0 mcp i cwPositions=427,427,426,428
> 00:14:03 .mcp 0 mcp i ab_I9_L0=0x00340000
> 00:14:04 .mcp 0 mcp i trace="MGT: bad az amp; aborting"
> 00:14:05 .mcp 0 mcp i ab_status=0,14,14,14
> 00:14:05 .mcp 0 mcp i ab_I9_L0=0x00240000
> 00:14:05 .mcp 0 mcp i ab_O12_L0=0x020a0000
> 00:14:06 .mcp 0 mcp i ab_I2_L0=0x000000f8
> 00:14:06 .mcp 0 mcp i ab_I6_L0=0xfff3fcfc
> 00:14:06 .mcp 0 mcp i ab_I9_L0=0x002c0000
> 00:14:06 .mcp 0 mcp i ab_O11_L0=0x04cc0040
> 00:14:07 .mcp 0 mcp i trace="failed to get time from
> utc-time.apo.nmsu.edu:
> S_sntpcLib_TIMEOUT"
> 00:14:09 .mcp 0 mcp i ab_I2_L0=0x000000f0
> 00:14:09 .mcp 0 mcp i trace="failed to get time from
> utc-time.apo.nmsu.edu:
> S_errno_EHOSTDOWN"
> 00:14:10 .mcp 0 mcp i trace="failed to get time from
> utc-time.apo.nmsu.edu:
> S_errno_EHOSTDOWN"
> 00:14:10 .mcp 582168 mcp d trace="INIT axis rotator: not running:
ABORT_EVENT"
> 00:14:10 .mcp 0 mcp i trace="Resetting amp for axis rotator: 4"
> 00:14:10 .mcp 582168 mcp d trace="set PID coeffs. axis=2, block=0"
00:14:10 .mcp 582168 mcp d trace="set PID coeffs. axis=2, block=1"
00:14:12 .mcp 582169 mcp d trace="INIT axis altitude: not running:
ABORT_EVENT"
> 00:14:12 .mcp 0 mcp i trace="Resetting amp for axis altitude: 2"
00:14:12 .mcp 582169 mcp d trace="set PID coeffs. axis=1, block=0"
00:14:12 .mcp 0 mcp i trace="Resetting amp for axis altitude: 3"
00:14:12 .mcp 582169 mcp d trace="set PID coeffs. axis=1, block=1"
00:14:14 .mcp 582170 mcp d trace="INIT axis azimuth: not running:
ABORT_EVENT"
> 00:14:14 .mcp 0 mcp i trace="Resetting amp for axis azimuth: 0"
> 00:14:14 .mcp 582170 mcp d trace="set PID coeffs. axis=0, block=0"
00:14:14 .mcp 0 mcp i trace="Resetting amp for axis azimuth: 1"
> 00:14:14 .mcp 582170 mcp d trace="set PID coeffs. axis=0, block=1"
00:14:15 .mcp 0 mcp i ab_status=0,1,1,0
> 00:14:15 .mcp 0 mcp i ab_I6_L0=0xfff3ffff
> 00:14:15 .mcp 0 mcp i ab_I8_L0=0xfdc743ff
> 00:14:15 .mcp 0 mcp i ab_I9_L0=0x00440000
> 00:14:15 .mcp 0 mcp i ab_O2_L0=0x0000000f
> 00:14:15 .mcp 0 mcp i ab_O11_L0=0x07ff0040
> 00:14:15 .mcp 0 mcp i ab_O12_L0=0x02050000
> 00:14:15 .mcp 0 mcp i cwPositions=426,423,427,424
> 00:14:16 .mcp 0 mcp i trace="failed to get time from
> utc-time.apo.nmsu.edu:
> S_errno_EHOSTDOWN"
> 00:14:16 .mcp 0 mcp i ab_I9_L0=0x00540000
> 00:14:17 .mcp 0 mcp i trace="failed to get time from
> utc-time.apo.nmsu.edu:
> S_errno_EHOSTDOWN"
> 00:14:18 .mcp 0 mcp i trace="failed to get time from
> utc-time.apo.nmsu.edu:
> S_errno_EHOSTDOWN"
> 00:14:53 .mcp 582212 mcp d trace="Sending msg to tTimerTask/msgLatched:
type 20
> delay 507 ticks"
> 00:14:53 .mcp 582213 mcp d trace="Sending msg to tTimerTask/msgLatched:
type 18
> delay 503 ticks"
> 00:14:53 .mcp 582214 mcp d trace="Sending msg to tTimerTask/msgLatched:
type 22
> delay 498 ticks"
>
> ____________________________________________________________
> Logs of Nightly APO Activities
> https://trac.sdss.org/tracmailman/browser/private/sloan-25mlog/index.html
>