2021-09-17T16:33:23.193Z,1631896403.193 [Supervisor](DEBUG): Initializing supervisor. 2021-09-17T16:33:23.197Z,1631896403.197 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2021-09-17T16:33:23.198Z,1631896403.198 [SyncHandler](INFO): Protected caller Thread ID is 835 2021-09-17T16:33:23.198Z,1631896403.198 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2021-09-17T16:33:23.199Z,1631896403.199 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2021-09-17T16:33:23.199Z,1631896403.199 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 836 2021-09-17T16:33:23.204Z,1631896403.204 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2021-09-17T16:33:23.225Z,1631896403.225 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2021-09-17T16:33:23.226Z,1631896403.226 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2021-09-17T16:33:23.226Z,1631896403.226 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 837 2021-09-17T16:33:23.228Z,1631896403.228 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2021-09-17T16:33:23.229Z,1631896403.229 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2021-09-17T16:33:23.230Z,1631896403.230 [logger ThreadHandler](INFO): Protected caller Thread ID is 838 2021-09-17T16:33:23.234Z,1631896403.234 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2021-09-17T16:33:23.234Z,1631896403.234 [Supervisor](INFO): Looking for Config files in directory: Config/ 2021-09-17T16:33:23.239Z,1631896403.239 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2021-09-17T16:33:23.661Z,1631896403.661 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2021-09-17T16:33:23.662Z,1631896403.662 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2021-09-17T16:33:23.742Z,1631896403.742 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2021-09-17T16:33:24.077Z,1631896404.077 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2021-09-17T16:33:24.079Z,1631896404.079 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2021-09-17T16:33:24.232Z,1631896404.232 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2021-09-17T16:33:24.234Z,1631896404.234 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2021-09-17T16:33:24.437Z,1631896404.437 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2021-09-17T16:33:24.439Z,1631896404.439 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2021-09-17T16:33:24.965Z,1631896404.965 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2021-09-17T16:33:24.967Z,1631896404.967 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2021-09-17T16:33:25.212Z,1631896405.212 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2021-09-17T16:33:25.214Z,1631896405.214 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2021-09-17T16:33:25.371Z,1631896405.371 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2021-09-17T16:33:25.372Z,1631896405.372 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2021-09-17T16:33:25.566Z,1631896405.566 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2021-09-17T16:33:25.567Z,1631896405.567 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2021-09-17T16:33:25.665Z,1631896405.665 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2021-09-17T16:33:25.665Z,1631896405.665 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2021-09-17T16:33:25.895Z,1631896405.895 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2021-09-17T16:33:25.895Z,1631896405.895 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2021-09-17T16:33:26.282Z,1631896406.282 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2021-09-17T16:33:26.282Z,1631896406.282 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2021-09-17T16:33:26.365Z,1631896406.365 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2021-09-17T16:33:26.495Z,1631896406.495 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2021-09-17T16:33:26.496Z,1631896406.496 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2021-09-17T16:33:27.715Z,1631896407.715 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2021-09-17T16:33:27.717Z,1631896407.717 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2021-09-17T16:33:28.097Z,1631896408.097 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2021-09-17T16:33:28.099Z,1631896408.099 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-polaris/ 2021-09-17T16:33:28.104Z,1631896408.104 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/vehicle.cfg 2021-09-17T16:33:28.309Z,1631896408.309 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Control.cfg 2021-09-17T16:33:28.440Z,1631896408.440 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Estimation.cfg 2021-09-17T16:33:28.541Z,1631896408.541 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/BIT.cfg 2021-09-17T16:33:28.642Z,1631896408.642 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Battery.cfg 2021-09-17T16:33:28.906Z,1631896408.906 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2021-09-17T16:33:28.907Z,1631896408.907 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Simulator.cfg 2021-09-17T16:33:28.994Z,1631896408.994 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Navigation.cfg 2021-09-17T16:33:29.090Z,1631896409.090 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Derivation.cfg 2021-09-17T16:33:29.217Z,1631896409.217 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/logger.cfg 2021-09-17T16:33:29.330Z,1631896409.330 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/secure.cfg 2021-09-17T16:33:29.418Z,1631896409.418 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Dock.cfg 2021-09-17T16:33:29.505Z,1631896409.505 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Servo.cfg 2021-09-17T16:33:29.615Z,1631896409.615 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/workSite.cfg 2021-09-17T16:33:29.714Z,1631896409.714 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Sensor.cfg 2021-09-17T16:33:29.913Z,1631896409.913 [Supervisor](INFO): Opening Config file at: Config/lrauv-polaris/Science.cfg 2021-09-17T16:33:30.078Z,1631896410.078 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2021-09-17T16:33:30.082Z,1631896410.082 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2021-09-17T16:33:30.788Z,1631896410.788 [AHRS_M2] Loaded 2021-09-17T16:33:30.788Z,1631896410.788 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2021-09-17T16:33:31.252Z,1631896411.252 [BackseatComponent] Loaded 2021-09-17T16:33:31.253Z,1631896411.253 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread. 2021-09-17T16:33:31.254Z,1631896411.254 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 4079A4E0 2021-09-17T16:33:31.254Z,1631896411.254 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 933 2021-09-17T16:33:31.257Z,1631896411.257 [LcmUniversalReporter] Loaded 2021-09-17T16:33:31.257Z,1631896411.257 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread. 2021-09-17T16:33:32.445Z,1631896412.445 [BPC1] Loaded 2021-09-17T16:33:32.445Z,1631896412.445 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2021-09-17T16:33:32.648Z,1631896412.648 [DataOverHttps] Loaded 2021-09-17T16:33:32.648Z,1631896412.648 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2021-09-17T16:33:32.649Z,1631896412.649 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407CA4E0 2021-09-17T16:33:32.650Z,1631896412.650 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 934 2021-09-17T16:33:32.669Z,1631896412.669 [Depth_Keller] Loaded 2021-09-17T16:33:32.670Z,1631896412.670 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2021-09-17T16:33:32.674Z,1631896412.674 [DropWeight] Loaded 2021-09-17T16:33:32.675Z,1631896412.675 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2021-09-17T16:33:32.812Z,1631896412.812 [Micromodem] Loaded 2021-09-17T16:33:32.812Z,1631896412.812 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2021-09-17T16:33:32.987Z,1631896412.987 [NAL9602] Loaded 2021-09-17T16:33:32.987Z,1631896412.987 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2021-09-17T16:33:33.197Z,1631896413.197 [Onboard] Loaded 2021-09-17T16:33:33.197Z,1631896413.197 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2021-09-17T16:33:33.198Z,1631896413.198 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 407FA4E0 2021-09-17T16:33:33.198Z,1631896413.198 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 935 2021-09-17T16:33:33.208Z,1631896413.208 [PowerOnly](INFO): Adding load control power supply at /dev/loadC1 2021-09-17T16:33:33.220Z,1631896413.220 [PowerOnly] Loaded 2021-09-17T16:33:33.221Z,1631896413.221 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2021-09-17T16:33:33.232Z,1631896413.232 [Power24vConverter] Loaded 2021-09-17T16:33:33.233Z,1631896413.233 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2021-09-17T16:33:33.246Z,1631896413.246 [Radio_Surface] Loaded 2021-09-17T16:33:33.247Z,1631896413.247 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2021-09-17T16:33:33.248Z,1631896413.248 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4082A4E0 2021-09-17T16:33:33.248Z,1631896413.248 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 936 2021-09-17T16:33:33.292Z,1631896413.292 [RDI_Pathfinder] Loaded 2021-09-17T16:33:33.292Z,1631896413.292 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2021-09-17T16:33:33.319Z,1631896413.319 [RDI_PathfinderUp] Loaded 2021-09-17T16:33:33.319Z,1631896413.319 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread. 2021-09-17T16:33:33.320Z,1631896413.320 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2021-09-17T16:33:33.321Z,1631896413.321 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2021-09-17T16:33:33.337Z,1631896413.337 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2021-09-17T16:33:33.338Z,1631896413.338 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2021-09-17T16:33:33.437Z,1631896413.437 [DeadReckonUsingMultipleVelocitySources] Loaded 2021-09-17T16:33:33.437Z,1631896413.437 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2021-09-17T16:33:33.451Z,1631896413.451 [NavChart] Loaded 2021-09-17T16:33:33.451Z,1631896413.451 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2021-09-17T16:33:33.457Z,1631896413.457 [UniversalFixResidualReporter] Loaded 2021-09-17T16:33:33.458Z,1631896413.458 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2021-09-17T16:33:33.468Z,1631896413.468 [WorkSite] Loaded 2021-09-17T16:33:33.469Z,1631896413.469 [ComponentRegistry](DEBUG): SyncComponent "WorkSite" handled in the control thread. 2021-09-17T16:33:33.469Z,1631896413.469 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2021-09-17T16:33:33.470Z,1631896413.470 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2021-09-17T16:33:33.594Z,1631896413.594 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2021-09-17T16:33:33.594Z,1631896413.594 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2021-09-17T16:33:33.756Z,1631896413.756 [BuoyancyServo] Loaded 2021-09-17T16:33:33.756Z,1631896413.756 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2021-09-17T16:33:33.778Z,1631896413.778 [ElevatorServo] Loaded 2021-09-17T16:33:33.779Z,1631896413.779 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2021-09-17T16:33:33.799Z,1631896413.799 [MassServo] Loaded 2021-09-17T16:33:33.800Z,1631896413.800 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2021-09-17T16:33:33.820Z,1631896413.820 [RudderServo] Loaded 2021-09-17T16:33:33.821Z,1631896413.821 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2021-09-17T16:33:33.840Z,1631896413.840 [ThrusterServo] Loaded 2021-09-17T16:33:33.840Z,1631896413.840 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2021-09-17T16:33:33.841Z,1631896413.841 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2021-09-17T16:33:33.841Z,1631896413.841 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2021-09-17T16:33:34.072Z,1631896414.072 [CTD_Seabird] Loaded 2021-09-17T16:33:34.072Z,1631896414.072 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2021-09-17T16:33:34.073Z,1631896414.073 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409544E0 2021-09-17T16:33:34.074Z,1631896414.074 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 937 2021-09-17T16:33:34.094Z,1631896414.094 [PAR_Licor] Loaded 2021-09-17T16:33:34.095Z,1631896414.095 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2021-09-17T16:33:34.128Z,1631896414.128 [WetLabsSeaOWL_UV_A] Loaded 2021-09-17T16:33:34.128Z,1631896414.128 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2021-09-17T16:33:34.129Z,1631896414.129 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409844E0 2021-09-17T16:33:34.130Z,1631896414.130 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 938 2021-09-17T16:33:34.130Z,1631896414.130 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2021-09-17T16:33:34.131Z,1631896414.131 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2021-09-17T16:33:34.524Z,1631896414.524 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2021-09-17T16:33:34.525Z,1631896414.525 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2021-09-17T16:33:34.588Z,1631896414.588 [DepthRateCalculator] Loaded 2021-09-17T16:33:34.589Z,1631896414.589 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2021-09-17T16:33:34.594Z,1631896414.594 [PitchRateCalculator] Loaded 2021-09-17T16:33:34.595Z,1631896414.595 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2021-09-17T16:33:34.604Z,1631896414.604 [SpeedCalculator] Loaded 2021-09-17T16:33:34.604Z,1631896414.604 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2021-09-17T16:33:34.618Z,1631896414.618 [TempGradientCalculator] Loaded 2021-09-17T16:33:34.619Z,1631896414.619 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2021-09-17T16:33:34.635Z,1631896414.635 [VerticalHomogeneityIndexCalculator] Loaded 2021-09-17T16:33:34.635Z,1631896414.635 [ComponentRegistry](DEBUG): SyncComponent "VerticalHomogeneityIndexCalculator" handled in the control thread. 2021-09-17T16:33:34.640Z,1631896414.640 [YawRateCalculator] Loaded 2021-09-17T16:33:34.640Z,1631896414.640 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2021-09-17T16:33:34.677Z,1631896414.677 [ElevatorOffsetCalculator] Loaded 2021-09-17T16:33:34.677Z,1631896414.677 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2021-09-17T16:33:34.678Z,1631896414.678 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2021-09-17T16:33:34.679Z,1631896414.679 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2021-09-17T16:33:34.860Z,1631896414.860 [SBIT](DEBUG): Construct Startup Built In Test. 2021-09-17T16:33:34.873Z,1631896414.873 [SBIT] Loaded 2021-09-17T16:33:34.873Z,1631896414.873 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2021-09-17T16:33:34.876Z,1631896414.876 [IBIT](DEBUG): Construct Initiated Built In Test. 2021-09-17T16:33:34.890Z,1631896414.890 [IBIT] Loaded 2021-09-17T16:33:34.890Z,1631896414.890 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2021-09-17T16:33:34.896Z,1631896414.896 [CBIT](DEBUG): Construct Continuous Built In Test. 2021-09-17T16:33:35.003Z,1631896415.003 [CBIT] Loaded 2021-09-17T16:33:35.003Z,1631896415.003 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2021-09-17T16:33:35.003Z,1631896415.003 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2021-09-17T16:33:35.004Z,1631896415.004 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2021-09-17T16:33:35.100Z,1631896415.100 [StratificationFrontDetector](IMPORTANT): thresholdVTHI set to: 0.399988 degC 2021-09-17T16:33:35.100Z,1631896415.100 [StratificationFrontDetector](INFO): (re)initializing 2021-09-17T16:33:35.101Z,1631896415.101 [StratificationFrontDetector] Loaded 2021-09-17T16:33:35.101Z,1631896415.101 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread. 2021-09-17T16:33:35.101Z,1631896415.101 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2021-09-17T16:33:35.102Z,1631896415.102 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2021-09-17T16:33:35.240Z,1631896415.240 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2021-09-17T16:33:35.241Z,1631896415.241 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2021-09-17T16:33:35.313Z,1631896415.313 [VerticalControl](DEBUG): Construct VerticalControl. 2021-09-17T16:33:35.369Z,1631896415.369 [VerticalControl] Loaded 2021-09-17T16:33:35.369Z,1631896415.369 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2021-09-17T16:33:35.372Z,1631896415.372 [HorizontalControl](DEBUG): Construct HorizontalControl. 2021-09-17T16:33:35.410Z,1631896415.410 [HorizontalControl] Loaded 2021-09-17T16:33:35.410Z,1631896415.410 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2021-09-17T16:33:35.413Z,1631896415.413 [SpeedControl](DEBUG): Construct SpeedControl. 2021-09-17T16:33:35.414Z,1631896415.414 [SpeedControl] Loaded 2021-09-17T16:33:35.415Z,1631896415.415 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2021-09-17T16:33:35.417Z,1631896415.417 [LoopControl](DEBUG): Construct LoopControl. 2021-09-17T16:33:35.418Z,1631896415.418 [LoopControl] Loaded 2021-09-17T16:33:35.418Z,1631896415.418 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2021-09-17T16:33:35.419Z,1631896415.419 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2021-09-17T16:33:35.419Z,1631896415.419 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2021-09-17T16:33:35.463Z,1631896415.463 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2021-09-17T16:33:35.470Z,1631896415.470 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2021-09-17T16:33:35.473Z,1631896415.473 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2021-09-17T16:33:35.484Z,1631896415.484 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2021-09-17T16:33:35.485Z,1631896415.485 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B324E0 2021-09-17T16:33:35.485Z,1631896415.485 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 939 2021-09-17T16:33:35.490Z,1631896415.490 [Supervisor](INFO): Main Thread ID is 829 2021-09-17T16:33:35.490Z,1631896415.490 [Supervisor](DEBUG): Running supervisor. 2021-09-17T16:33:35.491Z,1631896415.491 [CommandLine ThreadHandler](INFO): Handler Thread ID is 940 2021-09-17T16:33:35.493Z,1631896415.493 [controlThread ThreadHandler](INFO): Handler Thread ID is 941 2021-09-17T16:33:35.494Z,1631896415.494 [controlThread](DEBUG): Initializing ControlThread 2021-09-17T16:33:35.499Z,1631896415.499 [NavChart](DEBUG): Initialize NavChart Navigation. 2021-09-17T16:33:35.499Z,1631896415.499 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2021-09-17T16:33:35.500Z,1631896415.500 [WorkSite](DEBUG): Initializing WorkSite component. 2021-09-17T16:33:35.504Z,1631896415.504 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2021-09-17T16:33:35.505Z,1631896415.505 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2021-09-17T16:33:35.505Z,1631896415.505 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2021-09-17T16:33:35.505Z,1631896415.505 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2021-09-17T16:33:35.506Z,1631896415.506 [VerticalHomogeneityIndexCalculator](DEBUG): (re)initializing 2021-09-17T16:33:35.507Z,1631896415.507 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2021-09-17T16:33:35.507Z,1631896415.507 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2021-09-17T16:33:35.508Z,1631896415.508 [SBIT](INFO): Initialize SBIT Component. 2021-09-17T16:33:35.509Z,1631896415.509 [SBIT](IMPORTANT): git: 2021-09-08a 2021-09-17T16:33:35.509Z,1631896415.509 [SBIT](INFO): git hash: bad7acd522f33fafb57bb68c86a88bc7b3656cfc 2021-09-17T16:33:35.509Z,1631896415.509 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2021-09-17T16:33:35.511Z,1631896415.511 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Thu Aug 6 12:04:53 PDT 2020 2021-09-17T16:33:35.512Z,1631896415.512 [SBIT](INFO): Beginning SBIT in 36.000000 seconds. 2021-09-17T16:33:35.512Z,1631896415.512 [IBIT](INFO): Initialize IBIT Component. 2021-09-17T16:33:35.513Z,1631896415.513 [CBIT](DEBUG): Initialize CBIT Component. 2021-09-17T16:33:35.514Z,1631896415.514 [logger ThreadHandler](INFO): Handler Thread ID is 942 2021-09-17T16:33:35.528Z,1631896415.528 [CBIT](DEBUG): Initialized mux pins. 2021-09-17T16:33:35.528Z,1631896415.528 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2021-09-17T16:33:35.528Z,1631896415.528 [CBIT](DEBUG): Initializing the watchdog timer. 2021-09-17T16:33:35.532Z,1631896415.532 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 943 2021-09-17T16:33:35.540Z,1631896415.540 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 944 2021-09-17T16:33:35.541Z,1631896415.541 [DataOverHttps](DEBUG): dashIP=128.128.181.155 starts with a digit so assuming it is a numeric IP 2021-09-17T16:33:35.548Z,1631896415.548 [Onboard ThreadHandler](INFO): Handler Thread ID is 945 2021-09-17T16:33:35.553Z,1631896415.553 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET. 2021-09-17T16:33:35.561Z,1631896415.561 [CBIT](FAULT): Found backtrace file: 1631896266.603016 [NAL9602]: SIGSEGV: address not mapped to object 1631896266.603016 [NAL9602]: Backtrace: ./bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x1a11d0] 2021-09-17T16:33:35.579Z,1631896415.579 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 946 2021-09-17T16:33:35.581Z,1631896415.581 [CBIT](FAULT): Renaming backtrace file to Data/backtrace19 2021-09-17T16:33:35.582Z,1631896415.582 [CBIT](DEBUG): Initializing heartbeat. 2021-09-17T16:33:35.585Z,1631896415.585 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 947 2021-09-17T16:33:35.586Z,1631896415.586 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2021-09-17T16:33:35.598Z,1631896415.598 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 949 2021-09-17T16:33:35.598Z,1631896415.598 [WetLabsSeaOWL_UV_A](INFO): Powering down 2021-09-17T16:33:35.612Z,1631896415.612 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 950 2021-09-17T16:33:35.621Z,1631896415.621 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2021-09-17T16:33:35.622Z,1631896415.622 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2021-09-17T16:33:35.622Z,1631896415.622 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2021-09-17T16:33:35.622Z,1631896415.622 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2021-09-17T16:33:35.622Z,1631896415.622 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2021-09-17T16:33:35.622Z,1631896415.622 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2021-09-17T16:33:35.622Z,1631896415.622 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2021-09-17T16:33:35.623Z,1631896415.623 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2021-09-17T16:33:35.623Z,1631896415.623 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2021-09-17T16:33:35.623Z,1631896415.623 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2021-09-17T16:33:35.623Z,1631896415.623 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2021-09-17T16:33:35.623Z,1631896415.623 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2021-09-17T16:33:35.624Z,1631896415.624 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2021-09-17T16:33:35.624Z,1631896415.624 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2021-09-17T16:33:35.624Z,1631896415.624 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2021-09-17T16:33:35.624Z,1631896415.624 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2021-09-17T16:33:35.652Z,1631896415.652 [CBIT](DEBUG): Deactivating GF circuits. 2021-09-17T16:33:35.652Z,1631896415.652 [CBIT](DEBUG): Deactivating emergency mode. 2021-09-17T16:33:35.688Z,1631896415.688 [CBIT](DEBUG): Backplane powered. 2021-09-17T16:33:35.688Z,1631896415.688 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2021-09-17T16:33:35.690Z,1631896415.690 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2021-09-17T16:33:35.691Z,1631896415.691 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2021-09-17T16:33:35.692Z,1631896415.692 [LoopControl](DEBUG): Initialize LoopControlComponent. 2021-09-17T16:33:35.693Z,1631896415.693 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2021-09-17T16:33:35.721Z,1631896415.721 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2021-09-17T16:33:35.768Z,1631896415.768 [MissionManager](DEBUG): 2021-09-17T16:33:35.769Z,1631896415.769 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2021-09-17T16:33:35.835Z,1631896415.835 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2021-09-17T16:33:35.851Z,1631896415.851 [Default:A.Wait](DEBUG): Construct Wait. 2021-09-17T16:33:35.854Z,1631896415.854 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2021-09-17T16:33:35.902Z,1631896415.902 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2021-09-17T16:33:35.925Z,1631896415.925 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2021-09-17T16:33:35.931Z,1631896415.931 [Default:E.Execute](DEBUG): Construct Execute. 2021-09-17T16:33:35.951Z,1631896415.951 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2021-09-17T16:33:35.957Z,1631896415.957 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,Micromodem,NAL9602,PowerOnly,Power24vConverter,RDI_Pathfinder,RDI_PathfinderUp,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,WorkSite,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2021-09-17T16:33:35.972Z,1631896415.972 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2021-09-17T16:33:35.984Z,1631896415.984 [Radio_Surface](INFO): Powering up 2021-09-17T16:33:36.117Z,1631896416.117 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar 2021-09-17T16:33:36.119Z,1631896416.119 [Power24vConverter](INFO): Powering up. 2021-09-17T16:33:36.150Z,1631896416.150 [DepthRateCalculator](ERROR): Depth measurement is not active 2021-09-17T16:33:36.174Z,1631896416.174 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2021-09-17T16:33:36.180Z,1631896416.180 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2021-09-17T16:33:36.181Z,1631896416.181 [ElevatorServo](DEBUG): Initializing EZServoServo. 2021-09-17T16:33:36.188Z,1631896416.188 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2021-09-17T16:33:36.189Z,1631896416.189 [MassServo](DEBUG): Initializing EZServoServo. 2021-09-17T16:33:36.196Z,1631896416.196 [MassServo](DEBUG): Initializing MassServo. 2021-09-17T16:33:36.197Z,1631896416.197 [RudderServo](DEBUG): Initializing EZServoServo. 2021-09-17T16:33:36.204Z,1631896416.204 [RudderServo](DEBUG): Initializing RudderServo. 2021-09-17T16:33:36.205Z,1631896416.205 [ThrusterServo](DEBUG): Initializing EZServoServo. 2021-09-17T16:33:36.212Z,1631896416.212 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2021-09-17T16:33:36.214Z,1631896416.214 [CommandLine](FAULT): Scheduling is paused 2021-09-17T16:33:36.215Z,1631896416.215 [CBIT](INFO): Critical error at 20210917T163335 2021-09-17T16:33:36.215Z,1631896416.215 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2021-09-17T16:33:36.387Z,1631896416.387 [Micromodem](INFO): Powering up 2021-09-17T16:33:36.387Z,1631896416.387 [Micromodem](DEBUG): Initializing Micromodem. 2021-09-17T16:33:37.124Z,1631896417.124 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2021-09-17T16:33:37.124Z,1631896417.124 [RudderServo](FAULT): Rudder failed to initialize 2021-09-17T16:33:37.124Z,1631896417.124 [RudderServo] Communications Fault, FailCount= 1 2021-09-17T16:33:37.124Z,1631896417.124 [RudderServo](ERROR): Communications Fault 2021-09-17T16:33:37.224Z,1631896417.224 [CBIT](ERROR): Communications Fault in component: RudderServo 2021-09-17T16:33:37.455Z,1631896417.455 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2021-09-17T16:33:37.455Z,1631896417.455 [RudderServo](INFO): Powering down 2021-09-17T16:33:38.061Z,1631896418.061 [RudderServo](DEBUG): Initializing EZServoServo. 2021-09-17T16:33:38.181Z,1631896418.181 [RudderServo](DEBUG): Initializing RudderServo. 2021-09-17T16:33:38.185Z,1631896418.185 [CBIT](INFO): Clearing failed state for component RudderServo 2021-09-17T16:33:38.185Z,1631896418.185 [RudderServo] No Fault, FailCount= 1 2021-09-17T16:33:41.314Z,1631896421.314 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33 2021-09-17T16:33:44.538Z,1631896424.538 [Micromodem](INFO): Nmea in: $CATMG,2021-09-17T16:33:43.136359Z,RTC,RTC*55 2021-09-17T16:33:44.539Z,1631896424.539 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2021-09-17T16:33:43.136359Z,RTC,RTC*55 2021-09-17T16:33:50.689Z,1631896430.689 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error 2021-09-17T16:33:52.631Z,1631896432.631 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33 2021-09-17T16:33:53.398Z,1631896433.398 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31 2021-09-17T16:33:53.398Z,1631896433.398 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31 2021-09-17T16:33:53.802Z,1631896433.802 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33 2021-09-17T16:33:53.802Z,1631896433.802 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64 2021-09-17T16:33:54.206Z,1631896434.206 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66 2021-09-17T16:33:54.206Z,1631896434.206 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F 2021-09-17T16:33:54.634Z,1631896434.634 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D 2021-09-17T16:33:54.634Z,1631896434.634 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E 2021-09-17T16:33:55.018Z,1631896435.018 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C 2021-09-17T16:33:55.018Z,1631896435.018 [Micromodem](INFO): Nmea out: $CCCFG,FC0,14500*47 2021-09-17T16:33:55.418Z,1631896435.418 [Micromodem](INFO): Nmea in: $CACFG,FC0,14500*45 2021-09-17T16:33:55.418Z,1631896435.418 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63 2021-09-17T16:33:55.822Z,1631896435.822 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61 2021-09-17T16:33:55.822Z,1631896435.822 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A 2021-09-17T16:33:56.226Z,1631896436.226 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38 2021-09-17T16:33:56.227Z,1631896436.227 [Micromodem](INFO): Nmea out: $CCCLK,2021,09,17,16,33,57*4F 2021-09-17T16:33:56.642Z,1631896436.642 [Micromodem](INFO): Nmea in: $CACLK,2021,9,17,16,33,57*7D 2021-09-17T16:33:56.644Z,1631896436.644 [Micromodem](INFO): Nmea in: $CATMS,0,2021-09-17T16:33:58Z*72 2021-09-17T16:33:56.646Z,1631896436.646 [Micromodem](INFO): Nmea in: $CATMG,2021-09-17T16:33:58.027342Z,USER_CMD,RTC*15 2021-09-17T16:34:00.693Z,1631896440.693 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items 2021-09-17T16:34:03.114Z,1631896443.114 [NAL9602](INFO): Powering up NAL9602 2021-09-17T16:34:10.809Z,1631896450.809 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2021-09-17T16:34:10.809Z,1631896450.809 [RDI_Pathfinder] Communications Fault, FailCount= 1 2021-09-17T16:34:10.809Z,1631896450.809 [RDI_Pathfinder](ERROR): Communications Fault 2021-09-17T16:34:10.849Z,1631896450.849 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2021-09-17T16:34:11.244Z,1631896451.244 [RDI_Pathfinder](INFO): Powering down 2021-09-17T16:34:12.029Z,1631896452.029 [SBIT](IMPORTANT): Beginning Startup BIT 2021-09-17T16:34:12.037Z,1631896452.037 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2021-09-17T16:34:12.037Z,1631896452.037 [RDI_Pathfinder] No Fault, FailCount= 1 2021-09-17T16:34:12.038Z,1631896452.038 [CBIT](IMPORTANT): Beginning ground fault scan 2021-09-17T16:34:14.002Z,1631896454.002 [NAL9602](INFO): NAL9602 initialized 2021-09-17T16:34:23.081Z,1631896463.081 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.039272 CHAN A1 (24V): 0.043455 CHAN A2 (12V): 0.024977 CHAN A3 (5V): 0.009414 CHAN B0 (3.3V): 0.007202 CHAN B1 (3.15aV): 0.006725 CHAN B2 (3.15bV): 0.007014 CHAN B3 (GND): -0.002519 OPEN: 0.007097 Full Scale Calc: 4.765 mA, -1.589 mA 2021-09-17T16:34:25.729Z,1631896465.729 [NAL9602](INFO): SBD MO Status=0, MOMSN=25541, MT Status=0, MTMSN=0 2021-09-17T16:34:25.729Z,1631896465.729 [NAL9602](INFO): No messages in MT queue 2021-09-17T16:35:06.141Z,1631896506.141 [SBIT](IMPORTANT): SBIT PASSED 2021-09-17T16:35:06.142Z,1631896506.142 [SBIT](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2021-09-17T16:35:06.615Z,1631896506.615 [WorkSite](IMPORTANT): Reading workSite position from Data/workSite.cfg 2021-09-17T16:35:06.619Z,1631896506.619 [WorkSite](IMPORTANT): WorkSite fix at 20210917T163026: (40.964226, -71.231468) 2021-09-17T16:35:06.621Z,1631896506.621 [MissionManager](IMPORTANT): Started mission Startup 2021-09-17T16:35:06.621Z,1631896506.621 [Startup] Running Loop=1 2021-09-17T16:35:06.621Z,1631896506.621 [Startup](DEBUG): Aggregate::initialize Startup 2021-09-17T16:35:06.622Z,1631896506.622 [Startup:A.GoToSurface] Running Loop=1 2021-09-17T16:35:06.622Z,1631896506.622 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-09-17T16:35:06.622Z,1631896506.622 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-09-17T16:35:06.623Z,1631896506.623 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-09-17T16:35:06.623Z,1631896506.623 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-09-17T16:35:06.623Z,1631896506.623 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-09-17T16:35:06.624Z,1631896506.624 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-09-17T16:35:06.626Z,1631896506.626 [Startup:StartupSatComms] Running Loop=1 2021-09-17T16:35:06.626Z,1631896506.626 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2021-09-17T16:35:06.626Z,1631896506.626 [Startup:StartupSatComms:A] Running Loop=1 2021-09-17T16:35:06.978Z,1631896506.978 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2021-09-17T16:36:06.794Z,1631896566.794 [Startup:StartupSatComms:A](INFO): Timed out from 2021-09-17T16:35:06.6Z 2021-09-17T16:36:06.794Z,1631896566.794 [Startup:StartupSatComms:A] Stopped 2021-09-17T16:36:06.795Z,1631896566.795 [Startup:StartupSatComms:B] Running Loop=1 2021-09-17T16:36:07.205Z,1631896567.205 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2021-09-17T16:36:35.013Z,1631896595.013 [NAL9602](INFO): SBD MO Status=2, MOMSN=25542, MT Status=2, MTMSN=0 2021-09-17T16:36:35.014Z,1631896595.014 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-17T16:36:54.950Z,1631896614.950 [NAL9602](INFO): SBD MO Status=1, MOMSN=25542, MT Status=0, MTMSN=0 2021-09-17T16:36:55.072Z,1631896615.072 [NAL9602](INFO): Sent 18 bytes from file Logs/20210917T162349/Courier0006.lzma 2021-09-17T16:36:55.072Z,1631896615.072 [NAL9602](INFO): Packets left to send: 0 2021-09-17T16:37:06.889Z,1631896626.889 [Startup:StartupSatComms:B](INFO): Timed out from 2021-09-17T16:36:06.8Z 2021-09-17T16:37:06.889Z,1631896626.889 [Startup:StartupSatComms:B] Stopped 2021-09-17T16:37:06.889Z,1631896626.889 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2021-09-17T16:37:06.889Z,1631896626.889 [Startup:StartupSatComms] Stopped 2021-09-17T16:37:06.889Z,1631896626.889 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2021-09-17T16:37:06.890Z,1631896626.890 [Startup](INFO): Completed Startup 2021-09-17T16:37:06.890Z,1631896626.890 [MissionManager](INFO): Startup is completed. 2021-09-17T16:37:06.891Z,1631896626.891 [MissionManager](INFO): Uninitializing Mission Startup 2021-09-17T16:37:06.891Z,1631896626.891 [Startup] Stopped 2021-09-17T16:37:06.891Z,1631896626.891 [Startup](DEBUG): Aggregate::uninitialize Startup 2021-09-17T16:37:06.891Z,1631896626.891 [Startup:A.GoToSurface] Stopped 2021-09-17T16:37:06.891Z,1631896626.891 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-09-17T16:37:07.259Z,1631896627.259 [MissionManager](IMPORTANT): Started mission Default 2021-09-17T16:37:07.259Z,1631896627.259 [Default] Running Loop=1 2021-09-17T16:37:07.259Z,1631896627.259 [Default](DEBUG): Aggregate::initialize Default 2021-09-17T16:37:07.259Z,1631896627.259 [Default:B.GoToSurface] Running Loop=1 2021-09-17T16:37:07.259Z,1631896627.259 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-09-17T16:37:07.260Z,1631896627.260 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-09-17T16:37:07.260Z,1631896627.260 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-09-17T16:37:07.260Z,1631896627.260 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-09-17T16:37:07.261Z,1631896627.261 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-09-17T16:37:07.261Z,1631896627.261 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-09-17T16:37:07.261Z,1631896627.261 [Default:A.Wait] Running Loop=1 2021-09-17T16:37:07.262Z,1631896627.262 [Default:A.Wait](DEBUG): Initialize Wait Component. 2021-09-17T16:37:08.034Z,1631896628.034 [NAL9602](INFO): SBD MO Status=1, MOMSN=25543, MT Status=0, MTMSN=0 2021-09-17T16:37:08.084Z,1631896628.084 [NAL9602](INFO): Sent 184 bytes from file Logs/20210917T163323/Courier0000.lzma 2021-09-17T16:37:08.084Z,1631896628.084 [NAL9602](INFO): Packets left to send: 1 2021-09-17T16:37:20.620Z,1631896640.620 [Default:A.Wait](INFO): Done Waiting. 2021-09-17T16:37:20.620Z,1631896640.620 [Default:A.Wait] Stopped 2021-09-17T16:37:20.620Z,1631896640.620 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2021-09-17T16:37:20.979Z,1631896640.979 [Default:CheckIn] Running Loop=1 2021-09-17T16:37:20.979Z,1631896640.979 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-17T16:37:20.979Z,1631896640.979 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-17T16:37:21.385Z,1631896641.385 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2021-09-17T16:40:54.680Z,1631896854.680 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164055.00,A,4057.92323,N,07114.08353,W,1.011,188.16,170921,,,A*75 2021-09-17T16:40:54.683Z,1631896854.683 [NAL9602](INFO): GPS fix at 20210917T164055: (40.965387, -71.234725) 2021-09-17T16:40:54.762Z,1631896854.762 [Default:CheckIn:Read_GPS] Stopped 2021-09-17T16:40:54.762Z,1631896854.762 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-17T16:40:55.129Z,1631896855.129 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2021-09-17T16:41:13.817Z,1631896873.817 [NAL9602](INFO): SBD MO Status=1, MOMSN=25544, MT Status=0, MTMSN=0 2021-09-17T16:41:13.865Z,1631896873.865 [NAL9602](INFO): Sent 140 bytes from file Logs/20210917T163323/Courier0000.lzma 2021-09-17T16:41:13.865Z,1631896873.865 [NAL9602](INFO): Packets left to send: 0 2021-09-17T16:41:20.231Z,1631896880.231 [NAL9602](INFO): SBD MO Status=1, MOMSN=25545, MT Status=0, MTMSN=0 2021-09-17T16:41:20.292Z,1631896880.292 [NAL9602](INFO): Sent 72 bytes from file Logs/20210917T163323/Courier0004.lzma 2021-09-17T16:41:20.292Z,1631896880.292 [NAL9602](INFO): Packets left to send: 0 2021-09-17T16:41:29.448Z,1631896889.448 [NAL9602](INFO): SBD MO Status=1, MOMSN=25546, MT Status=0, MTMSN=0 2021-09-17T16:41:29.496Z,1631896889.496 [NAL9602](INFO): Sent 18 bytes from file Logs/20210917T162349/Express0007.lzma 2021-09-17T16:41:29.496Z,1631896889.496 [NAL9602](INFO): Packets left to send: 0 2021-09-17T16:41:39.236Z,1631896899.236 [NAL9602](INFO): SBD MO Status=1, MOMSN=25547, MT Status=0, MTMSN=0 2021-09-17T16:41:39.292Z,1631896899.292 [NAL9602](INFO): Sent 184 bytes from file Logs/20210917T163323/Express0001.lzma 2021-09-17T16:41:39.292Z,1631896899.292 [NAL9602](INFO): Packets left to send: 5 2021-09-17T16:41:51.151Z,1631896911.151 [NAL9602](INFO): SBD MO Status=1, MOMSN=25548, MT Status=0, MTMSN=0 2021-09-17T16:41:51.196Z,1631896911.196 [NAL9602](INFO): Sent 184 bytes from file Logs/20210917T163323/Express0001.lzma 2021-09-17T16:41:51.196Z,1631896911.196 [NAL9602](INFO): Packets left to send: 4 2021-09-17T16:42:02.620Z,1631896922.620 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2021-09-17T16:42:02.640Z,1631896922.640 [BPC1](INFO): Received data from all battery sticks. 2021-09-17T16:42:03.417Z,1631896923.417 [NAL9602](INFO): SBD MO Status=1, MOMSN=25549, MT Status=0, MTMSN=0 2021-09-17T16:42:03.474Z,1631896923.474 [NAL9602](INFO): Sent 184 bytes from file Logs/20210917T163323/Express0001.lzma 2021-09-17T16:42:03.474Z,1631896923.474 [NAL9602](INFO): Packets left to send: 3 2021-09-17T16:42:13.353Z,1631896933.353 [NAL9602](INFO): SBD MO Status=1, MOMSN=25550, MT Status=0, MTMSN=0 2021-09-17T16:42:13.400Z,1631896933.400 [NAL9602](INFO): Sent 184 bytes from file Logs/20210917T163323/Express0001.lzma 2021-09-17T16:42:13.400Z,1631896933.400 [NAL9602](INFO): Packets left to send: 2 2021-09-17T16:42:21.676Z,1631896941.676 [NAL9602](INFO): SBD MO Status=1, MOMSN=25551, MT Status=0, MTMSN=0 2021-09-17T16:42:21.732Z,1631896941.732 [NAL9602](INFO): Sent 184 bytes from file Logs/20210917T163323/Express0001.lzma 2021-09-17T16:42:21.732Z,1631896941.732 [NAL9602](INFO): Packets left to send: 1 2021-09-17T16:42:31.276Z,1631896951.276 [NAL9602](INFO): SBD MO Status=1, MOMSN=25552, MT Status=0, MTMSN=0 2021-09-17T16:42:31.332Z,1631896951.332 [NAL9602](INFO): Sent 100 bytes from file Logs/20210917T163323/Express0001.lzma 2021-09-17T16:42:31.332Z,1631896951.332 [NAL9602](INFO): Packets left to send: 0 2021-09-17T16:42:38.333Z,1631896958.333 [NAL9602](INFO): SBD MO Status=1, MOMSN=25553, MT Status=0, MTMSN=0 2021-09-17T16:42:38.385Z,1631896958.385 [NAL9602](INFO): Sent 95 bytes from file Logs/20210917T163323/Express0005.lzma 2021-09-17T16:42:38.385Z,1631896958.385 [NAL9602](INFO): Packets left to send: 0 2021-09-17T16:42:46.651Z,1631896966.651 [NAL9602](INFO): SBD MO Status=0, MOMSN=25554, MT Status=0, MTMSN=0 2021-09-17T16:42:46.774Z,1631896966.774 [Default:CheckIn:Read_Iridium] Stopped 2021-09-17T16:42:46.774Z,1631896966.774 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-17T16:42:46.774Z,1631896966.774 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-17T16:43:17.358Z,1631896997.358 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-17T16:44:24.477Z,1631897064.477 [RDI_Pathfinder](ERROR): only read 1 of 4 data items 2021-09-17T16:44:57.151Z,1631897097.151 [Micromodem](INFO): Nmea in: $CATRC,RECV,COP , 213,COPROC_par_read_parobj: size error 2021-09-17T16:44:57.151Z,1631897097.151 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CATRC,RECV,COP , 213,COPROC_par_read_parobj: size error expected 41 2021-09-17T16:44:57.153Z,1631897097.153 [Micromodem](INFO): Nmea in: $CAMSG,Bad Modulation Header,0*31 2021-09-17T16:44:57.551Z,1631897097.551 [Micromodem](INFO): Nmea in: $CACST,6,1,20210917164458.029365,06,822,23,0100,0150,149,02,02,01,02,-1,-01,-01,1,3,1,0,150,-100.0,0.44,-100,2.56,-01,-0.79,-2147483648,14500,4000*5C 2021-09-17T16:47:47.243Z,1631897267.243 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-17T16:47:47.243Z,1631897267.243 [Default:CheckIn:C.Wait] Stopped 2021-09-17T16:47:47.243Z,1631897267.243 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-17T16:47:47.243Z,1631897267.243 [Default:CheckIn:D] Running Loop=1 2021-09-17T16:47:47.653Z,1631897267.653 [Default:CheckIn:D] Stopped 2021-09-17T16:47:47.653Z,1631897267.653 [Default:CheckIn:E] Running Loop=1 2021-09-17T16:47:48.060Z,1631897268.060 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.673236 min 2021-09-17T16:47:48.060Z,1631897268.060 [Default:CheckIn:E] Stopped 2021-09-17T16:47:48.060Z,1631897268.060 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-17T16:47:48.060Z,1631897268.060 [Default:CheckIn] Stopped 2021-09-17T16:47:48.060Z,1631897268.060 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-17T16:47:48.061Z,1631897268.061 [Default:CheckIn](INFO): Running loop #2 2021-09-17T16:47:48.061Z,1631897268.061 [Default:CheckIn] Running Loop=2 2021-09-17T16:47:48.061Z,1631897268.061 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-17T16:47:48.061Z,1631897268.061 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-17T16:47:50.060Z,1631897270.060 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164750.00,A,4057.98296,N,07114.19883,W,1.555,320.41,170921,,,D*76 2021-09-17T16:47:50.062Z,1631897270.062 [NAL9602](INFO): GPS fix at 20210917T164750: (40.966383, -71.236647) 2021-09-17T16:47:50.104Z,1631897270.104 [Default:CheckIn:Read_GPS] Stopped 2021-09-17T16:47:50.104Z,1631897270.104 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-17T16:48:06.768Z,1631897286.768 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=25555, MT Status=1, MTMSN=904 2021-09-17T16:48:06.816Z,1631897286.816 [NAL9602](INFO): Sent 184 bytes from file Logs/20210917T163323/Courier0007.lzma 2021-09-17T16:48:06.816Z,1631897286.816 [NAL9602](INFO): Packets left to send: 1 2021-09-17T16:48:07.345Z,1631897287.345 [NAL9602](INFO): Received command:sched asap "restart sys" 4iei2 1 2 2021-09-17T16:48:07.357Z,1631897287.357 [CommandLine](IMPORTANT): got command schedule asap "restart sys" 4iei2 1 2.000000 2021-09-17T16:48:07.358Z,1631897287.358 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=4iei2 2021-09-17T16:48:07.359Z,1631897287.359 [CommandLine](IMPORTANT): Scheduled #1 (#1 of 2 with id='4iei2'): "restart sys" ASAP 2021-09-17T16:48:22.736Z,1631897302.736 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=25556, MT Status=1, MTMSN=905 2021-09-17T16:48:22.784Z,1631897302.784 [NAL9602](INFO): Sent 17 bytes from file Logs/20210917T163323/Courier0007.lzma 2021-09-17T16:48:22.784Z,1631897302.784 [NAL9602](INFO): Packets left to send: 0 2021-09-17T16:48:23.304Z,1631897303.304 [NAL9602](INFO): Received command:sched asap "" 4iei2 2 2 2021-09-17T16:48:23.321Z,1631897303.321 [CommandLine](IMPORTANT): got command schedule asap "" 4iei2 2 2.000000 2021-09-17T16:48:23.321Z,1631897303.321 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=4iei2 2021-09-17T16:48:23.322Z,1631897303.322 [CommandLine](IMPORTANT): Scheduled #2 (#2 of 2 with id='4iei2'): "" ASAP 2021-09-17T16:48:23.433Z,1631897303.433 [CommandLine](IMPORTANT): got command restart system 2021-09-17T16:48:25.576Z,1631897305.576 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-17T16:48:25.576Z,1631897305.576 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:25.592Z,1631897305.592 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2021-09-17T16:48:25.592Z,1631897305.592 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:25.593Z,1631897305.593 [CommandLine](INFO): Join timeout helper Thread ID is 983 2021-09-17T16:48:25.608Z,1631897305.608 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2021-09-17T16:48:25.608Z,1631897305.608 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:25.608Z,1631897305.608 [NavChartDb](INFO): Join timeout helper Thread ID is 984 2021-09-17T16:48:25.700Z,1631897305.700 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-17T16:48:25.700Z,1631897305.700 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:25.712Z,1631897305.712 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2021-09-17T16:48:25.712Z,1631897305.712 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:25.712Z,1631897305.712 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 985 2021-09-17T16:48:25.732Z,1631897305.732 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-17T16:48:25.732Z,1631897305.732 [WetLabsSeaOWL_UV_A](INFO): Powering down 2021-09-17T16:48:25.733Z,1631897305.733 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:25.752Z,1631897305.752 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2021-09-17T16:48:25.752Z,1631897305.752 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:25.752Z,1631897305.752 [CTD_Seabird](INFO): Join timeout helper Thread ID is 986 2021-09-17T16:48:26.240Z,1631897306.240 [CTD_Seabird](INFO): Powering down 2021-09-17T16:48:26.252Z,1631897306.252 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-17T16:48:26.252Z,1631897306.252 [CTD_Seabird](INFO): Powering down 2021-09-17T16:48:26.264Z,1631897306.264 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:26.264Z,1631897306.264 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2021-09-17T16:48:26.264Z,1631897306.264 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-09-17T16:48:26.265Z,1631897306.265 [Radio_Surface](INFO): Join timeout helper Thread ID is 987 2021-09-17T16:48:26.529Z,1631897306.529 [Radio_Surface](INFO): Powering down 2021-09-17T16:48:26.532Z,1631897306.532 [Radio_Sur