ACU: "Program Track failure"

[mhasself]

Capturing some logs for failed tracks that seem to be on an edge case. SATP1.

2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 start called for set_scan_params
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 set_scan_params:9 Status is now "starting".
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 Updated default scan params to {'az_speed': 0.5, 'az_accel': 0.25}
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 set_scan_params:9 Done
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 set_scan_params:9 Status is now "done".
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 start called for generate_scan
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 generate_scan:10 Status is now "starting".
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 User scan params: {'scan_upload_length': None, 'az_only': True, 'az_drift': 0.0, 'az_start': 'end', 'step_time': None, 'wait_to_start': None, 'start_time': None, 'num_scans': None, 'el_speed': 0.0, 'el_endpoint2': None, 'el_endpoint1': None, 'az_accel': None, 'az_speed': None, 'az_endpoint2': 220.0, 'az_endpoint1': 180.0}
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 generate_scan:10 Status is now "running".
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 The plan: {'step_time': 1.0, 'turnprep_buffer': 2.5, 'rampup_buffer': 0.25, 'scan_start_buffer': 0, 'rampup_time': 0.5, 'wait_to_start': 5, 'init_az': 180.0}
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 The scan_params: {'az_start': 'end', 'az_drift': 0.0, 'step_time': 1.0, 'wait_to_start': 5}
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 Sun safety check: Sun-safety checking is not enabled.
2024-01-23T19:14:01Z    2024-01-23T19:14:01+0000 Clearing faults to prepare for motion.
2024-01-23T19:14:02Z    2024-01-23T19:14:02+0000 Moving to start position, az=180.0, el=None
2024-01-23T19:14:02Z    2024-01-23T19:14:02+0000 Azimuth.state=INIT             dt=  0.000 dist=   0.001
2024-01-23T19:14:02Z    2024-01-23T19:14:02+0000 Azimuth.state=WAIT_MOVING      dt=  0.101 dist=   0.001
2024-01-23T19:14:02Z    2024-01-23T19:14:02+0000 Azimuth_mode is now "Preset"
2024-01-23T19:14:02Z    2024-01-23T19:14:02+0000 Elevation_mode is now "Preset"
2024-01-23T19:14:02Z    2024-01-23T19:14:02+0000 Azimuth.state=WAIT_STILL       dt=  0.302 dist=   0.001
2024-01-23T19:14:03Z    2024-01-23T19:14:03+0000 Azimuth.state=DONE             dt=  1.108 dist=   0.001
2024-01-23T19:14:04Z    2024-01-23T19:14:04+0000 Azimuth_mode is now "ProgramTrack"
2024-01-23T19:14:04Z    2024-01-23T19:14:04+0000 scan mode=go, line_buffer=0, track_free=10000
2024-01-23T19:14:13Z    2024-01-23T19:14:13+0000 Fault during track: "ProgramTrack_position_failure"
2024-01-23T19:14:13Z    2024-01-23T19:14:13+0000 Azimuth_mode is now "Stop"
2024-01-23T19:14:13Z    2024-01-23T19:14:13+0000 Unexpected mode transition!
2024-01-23T19:14:13Z    2024-01-23T19:14:13+0000 scan mode=abort, line_buffer=0, track_free=9989
2024-01-23T19:14:32Z    2024-01-23T19:14:32+0000 generate_scan:10 Problems during scan
2024-01-23T19:14:32Z    2024-01-23T19:14:32+0000 generate_scan:10 Status is now "done".

But after clear-faults, it worked:

