Date: Thu, 4 May 2006 11:11:06 -0700
From: Russell E Owen
Subject: Re: 2.5m obslog 20060503 (MJD 53859)
At 12:43 PM +0000 2006-05-04, observer@sdsshost2.apo.nmsu.edu wrote:
>09:08Z Telescope stopped tracking without obvious reason but the
>same way as two
>        nights ago. Tccmon showed all axies halted, no breaks were on. We
>        silently lost guide stars in the middle of exposure.
>
>        exposure was aborted, and we started a new one after going back to the
>        filed. Plate done.
I looked at the logs and the basic problem was that the MCP took too
long to reply to an ALT STATUS. The TCC then timed out and eventually
that led to the axes being halted.
The TCC screamed about the timout, issued an AxisNoTrack keyword,
initialized the axes and reported that the axes were halted -- which
is about all it could do. So I'm puzzled how a serious error like
that can happen "silently".
-- Russell
P.S. here is a log excerpt (with irrelevant lines deleted). I've put
note where the timeout occurred. (Note that the entries from
different logs may not be sequenced correctly when things happen very
quickly -- which explains why "to.MCP" commands often are listed
after the associated "from.MCP" replies).
-bash-2.05b$ ./combinelogs.py -d 2006-05-04T09:07:00 -b 60 -a 60
from.tcc25m from.MCP to.MCP
Printing entries in directories ['from.MCP', 'to.MCP', 'from.tcc25m']
from 2006-05-04T09:06:00 to 2006-05-04T09:08:00
...
from.MCP      2006-05-04 09:06:43.340Z AZ  +MOVE 0.0000301 0.0000000
from.MCP      2006-05-04 09:06:43.341Z  OK
to.MCP        2006-05-04 09:06:43.364Z AZ  +MOVE 0.0000301 0.0000000
from.MCP      2006-05-04 09:06:43.484Z ALT +MOVE -0.0000023 0.0000000
from.MCP      2006-05-04 09:06:43.489Z  OK
to.MCP        2006-05-04 09:06:43.504Z ALT +MOVE -0.0000023 0.0000000
from.MCP      2006-05-04 09:06:43.562Z ROT +MOVE 0.0000245 0.0000001
from.MCP      2006-05-04 09:06:43.568Z  OK
from.tcc25m   2006-05-04 09:06:43.580Z 39 19 I MoveItems="NNNYNNNNN"; Moved
from.tcc25m   2006-05-04 09:06:43.586Z 39 19 I ObjOff = 0.000019,
0.000000, 4653450437.25000, -0.000169, 0.000000, 4653450437.25000
from.tcc25m   2006-05-04 09:06:43.591Z 39 19 :
to.MCP        2006-05-04 09:06:43.594Z ROT +MOVE 0.0000245 0.0000001
from.tcc25m   2006-05-04 09:06:43.595Z 40 19 > Started; Cmd="offset
rotator -0.0001130"
from.MCP      2006-05-04 09:06:43.643Z AZ  +MOVE 0.0000000 0.0000000
from.MCP      2006-05-04 09:06:43.650Z  OK
to.MCP        2006-05-04 09:06:43.674Z AZ  +MOVE 0.0000000 0.0000000
from.MCP      2006-05-04 09:06:43.724Z ALT +MOVE 0.0000000 0.0000000
from.MCP      2006-05-04 09:06:43.730Z  OK
to.MCP        2006-05-04 09:06:43.756Z ALT +MOVE 0.0000000 0.0000000
from.MCP      2006-05-04 09:06:43.803Z ROT +MOVE -0.0001130 0.0000000
from.MCP      2006-05-04 09:06:43.810Z  OK
to.MCP        2006-05-04 09:06:43.834Z ROT +MOVE -0.0001130 0.0000000
from.MCP      2006-05-04 09:06:44.005Z AZ  STATUS
from.MCP      2006-05-04 09:06:44.054Z -37.255308 -0.007223
32836.999221 0 0.000000 OK
to.MCP        2006-05-04 09:06:44.054Z AZ  STATUS
*** this command timed out: ***
to.MCP        2006-05-04 09:06:44.254Z ALT STATUS
from.tcc25m   2006-05-04 09:06:47.162Z 0 0 F Modu="prt_Read";
Text="read timed out on port LTA19:"
to.MCP        2006-05-04 09:06:47.272Z AZ  MOVE -37.3405857
-0.0072098 32848.91000
from.MCP      2006-05-04 09:06:49.169Z ALT STATUS
from.tcc25m   2006-05-04 09:06:49.177Z 0 0 W Expected="AZ  MOVE
-37.3405857 -0.0072098 32848.91000"
from.tcc25m   2006-05-04 09:06:49.182Z 0 0 W Received="ALT STATUS"
from.tcc25m   2006-05-04 09:06:49.192Z 0 0 F Modu="prt_ReadMatch";
Text="bad reply"
from.MCP      2006-05-04 09:06:49.220Z 60.553477 -0.002125
32842.166162 0 0.000000 OK
from.tcc25m   2006-05-04 09:06:49.257Z 0 0 W Expected="ALT MOVE
60.5393058 -0.0021292 32848.91000"
from.tcc25m   2006-05-04 09:06:49.262Z 0 0 W Received="53477
-0.002125 32842.166162 0 0.000000"
from.tcc25m   2006-05-04 09:06:49.266Z 0 0 F Modu="prt_ReadMatch";
Text="bad reply"
from.MCP      2006-05-04 09:06:49.270Z ALT MOVE 60.5393058 -0.0021292
32848.91000
from.MCP      2006-05-04 09:06:49.278Z  OK
to.MCP        2006-05-04 09:06:49.294Z ALT MOVE 60.5393058 -0.0021292
32848.91000
from.tcc25m   2006-05-04 09:06:49.338Z 0 0 W Expected="ROT MOVE
148.8408103 -0.0056812 32848.91000"
from.tcc25m   2006-05-04 09:06:49.342Z 0 0 W Received="92 32848.91000"
from.tcc25m   2006-05-04 09:06:49.346Z 0 0 F Modu="prt_ReadMatch";
Text="bad reply"
from.MCP      2006-05-04 09:06:49.350Z ROT MOVE 148.8408103
-0.0056812 32848.91000
from.tcc25m   2006-05-04 09:06:49.351Z 0 0 F Text="failed to move one
or more axes"; AxisNoTrack="TTT";
AxisErrCode="ControllerErr","ControllerErr","ControllerErr"
...
from.tcc25m   2006-05-04 09:06:57.098Z 0 0 I TCCStatus="HHH","NNN";
TCCPos=NaN,NaN,NaN; AxePos=-37.30,60.55,148.87