2023-04-14T23:59:03.369Z,1681516743.369 [Supervisor](DEBUG): Initializing supervisor. 2023-04-14T23:59:03.373Z,1681516743.373 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2023-04-14T23:59:03.374Z,1681516743.374 [SyncHandler](INFO): Protected caller Thread ID is 1411 2023-04-14T23:59:03.374Z,1681516743.374 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2023-04-14T23:59:03.375Z,1681516743.375 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2023-04-14T23:59:03.376Z,1681516743.376 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1412 2023-04-14T23:59:03.380Z,1681516743.380 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2023-04-14T23:59:03.397Z,1681516743.397 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2023-04-14T23:59:03.398Z,1681516743.398 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2023-04-14T23:59:03.398Z,1681516743.398 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 1413 2023-04-14T23:59:03.403Z,1681516743.403 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2023-04-14T23:59:03.404Z,1681516743.404 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2023-04-14T23:59:03.404Z,1681516743.404 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1414 2023-04-14T23:59:03.406Z,1681516743.406 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2023-04-14T23:59:03.407Z,1681516743.407 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2023-04-14T23:59:03.407Z,1681516743.407 [logger ThreadHandler](INFO): Protected caller Thread ID is 1415 2023-04-14T23:59:03.411Z,1681516743.411 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2023-04-14T23:59:03.411Z,1681516743.411 [Supervisor](INFO): Looking for Config files in directory: Config/ 2023-04-14T23:59:03.413Z,1681516743.413 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2023-04-14T23:59:03.507Z,1681516743.507 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2023-04-14T23:59:03.508Z,1681516743.508 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2023-04-14T23:59:03.717Z,1681516743.717 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2023-04-14T23:59:03.717Z,1681516743.717 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2023-04-14T23:59:03.962Z,1681516743.962 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2023-04-14T23:59:03.963Z,1681516743.963 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2023-04-14T23:59:04.068Z,1681516744.068 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2023-04-14T23:59:04.069Z,1681516744.069 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2023-04-14T23:59:04.726Z,1681516744.726 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2023-04-14T23:59:04.727Z,1681516744.727 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2023-04-14T23:59:05.187Z,1681516745.187 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2023-04-14T23:59:05.188Z,1681516745.188 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2023-04-14T23:59:05.654Z,1681516745.654 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2023-04-14T23:59:05.655Z,1681516745.655 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2023-04-14T23:59:06.038Z,1681516746.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2023-04-14T23:59:06.039Z,1681516746.039 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2023-04-14T23:59:06.352Z,1681516746.352 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2023-04-14T23:59:06.352Z,1681516746.352 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2023-04-14T23:59:06.708Z,1681516746.708 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2023-04-14T23:59:06.709Z,1681516746.709 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2023-04-14T23:59:06.925Z,1681516746.925 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2023-04-14T23:59:06.926Z,1681516746.926 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2023-04-14T23:59:07.062Z,1681516747.062 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2023-04-14T23:59:07.062Z,1681516747.062 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2023-04-14T23:59:07.142Z,1681516747.142 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2023-04-14T23:59:07.221Z,1681516747.221 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2023-04-14T23:59:07.404Z,1681516747.404 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2023-04-14T23:59:07.405Z,1681516747.405 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2023-04-14T23:59:07.625Z,1681516747.625 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2023-04-14T23:59:07.627Z,1681516747.627 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/ 2023-04-14T23:59:07.628Z,1681516747.628 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg 2023-04-14T23:59:07.710Z,1681516747.710 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg 2023-04-14T23:59:08.410Z,1681516748.410 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2023-04-14T23:59:08.410Z,1681516748.410 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg 2023-04-14T23:59:08.709Z,1681516748.709 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg 2023-04-14T23:59:08.941Z,1681516748.941 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg 2023-04-14T23:59:09.112Z,1681516749.112 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg 2023-04-14T23:59:09.195Z,1681516749.195 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg 2023-04-14T23:59:09.302Z,1681516749.302 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg 2023-04-14T23:59:09.403Z,1681516749.403 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg 2023-04-14T23:59:09.553Z,1681516749.553 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg 2023-04-14T23:59:09.647Z,1681516749.647 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg 2023-04-14T23:59:09.742Z,1681516749.742 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2023-04-14T23:59:09.758Z,1681516749.758 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2023-04-14T23:59:09.904Z,1681516749.904 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2023-04-14T23:59:09.905Z,1681516749.905 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2023-04-14T23:59:10.061Z,1681516750.061 [BuoyancyServo] Loaded 2023-04-14T23:59:10.061Z,1681516750.061 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2023-04-14T23:59:10.082Z,1681516750.082 [ElevatorServo] Loaded 2023-04-14T23:59:10.082Z,1681516750.082 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2023-04-14T23:59:10.102Z,1681516750.102 [MassServo] Loaded 2023-04-14T23:59:10.103Z,1681516750.103 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2023-04-14T23:59:10.123Z,1681516750.123 [RudderServo] Loaded 2023-04-14T23:59:10.123Z,1681516750.123 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2023-04-14T23:59:10.138Z,1681516750.138 [ThrusterHE] Loaded 2023-04-14T23:59:10.138Z,1681516750.138 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread. 2023-04-14T23:59:10.139Z,1681516750.139 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2023-04-14T23:59:10.139Z,1681516750.139 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2023-04-14T23:59:10.281Z,1681516750.281 [SBIT](DEBUG): Construct Startup Built In Test. 2023-04-14T23:59:10.296Z,1681516750.296 [SBIT] Loaded 2023-04-14T23:59:10.297Z,1681516750.297 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2023-04-14T23:59:10.299Z,1681516750.299 [IBIT](DEBUG): Construct Initiated Built In Test. 2023-04-14T23:59:10.320Z,1681516750.320 [IBIT] Loaded 2023-04-14T23:59:10.320Z,1681516750.320 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2023-04-14T23:59:10.326Z,1681516750.326 [CBIT](DEBUG): Construct Continuous Built In Test. 2023-04-14T23:59:10.541Z,1681516750.541 [CBIT] Loaded 2023-04-14T23:59:10.542Z,1681516750.542 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2023-04-14T23:59:10.542Z,1681516750.542 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2023-04-14T23:59:10.543Z,1681516750.543 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2023-04-14T23:59:10.707Z,1681516750.707 [CTD_Seabird] Loaded 2023-04-14T23:59:10.707Z,1681516750.707 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2023-04-14T23:59:10.708Z,1681516750.708 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 406644E0 2023-04-14T23:59:10.709Z,1681516750.709 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1497 2023-04-14T23:59:10.740Z,1681516750.740 [ESPComponent] Loaded 2023-04-14T23:59:10.741Z,1681516750.741 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2023-04-14T23:59:10.760Z,1681516750.760 [PAR_Licor] Loaded 2023-04-14T23:59:10.760Z,1681516750.760 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2023-04-14T23:59:10.790Z,1681516750.790 [WetLabsBB2FL] Loaded 2023-04-14T23:59:10.791Z,1681516750.791 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2023-04-14T23:59:10.792Z,1681516750.792 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 406944E0 2023-04-14T23:59:10.792Z,1681516750.792 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1498 2023-04-14T23:59:10.793Z,1681516750.793 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2023-04-14T23:59:10.793Z,1681516750.793 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2023-04-14T23:59:10.843Z,1681516750.843 [DepthRateCalculator] Loaded 2023-04-14T23:59:10.843Z,1681516750.843 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2023-04-14T23:59:10.849Z,1681516750.849 [PitchRateCalculator] Loaded 2023-04-14T23:59:10.849Z,1681516750.849 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2023-04-14T23:59:10.859Z,1681516750.859 [SpeedCalculator] Loaded 2023-04-14T23:59:10.859Z,1681516750.859 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2023-04-14T23:59:10.874Z,1681516750.874 [VerticalHomogeneityIndexCalculator] Loaded 2023-04-14T23:59:10.874Z,1681516750.874 [ComponentRegistry](DEBUG): SyncComponent "VerticalHomogeneityIndexCalculator" handled in the control thread. 2023-04-14T23:59:10.878Z,1681516750.878 [YawRateCalculator] Loaded 2023-04-14T23:59:10.879Z,1681516750.879 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2023-04-14T23:59:10.898Z,1681516750.898 [ElevatorOffsetCalculator] Loaded 2023-04-14T23:59:10.898Z,1681516750.898 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2023-04-14T23:59:10.898Z,1681516750.898 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2023-04-14T23:59:10.899Z,1681516750.899 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2023-04-14T23:59:10.997Z,1681516750.997 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2023-04-14T23:59:10.998Z,1681516750.998 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2023-04-14T23:59:11.024Z,1681516751.024 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2023-04-14T23:59:11.025Z,1681516751.025 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2023-04-14T23:59:11.136Z,1681516751.136 [DeadReckonUsingMultipleVelocitySources] Loaded 2023-04-14T23:59:11.136Z,1681516751.136 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2023-04-14T23:59:11.150Z,1681516751.150 [NavChart] Loaded 2023-04-14T23:59:11.150Z,1681516751.150 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2023-04-14T23:59:11.156Z,1681516751.156 [UniversalFixResidualReporter] Loaded 2023-04-14T23:59:11.156Z,1681516751.156 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2023-04-14T23:59:11.157Z,1681516751.157 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2023-04-14T23:59:11.157Z,1681516751.157 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2023-04-14T23:59:11.573Z,1681516751.573 [AHRS_M2] Loaded 2023-04-14T23:59:11.573Z,1681516751.573 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2023-04-14T23:59:11.607Z,1681516751.607 [BackseatComponent] Loaded 2023-04-14T23:59:11.607Z,1681516751.607 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread. 2023-04-14T23:59:11.608Z,1681516751.608 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A244E0 2023-04-14T23:59:11.609Z,1681516751.609 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 1499 2023-04-14T23:59:11.612Z,1681516751.612 [LcmUniversalReporter] Loaded 2023-04-14T23:59:11.612Z,1681516751.612 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread. 2023-04-14T23:59:12.343Z,1681516752.343 [BPC1] Loaded 2023-04-14T23:59:12.343Z,1681516752.343 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2023-04-14T23:59:12.416Z,1681516752.416 [DataOverHttps] Loaded 2023-04-14T23:59:12.417Z,1681516752.417 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2023-04-14T23:59:12.418Z,1681516752.418 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40A544E0 2023-04-14T23:59:12.418Z,1681516752.418 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1500 2023-04-14T23:59:12.439Z,1681516752.439 [Depth_Keller] Loaded 2023-04-14T23:59:12.439Z,1681516752.439 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2023-04-14T23:59:12.444Z,1681516752.444 [DropWeight] Loaded 2023-04-14T23:59:12.444Z,1681516752.444 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2023-04-14T23:59:12.482Z,1681516752.482 [DVL_micro] Loaded 2023-04-14T23:59:12.483Z,1681516752.483 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2023-04-14T23:59:12.542Z,1681516752.542 [NAL9602] Loaded 2023-04-14T23:59:12.543Z,1681516752.543 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2023-04-14T23:59:12.570Z,1681516752.570 [Onboard] Loaded 2023-04-14T23:59:12.570Z,1681516752.570 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2023-04-14T23:59:12.571Z,1681516752.571 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40A844E0 2023-04-14T23:59:12.571Z,1681516752.571 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 1501 2023-04-14T23:59:12.583Z,1681516752.583 [Power24vConverter] Loaded 2023-04-14T23:59:12.584Z,1681516752.584 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2023-04-14T23:59:12.597Z,1681516752.597 [Radio_Surface] Loaded 2023-04-14T23:59:12.597Z,1681516752.597 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2023-04-14T23:59:12.598Z,1681516752.598 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40AB44E0 2023-04-14T23:59:12.598Z,1681516752.598 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1502 2023-04-14T23:59:12.691Z,1681516752.691 [DAT] Loaded 2023-04-14T23:59:12.692Z,1681516752.692 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread. 2023-04-14T23:59:12.693Z,1681516752.693 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40AE44E0 2023-04-14T23:59:12.693Z,1681516752.693 [DAT ThreadHandler](INFO): Protected caller Thread ID is 1503 2023-04-14T23:59:12.694Z,1681516752.694 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2023-04-14T23:59:12.694Z,1681516752.694 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2023-04-14T23:59:12.865Z,1681516752.865 [StratificationFrontDetector](IMPORTANT): thresholdVTHI set to: 0.050012 degC 2023-04-14T23:59:12.865Z,1681516752.865 [StratificationFrontDetector](INFO): (re)initializing 2023-04-14T23:59:12.865Z,1681516752.865 [StratificationFrontDetector] Loaded 2023-04-14T23:59:12.865Z,1681516752.865 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread. 2023-04-14T23:59:12.866Z,1681516752.866 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2023-04-14T23:59:12.867Z,1681516752.867 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2023-04-14T23:59:12.958Z,1681516752.958 [VerticalControl](DEBUG): Construct VerticalControl. 2023-04-14T23:59:13.009Z,1681516753.009 [VerticalControl] Loaded 2023-04-14T23:59:13.010Z,1681516753.010 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2023-04-14T23:59:13.013Z,1681516753.013 [HorizontalControl](DEBUG): Construct HorizontalControl. 2023-04-14T23:59:13.090Z,1681516753.090 [HorizontalControl] Loaded 2023-04-14T23:59:13.090Z,1681516753.090 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2023-04-14T23:59:13.092Z,1681516753.092 [SpeedControl](DEBUG): Construct SpeedControl. 2023-04-14T23:59:13.094Z,1681516753.094 [SpeedControl] Loaded 2023-04-14T23:59:13.094Z,1681516753.094 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2023-04-14T23:59:13.097Z,1681516753.097 [LoopControl](DEBUG): Construct LoopControl. 2023-04-14T23:59:13.098Z,1681516753.098 [LoopControl] Loaded 2023-04-14T23:59:13.098Z,1681516753.098 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2023-04-14T23:59:13.098Z,1681516753.098 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2023-04-14T23:59:13.099Z,1681516753.099 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2023-04-14T23:59:13.124Z,1681516753.124 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2023-04-14T23:59:13.125Z,1681516753.125 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2023-04-14T23:59:13.432Z,1681516753.432 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2023-04-14T23:59:13.438Z,1681516753.438 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2023-04-14T23:59:13.441Z,1681516753.441 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2023-04-14T23:59:13.452Z,1681516753.452 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2023-04-14T23:59:13.453Z,1681516753.453 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BDE4E0 2023-04-14T23:59:13.454Z,1681516753.454 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1504 2023-04-14T23:59:13.458Z,1681516753.458 [Supervisor](INFO): Main Thread ID is 1034 2023-04-14T23:59:13.458Z,1681516753.458 [Supervisor](DEBUG): Running supervisor. 2023-04-14T23:59:13.459Z,1681516753.459 [CommandExec ThreadHandler](INFO): Handler Thread ID is 1505 2023-04-14T23:59:13.460Z,1681516753.460 [CommandExec](INFO): Initializing the command executive. 2023-04-14T23:59:13.461Z,1681516753.461 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1506 2023-04-14T23:59:13.463Z,1681516753.463 [controlThread ThreadHandler](INFO): Handler Thread ID is 1507 2023-04-14T23:59:13.463Z,1681516753.463 [controlThread](DEBUG): Initializing ControlThread 2023-04-14T23:59:13.465Z,1681516753.465 [SBIT](INFO): Initialize SBIT Component. 2023-04-14T23:59:13.466Z,1681516753.466 [SBIT](IMPORTANT): git: 2023-04-14_A 2023-04-14T23:59:13.466Z,1681516753.466 [SBIT](INFO): git hash: a5e7240676c499658609ad29f2edbd696bbbdf6d 2023-04-14T23:59:13.466Z,1681516753.466 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2023-04-14T23:59:13.468Z,1681516753.468 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021 2023-04-14T23:59:13.469Z,1681516753.469 [SBIT](INFO): Beginning SBIT in 79.000000 seconds. 2023-04-14T23:59:13.469Z,1681516753.469 [IBIT](INFO): Initialize IBIT Component. 2023-04-14T23:59:13.470Z,1681516753.470 [CBIT](DEBUG): Initialize CBIT Component. 2023-04-14T23:59:13.471Z,1681516753.471 [logger ThreadHandler](INFO): Handler Thread ID is 1508 2023-04-14T23:59:13.484Z,1681516753.484 [CBIT](DEBUG): Initialized mux pins. 2023-04-14T23:59:13.484Z,1681516753.484 [CBIT](DEBUG): Initializing the watchdog timer. 2023-04-14T23:59:13.496Z,1681516753.496 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1509 2023-04-14T23:59:13.497Z,1681516753.497 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2023-04-14T23:59:13.501Z,1681516753.501 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1511 2023-04-14T23:59:13.504Z,1681516753.504 [WetLabsBB2FL](INFO): Powering up 2023-04-14T23:59:13.505Z,1681516753.505 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 1513 2023-04-14T23:59:13.508Z,1681516753.508 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2023-04-14T23:59:13.508Z,1681516753.508 [CBIT](DEBUG): Initializing heartbeat. 2023-04-14T23:59:13.523Z,1681516753.523 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1514 2023-04-14T23:59:13.524Z,1681516753.524 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2023-04-14T23:59:13.536Z,1681516753.536 [Onboard ThreadHandler](INFO): Handler Thread ID is 1515 2023-04-14T23:59:13.553Z,1681516753.553 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1516 2023-04-14T23:59:13.576Z,1681516753.576 [DAT ThreadHandler](INFO): Handler Thread ID is 1517 2023-04-14T23:59:13.577Z,1681516753.577 [DAT](INFO): Powering up 2023-04-14T23:59:13.577Z,1681516753.577 [DAT](DEBUG): Initializing DAT. 2023-04-14T23:59:13.580Z,1681516753.580 [CBIT](DEBUG): Deactivating GF circuits. 2023-04-14T23:59:13.580Z,1681516753.580 [CBIT](DEBUG): Deactivating emergency mode. 2023-04-14T23:59:13.581Z,1681516753.581 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1519 2023-04-14T23:59:13.584Z,1681516753.584 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2023-04-14T23:59:13.584Z,1681516753.584 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2023-04-14T23:59:13.584Z,1681516753.584 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2023-04-14T23:59:13.584Z,1681516753.584 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2023-04-14T23:59:13.585Z,1681516753.585 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2023-04-14T23:59:13.585Z,1681516753.585 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2023-04-14T23:59:13.585Z,1681516753.585 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2023-04-14T23:59:13.585Z,1681516753.585 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2023-04-14T23:59:13.585Z,1681516753.585 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000 2023-04-14T23:59:13.585Z,1681516753.585 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000 2023-04-14T23:59:13.620Z,1681516753.620 [CBIT](DEBUG): Backplane powered. 2023-04-14T23:59:13.624Z,1681516753.624 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2023-04-14T23:59:13.624Z,1681516753.624 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2023-04-14T23:59:13.625Z,1681516753.625 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2023-04-14T23:59:13.625Z,1681516753.625 [VerticalHomogeneityIndexCalculator](DEBUG): (re)initializing 2023-04-14T23:59:13.626Z,1681516753.626 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2023-04-14T23:59:13.626Z,1681516753.626 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2023-04-14T23:59:13.627Z,1681516753.627 [NavChart](DEBUG): Initialize NavChart Navigation. 2023-04-14T23:59:13.628Z,1681516753.628 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2023-04-14T23:59:13.638Z,1681516753.638 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2023-04-14T23:59:13.648Z,1681516753.648 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2023-04-14T23:59:13.649Z,1681516753.649 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2023-04-14T23:59:13.649Z,1681516753.649 [LoopControl](DEBUG): Initialize LoopControlComponent. 2023-04-14T23:59:13.650Z,1681516753.650 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml 2023-04-14T23:59:13.696Z,1681516753.696 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2023-04-14T23:59:13.729Z,1681516753.729 [MissionManager](DEBUG): 2023-04-14T23:59:13.729Z,1681516753.729 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml 2023-04-14T23:59:13.815Z,1681516753.815 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2023-04-14T23:59:13.825Z,1681516753.825 [Default:A.Wait](DEBUG): Construct Wait. 2023-04-14T23:59:13.827Z,1681516753.827 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2023-04-14T23:59:13.876Z,1681516753.876 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2023-04-14T23:59:13.879Z,1681516753.879 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2023-04-14T23:59:13.901Z,1681516753.901 [Default:E.Execute](DEBUG): Construct Execute. 2023-04-14T23:59:13.904Z,1681516753.904 [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 2023-04-14T23:59:13.909Z,1681516753.909 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2023-04-14T23:59:13.953Z,1681516753.953 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2023-04-14T23:59:13.960Z,1681516753.960 [Radio_Surface](INFO): Powering up 2023-04-14T23:59:14.029Z,1681516754.029 [Depth_Keller](ERROR): Pressure or depth reading out of range: 1895.444336 decibar, 0.000000 m 2023-04-14T23:59:14.037Z,1681516754.037 [Power24vConverter](INFO): Powering up. 2023-04-14T23:59:14.053Z,1681516754.053 [DepthRateCalculator](ERROR): Depth measurement is not active 2023-04-14T23:59:14.066Z,1681516754.066 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2023-04-14T23:59:14.072Z,1681516754.072 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2023-04-14T23:59:14.073Z,1681516754.073 [ElevatorServo](DEBUG): Initializing EZServoServo. 2023-04-14T23:59:14.081Z,1681516754.081 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2023-04-14T23:59:14.082Z,1681516754.082 [MassServo](DEBUG): Initializing EZServoServo. 2023-04-14T23:59:14.088Z,1681516754.088 [MassServo](DEBUG): Initializing MassServo. 2023-04-14T23:59:14.089Z,1681516754.089 [RudderServo](DEBUG): Initializing EZServoServo. 2023-04-14T23:59:14.096Z,1681516754.096 [RudderServo](DEBUG): Initializing RudderServo. 2023-04-14T23:59:14.097Z,1681516754.097 [ThrusterHE](DEBUG): Initializing EZServoServo. 2023-04-14T23:59:14.104Z,1681516754.104 [ThrusterHE](DEBUG): Initializing ThrusterHE. 2023-04-14T23:59:15.612Z,1681516755.612 [WetLabsBB2FL](INFO): Powering down 2023-04-14T23:59:19.673Z,1681516759.673 [ThrusterHE](ERROR): Zero Speed Commanded. 2023-04-14T23:59:20.528Z,1681516760.528 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit. 2023-04-14T23:59:25.420Z,1681516765.420 [DAT](INFO): DAT read: 2023-04-14T23:59:25.422Z,1681516765.422 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2023-04-14T23:59:26.933Z,1681516766.933 [DAT](INFO): DAT read: MF Frequency Band 2023-04-14T23:59:26.934Z,1681516766.934 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0 2023-04-14T23:59:26.935Z,1681516766.935 [DAT](INFO): DAT read: Apr 14 2023 23:59:21 2023-04-14T23:59:27.941Z,1681516767.941 [DAT](INFO): DAT read: Features enabled [Bearing] 2023-04-14T23:59:27.942Z,1681516767.942 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC 2023-04-14T23:59:27.942Z,1681516767.942 [DAT](INFO): commRate: 1200 2023-04-14T23:59:30.008Z,1681516770.008 [DAT](INFO): entering command mode 2023-04-14T23:59:30.208Z,1681516770.208 [DAT](INFO): DAT read: 2023-04-14T23:59:30.209Z,1681516770.209 [DAT](INFO): DAT read: user:1 2023-04-14T23:59:30.209Z,1681516770.209 [DAT](INFO): setting verbose to 3 2023-04-14T23:59:30.460Z,1681516770.460 [DAT](INFO): DAT read: user:1> 2023-04-14T23:59:30.462Z,1681516770.462 [DAT](INFO): DAT read: Verbose | 3 2023-04-14T23:59:30.462Z,1681516770.462 [DAT](INFO): set verbose to 3 2023-04-14T23:59:30.462Z,1681516770.462 [DAT](INFO): setting DatVerbose to 27440 2023-04-14T23:59:30.712Z,1681516770.712 [DAT](INFO): DAT read: user:2> 2023-04-14T23:59:30.713Z,1681516770.713 [DAT](INFO): DAT read: DatVerbose | 27440 2023-04-14T23:59:30.714Z,1681516770.714 [DAT](INFO): set DatVerbose to 27440 2023-04-14T23:59:30.714Z,1681516770.714 [DAT](INFO): setting transmit power to 8 2023-04-14T23:59:30.965Z,1681516770.965 [DAT](INFO): DAT read: user:3> 2023-04-14T23:59:30.965Z,1681516770.965 [DAT](INFO): DAT read: TxPower | 8 (Max) 2023-04-14T23:59:30.966Z,1681516770.966 [DAT](INFO): set transmit power to 8 2023-04-14T23:59:30.966Z,1681516770.966 [DAT](INFO): setting local address to 4 2023-04-14T23:59:31.216Z,1681516771.216 [DAT](INFO): DAT read: user:4> 2023-04-14T23:59:31.217Z,1681516771.217 [DAT](INFO): DAT read: LocalAddr | 4 2023-04-14T23:59:31.218Z,1681516771.218 [DAT](INFO): set local address to 4 2023-04-14T23:59:31.219Z,1681516771.219 [DAT](INFO): Setting time to: 23:59:31 And date to:4/14/2023 2023-04-14T23:59:31.468Z,1681516771.468 [DAT](INFO): DAT read: user:5> 2023-04-14T23:59:31.469Z,1681516771.469 [DAT](INFO): DAT read: Fri Apr 14, 2023 23:59:31 2023-04-14T23:59:31.470Z,1681516771.470 [DAT](INFO): Local DAT time set to Fri Apr 14, 2023 23:59:31 2023-04-14T23:59:42.626Z,1681516782.626 [NAL9602](INFO): Powering up NAL9602 2023-04-14T23:59:53.519Z,1681516793.519 [NAL9602](INFO): NAL9602 initialized 2023-04-15T00:00:06.445Z,1681516806.445 [NAL9602](INFO): SBD MO Status=0, MOMSN=2446, MT Status=0, MTMSN=0 2023-04-15T00:00:06.445Z,1681516806.445 [NAL9602](INFO): No messages in MT queue 2023-04-15T00:00:33.124Z,1681516833.124 [SBIT](IMPORTANT): Beginning Startup BIT 2023-04-15T00:00:33.129Z,1681516833.129 [CBIT](IMPORTANT): Beginning ground fault scan 2023-04-15T00:00:44.090Z,1681516844.090 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): 0.025386 CHAN A1 (24V): 0.027189 CHAN A2 (12V): -0.019189 CHAN A3 (5V): -0.025432 CHAN B0 (3.3V): -0.013690 CHAN B1 (3.15aV): -0.007752 CHAN B2 (3.15bV): -0.004575 CHAN B3 (GND): -0.015820 OPEN: 0.008602 Full Scale: +/- 1 mA 2023-04-15T00:00:55.331Z,1681516855.331 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000052.00,A,3648.15262,N,12147.22236,W,0.058,0.00,150423,,,A*7A 2023-04-15T00:00:55.334Z,1681516855.334 [NAL9602](INFO): GPS fix at 20230415T000052: (36.802544, -121.787039) 2023-04-15T00:01:26.862Z,1681516886.862 [SBIT](FAULT): Mass: EXPECTED:-0.014830 ACTUAL:-0.015000 2023-04-15T00:01:26.862Z,1681516886.862 [SBIT](FAULT): Control surface position failure. 2023-04-15T00:01:27.330Z,1681516887.330 [SBIT](CRITICAL): SBIT FAILED 2023-04-15T00:01:27.330Z,1681516887.330 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2023-04-15T00:01:27.331Z,1681516887.331 [SBIT](IMPORTANT): CBIT.stopDepth=60 meter; 2023-04-15T00:01:27.331Z,1681516887.331 [SBIT](IMPORTANT): Depth_Keller.offset=-0.8 decibar; 2023-04-15T00:01:27.331Z,1681516887.331 [SBIT](IMPORTANT): ESPComponent.sampleTimeout=4 minute; 2023-04-15T00:01:27.331Z,1681516887.331 [SBIT](IMPORTANT): ElevatorServo.offsetAngle=1 degree; 2023-04-15T00:01:27.331Z,1681516887.331 [SBIT](IMPORTANT): Express linearApproximation VerticalHomogeneityIndexCalculator.vertical_salinity_homogeneity_index 0.050000 practical_salinity_unit; 2023-04-15T00:01:27.331Z,1681516887.331 [SBIT](IMPORTANT): Express linearApproximation VerticalHomogeneityIndexCalculator.vertical_temperature_homogeneity_index 0.050000 celsius; 2023-04-15T00:01:27.331Z,1681516887.331 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff470nm; 2023-04-15T00:01:27.332Z,1681516887.332 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff650nm; 2023-04-15T00:01:27.332Z,1681516887.332 [SBIT](IMPORTANT): StratificationFrontDetector.loadAtStartup=1 bool; 2023-04-15T00:01:27.332Z,1681516887.332 [SBIT](IMPORTANT): StratificationFrontDetector.threshold_VTHI=0.05 celsius; 2023-04-15T00:01:27.332Z,1681516887.332 [SBIT](IMPORTANT): StratificationFrontDetector.verbosity=1 count; 2023-04-15T00:01:27.332Z,1681516887.332 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=79.764107 cubic_centimeter; 2023-04-15T00:01:27.332Z,1681516887.332 [SBIT](IMPORTANT): VerticalControl.massDefault=-14.830472 millimeter; 2023-04-15T00:01:27.332Z,1681516887.332 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth3=20 meter; 2023-04-15T00:01:27.333Z,1681516887.333 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth4=30 meter; 2023-04-15T00:01:27.333Z,1681516887.333 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.loadAtStartup=1 bool; 2023-04-15T00:01:27.334Z,1681516887.334 [CommandExec](FAULT): Scheduling is paused 2023-04-15T00:01:27.335Z,1681516887.335 [CBIT](INFO): Critical error at 20230415T000127 2023-04-15T00:01:27.335Z,1681516887.335 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2023-04-15T00:01:27.685Z,1681516887.685 [MissionManager](IMPORTANT): Started mission Startup 2023-04-15T00:01:27.686Z,1681516887.686 [Startup] Running Loop=1 2023-04-15T00:01:27.686Z,1681516887.686 [Startup](DEBUG): Aggregate::initialize Startup 2023-04-15T00:01:27.686Z,1681516887.686 [Startup:A.GoToSurface] Running Loop=1 2023-04-15T00:01:27.686Z,1681516887.686 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2023-04-15T00:01:27.687Z,1681516887.687 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2023-04-15T00:01:27.687Z,1681516887.687 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2023-04-15T00:01:27.687Z,1681516887.687 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2023-04-15T00:01:27.692Z,1681516887.692 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2023-04-15T00:01:27.692Z,1681516887.692 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2023-04-15T00:01:27.694Z,1681516887.694 [Startup:StartupSatComms] Running Loop=1 2023-04-15T00:01:27.694Z,1681516887.694 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2023-04-15T00:01:27.694Z,1681516887.694 [Startup:StartupSatComms:A] Running Loop=1 2023-04-15T00:01:28.093Z,1681516888.093 [NAL9602](INFO): Not Powering down - fast GPS 2023-04-15T00:01:28.105Z,1681516888.105 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2023-04-15T00:01:29.695Z,1681516889.695 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000126.00,A,3648.15269,N,12147.22186,W,0.039,0.00,150423,,,A*7C 2023-04-15T00:01:29.704Z,1681516889.704 [NAL9602](INFO): GPS fix at 20230415T000126: (36.802545, -121.787031) 2023-04-15T00:01:29.714Z,1681516889.714 [Startup:StartupSatComms:A] Stopped 2023-04-15T00:01:29.715Z,1681516889.715 [Startup:StartupSatComms:B] Running Loop=1 2023-04-15T00:01:30.140Z,1681516890.140 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2023-04-15T00:02:20.695Z,1681516940.695 [NAL9602](INFO): SBD MO Status=2, MOMSN=2447, MT Status=2, MTMSN=0 2023-04-15T00:02:20.695Z,1681516940.695 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2023-04-15T00:02:29.927Z,1681516949.927 [Startup:StartupSatComms:B](INFO): Timed out from 2023-04-15T00:01:29.7Z 2023-04-15T00:02:29.927Z,1681516949.927 [Startup:StartupSatComms:B] Stopped 2023-04-15T00:02:29.928Z,1681516949.928 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2023-04-15T00:02:29.928Z,1681516949.928 [Startup:StartupSatComms] Stopped 2023-04-15T00:02:29.928Z,1681516949.928 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2023-04-15T00:02:29.929Z,1681516949.929 [Startup](INFO): Completed Startup 2023-04-15T00:02:29.929Z,1681516949.929 [MissionManager](INFO): Startup is completed. 2023-04-15T00:02:29.929Z,1681516949.929 [MissionManager](INFO): Uninitializing Mission Startup 2023-04-15T00:02:29.929Z,1681516949.929 [Startup] Stopped 2023-04-15T00:02:29.929Z,1681516949.929 [Startup](DEBUG): Aggregate::uninitialize Startup 2023-04-15T00:02:29.929Z,1681516949.929 [Startup:A.GoToSurface] Stopped 2023-04-15T00:02:29.929Z,1681516949.929 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2023-04-15T00:02:30.341Z,1681516950.341 [MissionManager](IMPORTANT): Started mission Default 2023-04-15T00:02:30.341Z,1681516950.341 [Default] Running Loop=1 2023-04-15T00:02:30.341Z,1681516950.341 [Default](DEBUG): Aggregate::initialize Default 2023-04-15T00:02:30.341Z,1681516950.341 [Default:B.GoToSurface] Running Loop=1 2023-04-15T00:02:30.341Z,1681516950.341 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2023-04-15T00:02:30.342Z,1681516950.342 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2023-04-15T00:02:30.342Z,1681516950.342 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2023-04-15T00:02:30.342Z,1681516950.342 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2023-04-15T00:02:30.343Z,1681516950.343 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2023-04-15T00:02:30.343Z,1681516950.343 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2023-04-15T00:02:30.343Z,1681516950.343 [Default:A.Wait] Running Loop=1 2023-04-15T00:02:30.343Z,1681516950.343 [Default:A.Wait](DEBUG): Initialize Wait Component. 2023-04-15T00:02:43.345Z,1681516963.345 [Default:A.Wait](INFO): Done Waiting. 2023-04-15T00:02:43.346Z,1681516963.346 [Default:A.Wait] Stopped 2023-04-15T00:02:43.346Z,1681516963.346 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2023-04-15T00:02:43.772Z,1681516963.772 [DVL_micro](ERROR): Failed to parse: :5,+01275,-0000,I 2023-04-15T00:02:43.791Z,1681516963.791 [Default:CheckIn] Running Loop=1 2023-04-15T00:02:43.791Z,1681516963.791 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2023-04-15T00:02:43.820Z,1681516963.820 [Default:CheckIn:Read_GPS] Running Loop=1 2023-04-15T00:02:44.174Z,1681516964.174 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2023-04-15T00:02:46.577Z,1681516966.577 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2023-04-15T00:02:46.577Z,1681516966.577 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+19.1,0000.0,1489:WI,+00650,+01087,-01177,+000I,+00650,+01087,-01177,+00000,I 2023-04-15T00:02:47.910Z,1681516967.910 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004593 2023-04-15T00:02:48.595Z,1681516968.595 [NAL9602](INFO): SBD MO Status=2, MOMSN=2447, MT Status=2, MTMSN=0 2023-04-15T00:02:48.596Z,1681516968.596 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2023-04-15T00:02:49.783Z,1681516969.783 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000246.00,A,3648.15220,N,12147.22327,W,0.039,148.44,150423,,,A*70 2023-04-15T00:02:49.793Z,1681516969.793 [NAL9602](INFO): GPS fix at 20230415T000246: (36.802537, -121.787054) 2023-04-15T00:02:49.803Z,1681516969.803 [Default:CheckIn:Read_GPS] Stopped 2023-04-15T00:02:49.803Z,1681516969.803 [Default:CheckIn:Read_Iridium] Running Loop=1 2023-04-15T00:02:50.217Z,1681516970.217 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2023-04-15T00:02:57.472Z,1681516977.472 [DataOverHttps](INFO): Sending 144 bytes from file Logs/20230414T232437/Courier0010.lzma 2023-04-15T00:02:58.474Z,1681516978.474 [DataOverHttps](INFO): Moved sent file to Logs/20230414T232437/Courier0010.lzma.bak 2023-04-15T00:02:58.474Z,1681516978.474 [DataOverHttps](INFO): SBD MOMSN=18223011 2023-04-15T00:03:01.915Z,1681516981.915 [NAL9602](INFO): SBD MO Status=1, MOMSN=2447, MT Status=0, MTMSN=0 2023-04-15T00:03:01.916Z,1681516981.916 [NAL9602](INFO): No messages in MT queue 2023-04-15T00:03:14.420Z,1681516994.420 [DataOverHttps](INFO): Sending 298 bytes from file Logs/20230414T235903/Courier0000.lzma 2023-04-15T00:03:15.423Z,1681516995.423 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Courier0000.lzma.bak 2023-04-15T00:03:15.423Z,1681516995.423 [DataOverHttps](INFO): SBD MOMSN=18223015 2023-04-15T00:03:31.468Z,1681517011.468 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230414T235903/Courier0004.lzma 2023-04-15T00:03:32.470Z,1681517012.470 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Courier0004.lzma.bak 2023-04-15T00:03:32.470Z,1681517012.470 [DataOverHttps](INFO): SBD MOMSN=18223020 2023-04-15T00:03:32.620Z,1681517012.620 [NAL9602](INFO): Not Powering down - fast GPS 2023-04-15T00:03:51.410Z,1681517031.410 [DataOverHttps](INFO): Sending 1556 bytes from file Logs/20230414T232437/Express0011.lzma 2023-04-15T00:03:52.409Z,1681517032.409 [DataOverHttps](INFO): Moved sent file to Logs/20230414T232437/Express0011.lzma.bak 2023-04-15T00:03:52.410Z,1681517032.410 [DataOverHttps](INFO): SBD MOMSN=18223023 2023-04-15T00:04:08.293Z,1681517048.293 [DataOverHttps](INFO): Sending 1181 bytes from file Logs/20230414T235903/Express0001.lzma 2023-04-15T00:04:09.294Z,1681517049.294 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0001.lzma.bak 2023-04-15T00:04:09.294Z,1681517049.294 [DataOverHttps](INFO): SBD MOMSN=18223137 2023-04-15T00:04:28.583Z,1681517068.583 [DataOverHttps](INFO): Sending 106 bytes from file Logs/20230414T235903/Express0005.lzma 2023-04-15T00:04:29.585Z,1681517069.585 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0005.lzma.bak 2023-04-15T00:04:29.586Z,1681517069.586 [DataOverHttps](INFO): SBD MOMSN=18223167 2023-04-15T00:04:30.910Z,1681517070.910 [Default:CheckIn:Read_Iridium] Stopped 2023-04-15T00:04:30.910Z,1681517070.910 [Default:CheckIn:C.Wait] Running Loop=1 2023-04-15T00:04:30.910Z,1681517070.910 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2023-04-15T00:06:19.234Z,1681517179.234 [DVL_micro](ERROR): only read 3 of 4 data items 2023-04-15T00:06:19.234Z,1681517179.234 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+99999.99,+9999.99 2023-04-15T00:06:52.354Z,1681517212.354 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2023-04-15T00:06:52.369Z,1681517212.369 [BPC1](INFO): Received data from all battery sticks. 2023-04-15T00:09:13.165Z,1681517353.165 [DataOverHttps](IMPORTANT): SBD MTMSN=20230415T000912 2023-04-15T00:09:20.684Z,1681517360.684 [DataOverHttps](INFO): Received command: strobe off 2023-04-15T00:09:20.733Z,1681517360.733 [CommandExec](IMPORTANT): got command strobe off 2023-04-15T00:09:20.733Z,1681517360.733 [CommandExec](IMPORTANT): Deactivating strobe 2023-04-15T00:09:31.600Z,1681517371.600 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2023-04-15T00:09:31.600Z,1681517371.600 [Default:CheckIn:C.Wait] Stopped 2023-04-15T00:09:31.600Z,1681517371.600 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2023-04-15T00:09:31.600Z,1681517371.600 [Default:CheckIn:D] Running Loop=1 2023-04-15T00:09:32.006Z,1681517372.006 [Default:CheckIn:D] Stopped 2023-04-15T00:09:32.006Z,1681517372.006 [Default:CheckIn:E] Running Loop=1 2023-04-15T00:09:32.425Z,1681517372.425 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.027745 min 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn:E] Stopped 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn](INFO): Completed Default:CheckIn 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn] Stopped 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn](INFO): Running loop #2 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn] Running Loop=2 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2023-04-15T00:09:32.426Z,1681517372.426 [Default:CheckIn:Read_GPS] Running Loop=1 2023-04-15T00:09:34.402Z,1681517374.402 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000934.00,A,3648.15080,N,12147.22096,W,0.039,75.02,150423,,,A*42 2023-04-15T00:09:34.413Z,1681517374.413 [NAL9602](INFO): GPS fix at 20230415T000934: (36.802513, -121.787016) 2023-04-15T00:09:34.446Z,1681517374.446 [Default:CheckIn:Read_GPS] Stopped 2023-04-15T00:09:34.447Z,1681517374.447 [Default:CheckIn:Read_Iridium] Running Loop=1 2023-04-15T00:09:45.455Z,1681517385.455 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20230414T235903/Courier0007.lzma 2023-04-15T00:09:46.458Z,1681517386.458 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Courier0007.lzma.bak 2023-04-15T00:09:46.458Z,1681517386.458 [DataOverHttps](INFO): SBD MOMSN=18223174 2023-04-15T00:09:59.502Z,1681517399.502 [NAL9602](INFO): SBD MO Status=2, MOMSN=2448, MT Status=2, MTMSN=0 2023-04-15T00:09:59.502Z,1681517399.502 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2023-04-15T00:10:02.320Z,1681517402.320 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20230414T235903/Express0008.lzma 2023-04-15T00:10:03.322Z,1681517403.322 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0008.lzma.bak 2023-04-15T00:10:03.322Z,1681517403.322 [DataOverHttps](INFO): SBD MOMSN=18223177 2023-04-15T00:10:15.658Z,1681517415.658 [NAL9602](INFO): SBD MO Status=2, MOMSN=2448, MT Status=2, MTMSN=0 2023-04-15T00:10:15.658Z,1681517415.658 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2023-04-15T00:10:21.707Z,1681517421.707 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20230414T235903/Express0011.lzma 2023-04-15T00:10:22.711Z,1681517422.711 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0011.lzma.bak 2023-04-15T00:10:22.711Z,1681517422.711 [DataOverHttps](INFO): SBD MOMSN=18223183 2023-04-15T00:10:23.775Z,1681517423.775 [Default:CheckIn:Read_Iridium] Stopped 2023-04-15T00:10:23.775Z,1681517423.775 [Default:CheckIn:C.Wait] Running Loop=1 2023-04-15T00:10:23.775Z,1681517423.775 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2023-04-15T00:11:18.297Z,1681517478.297 [NAL9602](INFO): SBD MO Status=2, MOMSN=2448, MT Status=2, MTMSN=0 2023-04-15T00:11:18.297Z,1681517478.297 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2023-04-15T00:11:38.142Z,1681517498.142 [NAL9602](INFO): SBD MO Status=1, MOMSN=2448, MT Status=0, MTMSN=0 2023-04-15T00:11:38.142Z,1681517498.142 [NAL9602](INFO): No messages in MT queue 2023-04-15T00:12:08.805Z,1681517528.805 [NAL9602](INFO): Not Powering down - fast GPS 2023-04-15T00:13:32.042Z,1681517612.042 [DVL_micro](ERROR): Failed to parse: 9.99,+99999.99,+9999.99 2023-04-15T00:15:24.387Z,1681517724.387 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2023-04-15T00:15:24.387Z,1681517724.387 [Default:CheckIn:C.Wait] Stopped 2023-04-15T00:15:24.387Z,1681517724.387 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2023-04-15T00:15:24.387Z,1681517724.387 [Default:CheckIn:D] Running Loop=1 2023-04-15T00:15:24.761Z,1681517724.761 [Default:CheckIn:D] Stopped 2023-04-15T00:15:24.762Z,1681517724.762 [Default:CheckIn:E] Running Loop=1 2023-04-15T00:15:25.169Z,1681517725.169 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.907006 min 2023-04-15T00:15:25.169Z,1681517725.169 [Default:CheckIn:E] Stopped 2023-04-15T00:15:25.169Z,1681517725.169 [Default:CheckIn](INFO): Completed Default:CheckIn 2023-04-15T00:15:25.170Z,1681517725.170 [Default:CheckIn] Stopped 2023-04-15T00:15:25.170Z,1681517725.170 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2023-04-15T00:15:25.170Z,1681517725.170 [Default:CheckIn](INFO): Running loop #3 2023-04-15T00:15:25.170Z,1681517725.170 [Default:CheckIn] Running Loop=3 2023-04-15T00:15:25.170Z,1681517725.170 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2023-04-15T00:15:25.170Z,1681517725.170 [Default:CheckIn:Read_GPS] Running Loop=1 2023-04-15T00:15:27.182Z,1681517727.182 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001526.00,A,3648.51600,N,12147.12818,W,4.860,312.75,150423,,,D*78 2023-04-15T00:15:27.184Z,1681517727.184 [NAL9602](INFO): GPS fix at 20230415T001526: (36.808600, -121.785470) 2023-04-15T00:15:27.194Z,1681517727.194 [Default:CheckIn:Read_GPS] Stopped 2023-04-15T00:15:27.194Z,1681517727.194 [Default:CheckIn:Read_Iridium] Running Loop=1 2023-04-15T00:15:37.607Z,1681517737.607 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230414T235903/Courier0013.lzma 2023-04-15T00:15:38.610Z,1681517738.610 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Courier0013.lzma.bak 2023-04-15T00:15:38.610Z,1681517738.610 [DataOverHttps](INFO): SBD MOMSN=18223205 2023-04-15T00:15:39.365Z,1681517739.365 [NAL9602](INFO): SBD MO Status=1, MOMSN=2449, MT Status=0, MTMSN=0 2023-04-15T00:15:39.365Z,1681517739.365 [NAL9602](INFO): No messages in MT queue 2023-04-15T00:15:55.370Z,1681517755.370 [DataOverHttps](INFO): Sending 144 bytes from file Logs/20230414T235903/Express0014.lzma 2023-04-15T00:15:56.358Z,1681517756.358 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0014.lzma.bak 2023-04-15T00:15:56.358Z,1681517756.358 [DataOverHttps](INFO): SBD MOMSN=18223208 2023-04-15T00:15:57.537Z,1681517757.537 [Default:CheckIn:Read_Iridium] Stopped 2023-04-15T00:15:57.537Z,1681517757.537 [Default:CheckIn:C.Wait] Running Loop=1 2023-04-15T00:15:57.537Z,1681517757.537 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2023-04-15T00:16:10.058Z,1681517770.058 [NAL9602](INFO): Not Powering down - fast GPS 2023-04-15T00:17:04.601Z,1681517824.601 [DVL_micro](ERROR): only read 3 of 4 data items 2023-04-15T00:17:04.601Z,1681517824.601 [DVL_micro](ERROR): Failed to parse: :BI,-00100,+01259,-0100,I 2023-04-15T00:20:29.923Z,1681518029.923 [DVL_micro](ERROR): only read 0 of 4 data items 2023-04-15T00:20:29.923Z,1681518029.923 [DVL_micro](ERROR): Failed to parse: :RD9,+9999.99,+9999.99,+9999.99 2023-04-15T00:20:37.613Z,1681518037.613 [DVL_micro](ERROR): Failed to parse: :SA,+05.48,-07.71,249.4 2023-04-15T00:20:58.201Z,1681518058.201 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2023-04-15T00:20:58.201Z,1681518058.201 [Default:CheckIn:C.Wait] Stopped 2023-04-15T00:20:58.201Z,1681518058.201 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2023-04-15T00:20:58.202Z,1681518058.202 [Default:CheckIn:D] Running Loop=1 2023-04-15T00:20:58.611Z,1681518058.611 [Default:CheckIn:D] Stopped 2023-04-15T00:20:58.611Z,1681518058.611 [Default:CheckIn:E] Running Loop=1 2023-04-15T00:20:59.016Z,1681518059.016 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.471159 min 2023-04-15T00:20:59.016Z,1681518059.016 [Default:CheckIn:E] Stopped 2023-04-15T00:20:59.016Z,1681518059.016 [Default:CheckIn](INFO): Completed Default:CheckIn 2023-04-15T00:20:59.016Z,1681518059.016 [Default:CheckIn] Stopped 2023-04-15T00:20:59.016Z,1681518059.016 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2023-04-15T00:20:59.017Z,1681518059.017 [Default:CheckIn](INFO): Running loop #4 2023-04-15T00:20:59.017Z,1681518059.017 [Default:CheckIn] Running Loop=4 2023-04-15T00:20:59.017Z,1681518059.017 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2023-04-15T00:20:59.017Z,1681518059.017 [Default:CheckIn:Read_GPS] Running Loop=1 2023-04-15T00:21:01.022Z,1681518061.022 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002100.00,A,3648.39683,N,12147.88947,W,10.672,278.44,150423,,,D*41 2023-04-15T00:21:01.024Z,1681518061.024 [NAL9602](INFO): GPS fix at 20230415T002100: (36.806614, -121.798158) 2023-04-15T00:21:01.054Z,1681518061.054 [Default:CheckIn:Read_GPS] Stopped 2023-04-15T00:21:01.054Z,1681518061.054 [Default:CheckIn:Read_Iridium] Running Loop=1 2023-04-15T00:21:08.679Z,1681518068.679 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20230414T235903/Courier0016.lzma 2023-04-15T00:21:09.684Z,1681518069.684 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Courier0016.lzma.bak 2023-04-15T00:21:09.684Z,1681518069.684 [DataOverHttps](INFO): SBD MOMSN=18223213 2023-04-15T00:21:25.587Z,1681518085.587 [DataOverHttps](INFO): Sending 143 bytes from file Logs/20230414T235903/Express0017.lzma 2023-04-15T00:21:26.590Z,1681518086.590 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0017.lzma.bak 2023-04-15T00:21:26.590Z,1681518086.590 [DataOverHttps](INFO): SBD MOMSN=18223216 2023-04-15T00:21:27.700Z,1681518087.700 [Default:CheckIn:Read_Iridium] Stopped 2023-04-15T00:21:27.700Z,1681518087.700 [Default:CheckIn:C.Wait] Running Loop=1 2023-04-15T00:21:27.700Z,1681518087.700 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2023-04-15T00:21:49.123Z,1681518109.123 [NAL9602](INFO): SBD MO Status=1, MOMSN=2450, MT Status=0, MTMSN=0 2023-04-15T00:21:49.123Z,1681518109.123 [NAL9602](INFO): No messages in MT queue 2023-04-15T00:22:19.819Z,1681518139.819 [NAL9602](INFO): Not Powering down - fast GPS 2023-04-15T00:24:02.489Z,1681518242.489 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2023-04-15T00:24:02.489Z,1681518242.489 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+18.4,0000.0,148 2023-04-15T00:26:28.409Z,1681518388.409 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2023-04-15T00:26:28.410Z,1681518388.409 [Default:CheckIn:C.Wait] Stopped 2023-04-15T00:26:28.410Z,1681518388.410 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2023-04-15T00:26:28.410Z,1681518388.410 [Default:CheckIn:D] Running Loop=1 2023-04-15T00:26:28.813Z,1681518388.813 [Default:CheckIn:D] Stopped 2023-04-15T00:26:28.813Z,1681518388.813 [Default:CheckIn:E] Running Loop=1 2023-04-15T00:26:29.216Z,1681518389.216 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.974534 min 2023-04-15T00:26:29.216Z,1681518389.216 [Default:CheckIn:E] Stopped 2023-04-15T00:26:29.216Z,1681518389.216 [Default:CheckIn](INFO): Completed Default:CheckIn 2023-04-15T00:26:29.216Z,1681518389.216 [Default:CheckIn] Stopped 2023-04-15T00:26:29.216Z,1681518389.216 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2023-04-15T00:26:29.216Z,1681518389.216 [Default:CheckIn](INFO): Running loop #5 2023-04-15T00:26:29.217Z,1681518389.217 [Default:CheckIn] Running Loop=5 2023-04-15T00:26:29.217Z,1681518389.217 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2023-04-15T00:26:29.217Z,1681518389.217 [Default:CheckIn:Read_GPS] Running Loop=1 2023-04-15T00:26:31.231Z,1681518391.231 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002630.00,A,3648.55204,N,12149.09006,W,9.175,231.71,150423,,,D*7C 2023-04-15T00:26:31.234Z,1681518391.234 [NAL9602](INFO): GPS fix at 20230415T002630: (36.809201, -121.818168) 2023-04-15T00:26:31.259Z,1681518391.259 [Default:CheckIn:Read_GPS] Stopped 2023-04-15T00:26:31.259Z,1681518391.259 [Default:CheckIn:Read_Iridium] Running Loop=1 2023-04-15T00:26:39.183Z,1681518399.183 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230414T235903/Courier0019.lzma 2023-04-15T00:26:40.186Z,1681518400.186 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Courier0019.lzma.bak 2023-04-15T00:26:40.186Z,1681518400.186 [DataOverHttps](INFO): SBD MOMSN=18223228 2023-04-15T00:26:44.589Z,1681518404.589 [NAL9602](INFO): SBD MO Status=1, MOMSN=2451, MT Status=0, MTMSN=0 2023-04-15T00:26:44.589Z,1681518404.589 [NAL9602](INFO): No messages in MT queue 2023-04-15T00:26:58.631Z,1681518418.631 [DataOverHttps](INFO): Sending 144 bytes from file Logs/20230414T235903/Express0020.lzma 2023-04-15T00:26:59.634Z,1681518419.634 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0020.lzma.bak 2023-04-15T00:26:59.634Z,1681518419.634 [DataOverHttps](INFO): SBD MOMSN=18223231 2023-04-15T00:27:00.751Z,1681518420.751 [Default:CheckIn:Read_Iridium] Stopped 2023-04-15T00:27:00.752Z,1681518420.752 [Default:CheckIn:C.Wait] Running Loop=1 2023-04-15T00:27:00.752Z,1681518420.752 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2023-04-15T00:27:15.269Z,1681518435.269 [NAL9602](INFO): Not Powering down - fast GPS 2023-04-15T00:27:27.786Z,1681518447.786 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2023-04-15T00:27:27.786Z,1681518447.786 [DVL_micro](ERROR): Failed to parse: :TS,000000000.0,+18.2,0000.0000 2023-04-15T00:29:59.804Z,1681518599.804 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.171341 2023-04-15T00:30:17.840Z,1681518617.840 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002825 2023-04-15T00:30:50.255Z,1681518650.255 [DVL_micro](ERROR): only read 3 of 4 data items 2023-04-15T00:30:50.255Z,1681518650.255 [DVL_micro](ERROR): Failed to parse: :BI,+00000,+00000,+0000,I 2023-04-15T00:32:01.359Z,1681518721.359 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2023-04-15T00:32:01.359Z,1681518721.359 [Default:CheckIn:C.Wait] Stopped 2023-04-15T00:32:01.360Z,1681518721.360 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2023-04-15T00:32:01.360Z,1681518721.360 [Default:CheckIn:D] Running Loop=1 2023-04-15T00:32:01.778Z,1681518721.778 [Default:CheckIn:D] Stopped 2023-04-15T00:32:01.778Z,1681518721.778 [Default:CheckIn:E] Running Loop=1 2023-04-15T00:32:02.168Z,1681518722.168 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.523954 min 2023-04-15T00:32:02.168Z,1681518722.168 [Default:CheckIn:E] Stopped 2023-04-15T00:32:02.168Z,1681518722.168 [Default:CheckIn](INFO): Completed Default:CheckIn 2023-04-15T00:32:02.168Z,1681518722.168 [Default:CheckIn] Stopped 2023-04-15T00:32:02.168Z,1681518722.168 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2023-04-15T00:32:02.169Z,1681518722.169 [Default:CheckIn](INFO): Running loop #6 2023-04-15T00:32:02.169Z,1681518722.169 [Default:CheckIn] Running Loop=6 2023-04-15T00:32:02.169Z,1681518722.169 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2023-04-15T00:32:02.169Z,1681518722.169 [Default:CheckIn:Read_GPS] Running Loop=1 2023-04-15T00:32:04.177Z,1681518724.177 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,003203.00,A,3648.50425,N,12149.19119,W,0.641,314.13,150423,,,D*7C 2023-04-15T00:32:04.179Z,1681518724.179 [NAL9602](INFO): GPS fix at 20230415T003203: (36.808404, -121.819853) 2023-04-15T00:32:04.190Z,1681518724.190 [Default:CheckIn:Read_GPS] Stopped 2023-04-15T00:32:04.190Z,1681518724.190 [Default:CheckIn:Read_Iridium] Running Loop=1 2023-04-15T00:32:11.351Z,1681518731.351 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230414T235903/Courier0022.lzma 2023-04-15T00:32:12.354Z,1681518732.354 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Courier0022.lzma.bak 2023-04-15T00:32:12.354Z,1681518732.354 [DataOverHttps](INFO): SBD MOMSN=18223236 2023-04-15T00:32:20.423Z,1681518740.423 [NAL9602](INFO): SBD MO Status=1, MOMSN=2452, MT Status=0, MTMSN=0 2023-04-15T00:32:20.428Z,1681518740.428 [NAL9602](INFO): No messages in MT queue 2023-04-15T00:32:32.147Z,1681518752.147 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20230414T235903/Express0023.lzma 2023-04-15T00:32:33.150Z,1681518753.150 [DataOverHttps](INFO): Moved sent file to Logs/20230414T235903/Express0023.lzma.bak 2023-04-15T00:32:33.150Z,1681518753.150 [DataOverHttps](INFO): SBD MOMSN=18223239 2023-04-15T00:32:34.561Z,1681518754.561 [Default:CheckIn:Read_Iridium] Stopped 2023-04-15T00:32:34.561Z,1681518754.561 [Default:CheckIn:C.Wait] Running Loop=1 2023-04-15T00:32:34.561Z,1681518754.561 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2023-04-15T00:32:41.426Z,1681518761.426 [DVL_micro](ERROR): Failed to parse: :R32,+0000.30,+0000.30,+0000.65 2023-04-15T00:32:51.108Z,1681518771.108 [NAL9602](INFO): Not Powering down - fast GPS 2023-04-15T00:33:45.369Z,1681518825.369 [DataOverHttps](IMPORTANT): SBD MTMSN=20230415T003344 2023-04-15T00:33:46.479Z,1681518826.479 [DVL_micro](ERROR): Failed to parse:38.58,+0038.64,+0043.18,+0042.87