2024-01-23T19:18:40Z    2024-01-23T19:18:40+0000 start called for clear_faults
2024-01-23T19:18:40Z    2024-01-23T19:18:40+0000 clear_faults:11 Status is now "starting".
2024-01-23T19:18:40Z    2024-01-23T19:18:40+0000 clear_faults:11 Status is now "running".
2024-01-23T19:18:40Z    2024-01-23T19:18:40+0000 clear_faults:11 Status is now "stopping".
2024-01-23T19:18:40Z    2024-01-23T19:18:40+0000 clear_faults:11 Job completed.
2024-01-23T19:18:40Z    2024-01-23T19:18:40+0000 clear_faults:11 Status is now "done".
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 start called for set_scan_params
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 set_scan_params:12 Status is now "starting".
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 Updated default scan params to {'az_speed': 0.5, 'az_accel': 0.25}
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 set_scan_params:12 Done
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 set_scan_params:12 Status is now "done".
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 start called for generate_scan
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 generate_scan:13 Status is now "starting".
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 User scan params: {'scan_upload_length': None, 'az_only': True, 'az_drift': 0.0, 'az_start': 'end', 'step_time': None, 'wait_to_start': None, 'start_time': None, 'num_scans': None, 'el_speed': 0.0, 'el_endpoint2': None, 'el_endpoint1': None, 'az_accel': None, 'az_speed': None, 'az_endpoint2': 220.0, 'az_endpoint1': 180.0}
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 generate_scan:13 Status is now "running".
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 The plan: {'step_time': 1.0, 'turnprep_buffer': 2.5, 'rampup_buffer': 0.25, 'scan_start_buffer': 0, 'rampup_time': 0.5, 'wait_to_start': 5, 'init_az': 180.0}
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 The scan_params: {'az_start': 'end', 'az_drift': 0.0, 'step_time': 1.0, 'wait_to_start': 5}
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 Sun safety check: Sun-safety checking is not enabled.
2024-01-23T19:21:45Z    2024-01-23T19:21:45+0000 Clearing faults to prepare for motion.
2024-01-23T19:21:46Z    2024-01-23T19:21:46+0000 Moving to start position, az=180.0, el=None
2024-01-23T19:21:46Z    2024-01-23T19:21:46+0000 Azimuth.state=INIT             dt=  0.000 dist=   0.001
2024-01-23T19:21:46Z    2024-01-23T19:21:46+0000 Azimuth.state=WAIT_MOVING      dt=  0.101 dist=   0.001
2024-01-23T19:21:46Z    2024-01-23T19:21:46+0000 Azimuth_mode is now "Preset"
2024-01-23T19:21:46Z    2024-01-23T19:21:46+0000 Azimuth.state=WAIT_STILL       dt=  0.302 dist=   0.001
2024-01-23T19:21:47Z    2024-01-23T19:21:47+0000 Azimuth.state=DONE             dt=  1.107 dist=   0.001
2024-01-23T19:21:48Z    2024-01-23T19:21:48+0000 Azimuth_mode is now "ProgramTrack"
2024-01-23T19:21:48Z    2024-01-23T19:21:48+0000 scan mode=go, line_buffer=0, track_free=10000

[mhasself]

Then this one just didn't do anything; moved to az=180 and bailed out of the loop without scanning. "Free positions" never moved from 10000.

2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 start called for generate_scan
2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 generate_scan:15 Status is now "starting".
2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 User scan params: {'scan_upload_length': None, 'az_only': True, 'az_drift': 0.0, 'az_start': 'end', 'step_time': None, 'wait_to_start': None, 'start_time': None, 'num_scans': None, 'el_speed': 0.0, 'el_endpoint2': None, 'el_endpoint1': None, 'az_accel': None, 'az_speed': None, 'az_endpoint2': 220.0, 'az_endpoint1': 180.0}
2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 generate_scan:15 Status is now "running".
2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 The plan: {'step_time': 1.0, 'turnprep_buffer': 2.5, 'rampup_buffer': 0.25, 'scan_start_buffer': 0, 'rampup_time': 0.5, 'wait_to_start': 5, 'init_az': 180.0}
2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 The scan_params: {'az_start': 'end', 'az_drift': 0.0, 'step_time': 1.0, 'wait_to_start': 5}
2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 Sun safety check: Sun-safety checking is not enabled.
2024-01-23T19:31:36Z    2024-01-23T19:31:36+0000 Clearing faults to prepare for motion.
2024-01-23T19:31:37Z    2024-01-23T19:31:37+0000 Moving to start position, az=180.0, el=None
2024-01-23T19:31:37Z    2024-01-23T19:31:37+0000 Azimuth.state=INIT             dt=  0.000 dist=   4.502
2024-01-23T19:31:37Z    2024-01-23T19:31:37+0000 Azimuth.state=WAIT_MOVING      dt=  0.100 dist=   4.502
2024-01-23T19:31:37Z    2024-01-23T19:31:37+0000 Azimuth_mode is now "Preset"
2024-01-23T19:31:37Z    2024-01-23T19:31:37+0000 Azimuth.state=WAIT_STILL       dt=  0.303 dist=   4.502
2024-01-23T19:31:48Z    2024-01-23T19:31:48+0000 Azimuth.state=DONE             dt= 11.316 dist=   0.002
2024-01-23T19:31:49Z    2024-01-23T19:31:49+0000 Azimuth_mode is now "ProgramTrack"
2024-01-23T19:31:50Z    2024-01-23T19:31:50+0000 scan mode=go, line_buffer=0, track_free=10000
2024-01-23T19:32:41Z    2024-01-23T19:32:41+0000 generate_scan:15 Scan ended cleanly
2024-01-23T19:32:41Z    2024-01-23T19:32:41+0000 generate_scan:15 Status is now "done".

[mhasself]

This is all with SOCS=v0.4.5