2024-04-23T16:33:57.146Z,1713890037.146 [Supervisor](DEBUG): Initializing supervisor. 2024-04-23T16:33:57.151Z,1713890037.151 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2024-04-23T16:33:57.151Z,1713890037.151 [SyncHandler](INFO): Protected caller Thread ID is 5487 2024-04-23T16:33:57.151Z,1713890037.151 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2024-04-23T16:33:57.152Z,1713890037.152 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2024-04-23T16:33:57.153Z,1713890037.153 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5488 2024-04-23T16:33:57.157Z,1713890037.157 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2024-04-23T16:33:57.174Z,1713890037.174 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2024-04-23T16:33:57.175Z,1713890037.175 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2024-04-23T16:33:57.175Z,1713890037.175 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 5489 2024-04-23T16:33:57.185Z,1713890037.185 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2024-04-23T16:33:57.190Z,1713890037.190 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2024-04-23T16:33:57.190Z,1713890037.190 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5490 2024-04-23T16:33:57.192Z,1713890037.192 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2024-04-23T16:33:57.193Z,1713890037.193 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2024-04-23T16:33:57.193Z,1713890037.193 [logger ThreadHandler](INFO): Protected caller Thread ID is 5491 2024-04-23T16:33:57.200Z,1713890037.200 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2024-04-23T16:33:57.201Z,1713890037.201 [Supervisor](INFO): Looking for Config files in directory: Config/ 2024-04-23T16:33:57.202Z,1713890037.202 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2024-04-23T16:33:57.613Z,1713890037.613 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2024-04-23T16:33:57.614Z,1713890037.614 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2024-04-23T16:33:58.373Z,1713890038.373 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2024-04-23T16:33:58.374Z,1713890038.374 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2024-04-23T16:33:58.497Z,1713890038.497 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2024-04-23T16:33:58.497Z,1713890038.497 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2024-04-23T16:33:59.059Z,1713890039.059 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2024-04-23T16:33:59.060Z,1713890039.060 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2024-04-23T16:33:59.172Z,1713890039.172 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2024-04-23T16:33:59.173Z,1713890039.173 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2024-04-23T16:33:59.268Z,1713890039.268 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2024-04-23T16:33:59.699Z,1713890039.699 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2024-04-23T16:33:59.700Z,1713890039.700 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2024-04-23T16:33:59.939Z,1713890039.939 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2024-04-23T16:33:59.940Z,1713890039.940 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2024-04-23T16:34:00.090Z,1713890040.090 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2024-04-23T16:34:00.091Z,1713890040.091 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2024-04-23T16:34:00.358Z,1713890040.358 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2024-04-23T16:34:00.358Z,1713890040.358 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2024-04-23T16:34:00.918Z,1713890040.918 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2024-04-23T16:34:00.918Z,1713890040.918 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2024-04-23T16:34:01.315Z,1713890041.315 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2024-04-23T16:34:01.316Z,1713890041.316 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2024-04-23T16:34:01.409Z,1713890041.409 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2024-04-23T16:34:01.618Z,1713890041.618 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2024-04-23T16:34:01.619Z,1713890041.619 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2024-04-23T16:34:01.866Z,1713890041.866 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2024-04-23T16:34:01.867Z,1713890041.867 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2024-04-23T16:34:02.191Z,1713890042.191 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2024-04-23T16:34:02.193Z,1713890042.193 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/ 2024-04-23T16:34:02.194Z,1713890042.194 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg 2024-04-23T16:34:02.856Z,1713890042.856 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg 2024-04-23T16:34:03.466Z,1713890043.466 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg 2024-04-23T16:34:03.565Z,1713890043.565 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg 2024-04-23T16:34:03.662Z,1713890043.662 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg 2024-04-23T16:34:03.786Z,1713890043.786 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg 2024-04-23T16:34:03.906Z,1713890043.906 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg 2024-04-23T16:34:04.183Z,1713890044.183 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2024-04-23T16:34:04.184Z,1713890044.184 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg 2024-04-23T16:34:04.333Z,1713890044.333 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg 2024-04-23T16:34:04.440Z,1713890044.440 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg 2024-04-23T16:34:04.547Z,1713890044.547 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg 2024-04-23T16:34:04.663Z,1713890044.663 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/root/ 2024-04-23T16:34:04.663Z,1713890044.663 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2024-04-23T16:34:04.672Z,1713890044.672 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2024-04-23T16:34:04.787Z,1713890044.787 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2024-04-23T16:34:04.788Z,1713890044.788 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2024-04-23T16:34:04.798Z,1713890044.798 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2024-04-23T16:34:04.799Z,1713890044.799 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2024-04-23T16:34:04.849Z,1713890044.849 [DepthRateCalculator] Loaded 2024-04-23T16:34:04.849Z,1713890044.849 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2024-04-23T16:34:04.855Z,1713890044.855 [PitchRateCalculator] Loaded 2024-04-23T16:34:04.855Z,1713890044.855 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2024-04-23T16:34:04.865Z,1713890044.865 [SpeedCalculator] Loaded 2024-04-23T16:34:04.865Z,1713890044.865 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2024-04-23T16:34:04.870Z,1713890044.870 [YawRateCalculator] Loaded 2024-04-23T16:34:04.870Z,1713890044.870 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2024-04-23T16:34:04.891Z,1713890044.891 [ElevatorOffsetCalculator] Loaded 2024-04-23T16:34:04.892Z,1713890044.892 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2024-04-23T16:34:04.892Z,1713890044.892 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2024-04-23T16:34:04.893Z,1713890044.893 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2024-04-23T16:34:04.944Z,1713890044.944 [VerticalControl](DEBUG): Construct VerticalControl. 2024-04-23T16:34:04.999Z,1713890044.999 [VerticalControl] Loaded 2024-04-23T16:34:04.999Z,1713890044.999 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2024-04-23T16:34:05.002Z,1713890045.002 [HorizontalControl](DEBUG): Construct HorizontalControl. 2024-04-23T16:34:05.044Z,1713890045.044 [HorizontalControl] Loaded 2024-04-23T16:34:05.044Z,1713890045.044 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2024-04-23T16:34:05.047Z,1713890045.047 [SpeedControl](DEBUG): Construct SpeedControl. 2024-04-23T16:34:05.049Z,1713890045.049 [SpeedControl] Loaded 2024-04-23T16:34:05.050Z,1713890045.050 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2024-04-23T16:34:05.052Z,1713890045.052 [LoopControl](DEBUG): Construct LoopControl. 2024-04-23T16:34:05.053Z,1713890045.053 [LoopControl] Loaded 2024-04-23T16:34:05.053Z,1713890045.053 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2024-04-23T16:34:05.053Z,1713890045.053 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2024-04-23T16:34:05.054Z,1713890045.054 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2024-04-23T16:34:05.164Z,1713890045.164 [DeadReckonUsingMultipleVelocitySources] Loaded 2024-04-23T16:34:05.164Z,1713890045.164 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2024-04-23T16:34:05.178Z,1713890045.178 [NavChart] Loaded 2024-04-23T16:34:05.178Z,1713890045.178 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2024-04-23T16:34:05.183Z,1713890045.183 [UniversalFixResidualReporter] Loaded 2024-04-23T16:34:05.184Z,1713890045.184 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2024-04-23T16:34:05.184Z,1713890045.184 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2024-04-23T16:34:05.185Z,1713890045.185 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2024-04-23T16:34:05.360Z,1713890045.360 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2024-04-23T16:34:05.360Z,1713890045.360 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2024-04-23T16:34:05.819Z,1713890045.819 [AHRS_M2] Loaded 2024-04-23T16:34:05.819Z,1713890045.819 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2024-04-23T16:34:05.855Z,1713890045.855 [BackseatComponent] Loaded 2024-04-23T16:34:05.855Z,1713890045.855 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread. 2024-04-23T16:34:05.856Z,1713890045.856 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 409204E0 2024-04-23T16:34:05.856Z,1713890045.856 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 5573 2024-04-23T16:34:05.859Z,1713890045.859 [LcmUniversalReporter] Loaded 2024-04-23T16:34:05.859Z,1713890045.859 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread. 2024-04-23T16:34:06.668Z,1713890046.668 [BPC1] Loaded 2024-04-23T16:34:06.668Z,1713890046.668 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2024-04-23T16:34:06.742Z,1713890046.742 [DataOverHttps] Loaded 2024-04-23T16:34:06.742Z,1713890046.742 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2024-04-23T16:34:06.743Z,1713890046.743 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409504E0 2024-04-23T16:34:06.743Z,1713890046.743 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5574 2024-04-23T16:34:06.764Z,1713890046.764 [Depth_Keller] Loaded 2024-04-23T16:34:06.764Z,1713890046.764 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2024-04-23T16:34:06.769Z,1713890046.769 [DropWeight] Loaded 2024-04-23T16:34:06.769Z,1713890046.769 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2024-04-23T16:34:06.807Z,1713890046.807 [DVL_micro] Loaded 2024-04-23T16:34:06.808Z,1713890046.808 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2024-04-23T16:34:06.869Z,1713890046.869 [NAL9602] Loaded 2024-04-23T16:34:06.870Z,1713890046.870 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2024-04-23T16:34:06.899Z,1713890046.899 [Onboard] Loaded 2024-04-23T16:34:06.899Z,1713890046.899 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2024-04-23T16:34:06.900Z,1713890046.900 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409804E0 2024-04-23T16:34:06.901Z,1713890046.901 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 5575 2024-04-23T16:34:06.913Z,1713890046.913 [Power24vConverter] Loaded 2024-04-23T16:34:06.913Z,1713890046.913 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2024-04-23T16:34:06.926Z,1713890046.926 [Radio_Surface] Loaded 2024-04-23T16:34:06.926Z,1713890046.926 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2024-04-23T16:34:06.927Z,1713890046.927 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409B04E0 2024-04-23T16:34:06.927Z,1713890046.927 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5576 2024-04-23T16:34:06.941Z,1713890046.941 [Sonardyne_Nano] Loaded 2024-04-23T16:34:06.941Z,1713890046.941 [ComponentRegistry](DEBUG): SyncComponent "Sonardyne_Nano" handled in the control thread. 2024-04-23T16:34:07.034Z,1713890047.034 [DAT] Loaded 2024-04-23T16:34:07.034Z,1713890047.034 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread. 2024-04-23T16:34:07.035Z,1713890047.035 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 409E04E0 2024-04-23T16:34:07.035Z,1713890047.035 [DAT ThreadHandler](INFO): Protected caller Thread ID is 5577 2024-04-23T16:34:07.036Z,1713890047.036 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2024-04-23T16:34:07.037Z,1713890047.037 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2024-04-23T16:34:07.169Z,1713890047.169 [BuoyancyServo] Loaded 2024-04-23T16:34:07.169Z,1713890047.169 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2024-04-23T16:34:07.190Z,1713890047.190 [ElevatorServo] Loaded 2024-04-23T16:34:07.190Z,1713890047.190 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2024-04-23T16:34:07.209Z,1713890047.209 [MassServo] Loaded 2024-04-23T16:34:07.210Z,1713890047.210 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2024-04-23T16:34:07.228Z,1713890047.228 [RudderServo] Loaded 2024-04-23T16:34:07.228Z,1713890047.228 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2024-04-23T16:34:07.243Z,1713890047.243 [ThrusterHE] Loaded 2024-04-23T16:34:07.243Z,1713890047.243 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread. 2024-04-23T16:34:07.244Z,1713890047.244 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2024-04-23T16:34:07.244Z,1713890047.244 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2024-04-23T16:34:07.529Z,1713890047.529 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2024-04-23T16:34:07.530Z,1713890047.530 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2024-04-23T16:34:07.557Z,1713890047.557 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2024-04-23T16:34:07.557Z,1713890047.557 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2024-04-23T16:34:07.953Z,1713890047.953 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2024-04-23T16:34:07.954Z,1713890047.954 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2024-04-23T16:34:08.136Z,1713890048.136 [CTD_Seabird] Loaded 2024-04-23T16:34:08.136Z,1713890048.136 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2024-04-23T16:34:08.137Z,1713890048.137 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B964E0 2024-04-23T16:34:08.138Z,1713890048.138 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 5578 2024-04-23T16:34:08.171Z,1713890048.171 [ESPComponent] Loaded 2024-04-23T16:34:08.171Z,1713890048.171 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2024-04-23T16:34:08.191Z,1713890048.191 [PAR_Licor] Loaded 2024-04-23T16:34:08.191Z,1713890048.191 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2024-04-23T16:34:08.235Z,1713890048.235 [WetLabsBB2FL] Loaded 2024-04-23T16:34:08.235Z,1713890048.235 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2024-04-23T16:34:08.236Z,1713890048.236 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40BC64E0 2024-04-23T16:34:08.237Z,1713890048.237 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5579 2024-04-23T16:34:08.237Z,1713890048.237 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2024-04-23T16:34:08.238Z,1713890048.238 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2024-04-23T16:34:08.380Z,1713890048.380 [SBIT](DEBUG): Construct Startup Built In Test. 2024-04-23T16:34:08.389Z,1713890048.389 [SBIT] Loaded 2024-04-23T16:34:08.390Z,1713890048.390 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2024-04-23T16:34:08.393Z,1713890048.393 [IBIT](DEBUG): Construct Initiated Built In Test. 2024-04-23T16:34:08.405Z,1713890048.405 [IBIT] Loaded 2024-04-23T16:34:08.406Z,1713890048.406 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2024-04-23T16:34:08.411Z,1713890048.411 [CBIT](DEBUG): Construct Continuous Built In Test. 2024-04-23T16:34:08.516Z,1713890048.516 [CBIT] Loaded 2024-04-23T16:34:08.517Z,1713890048.517 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2024-04-23T16:34:08.517Z,1713890048.517 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2024-04-23T16:34:08.523Z,1713890048.523 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2024-04-23T16:34:08.526Z,1713890048.526 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2024-04-23T16:34:08.537Z,1713890048.537 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2024-04-23T16:34:08.538Z,1713890048.538 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C354E0 2024-04-23T16:34:08.539Z,1713890048.539 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5580 2024-04-23T16:34:08.543Z,1713890048.543 [Supervisor](INFO): Main Thread ID is 5282 2024-04-23T16:34:08.543Z,1713890048.543 [Supervisor](DEBUG): Running supervisor. 2024-04-23T16:34:08.544Z,1713890048.544 [CommandExec ThreadHandler](INFO): Handler Thread ID is 5581 2024-04-23T16:34:08.544Z,1713890048.544 [CommandExec](INFO): Initializing the command executive. 2024-04-23T16:34:08.546Z,1713890048.546 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5582 2024-04-23T16:34:08.549Z,1713890048.549 [controlThread ThreadHandler](INFO): Handler Thread ID is 5583 2024-04-23T16:34:08.550Z,1713890048.550 [controlThread](DEBUG): Initializing ControlThread 2024-04-23T16:34:08.550Z,1713890048.550 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2024-04-23T16:34:08.551Z,1713890048.551 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2024-04-23T16:34:08.551Z,1713890048.551 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2024-04-23T16:34:08.551Z,1713890048.551 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2024-04-23T16:34:08.552Z,1713890048.552 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2024-04-23T16:34:08.552Z,1713890048.552 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2024-04-23T16:34:08.554Z,1713890048.554 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2024-04-23T16:34:08.555Z,1713890048.555 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2024-04-23T16:34:08.555Z,1713890048.555 [LoopControl](DEBUG): Initialize LoopControlComponent. 2024-04-23T16:34:08.556Z,1713890048.556 [NavChart](DEBUG): Initialize NavChart Navigation. 2024-04-23T16:34:08.556Z,1713890048.556 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2024-04-23T16:34:08.565Z,1713890048.565 [SBIT](INFO): Initialize SBIT Component. 2024-04-23T16:34:08.565Z,1713890048.565 [SBIT](IMPORTANT): git: 2024-04-11 2024-04-23T16:34:08.565Z,1713890048.565 [SBIT](INFO): git hash: 8b14ac3cbe1df2c95d6505c0066306c41245f1d7 2024-04-23T16:34:08.566Z,1713890048.566 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2024-04-23T16:34:08.567Z,1713890048.567 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #1 PREEMPT Tue Sep 24 11:12:27 PDT 2019 Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021 2024-04-23T16:34:08.568Z,1713890048.568 [SBIT](INFO): Beginning SBIT in 148.000000 seconds. 2024-04-23T16:34:08.569Z,1713890048.569 [IBIT](INFO): Initialize IBIT Component. 2024-04-23T16:34:08.569Z,1713890048.569 [CBIT](DEBUG): Initialize CBIT Component. 2024-04-23T16:34:08.570Z,1713890048.570 [logger ThreadHandler](INFO): Handler Thread ID is 5584 2024-04-23T16:34:08.581Z,1713890048.581 [CBIT](DEBUG): Initialized mux pins. 2024-04-23T16:34:08.581Z,1713890048.581 [CBIT](DEBUG): Initializing the watchdog timer. 2024-04-23T16:34:08.589Z,1713890048.589 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 5585 2024-04-23T16:34:08.601Z,1713890048.601 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5586 2024-04-23T16:34:08.603Z,1713890048.603 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2024-04-23T16:34:08.605Z,1713890048.605 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2024-04-23T16:34:08.605Z,1713890048.605 [CBIT](DEBUG): Initializing heartbeat. 2024-04-23T16:34:08.613Z,1713890048.613 [Onboard ThreadHandler](INFO): Handler Thread ID is 5587 2024-04-23T16:34:08.631Z,1713890048.631 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5588 2024-04-23T16:34:08.650Z,1713890048.650 [DAT ThreadHandler](INFO): Handler Thread ID is 5589 2024-04-23T16:34:08.650Z,1713890048.650 [DAT](INFO): Powering up 2024-04-23T16:34:08.650Z,1713890048.650 [DAT](DEBUG): Initializing DAT. 2024-04-23T16:34:08.654Z,1713890048.654 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 5591 2024-04-23T16:34:08.655Z,1713890048.655 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2024-04-23T16:34:08.658Z,1713890048.658 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5593 2024-04-23T16:34:08.661Z,1713890048.661 [WetLabsBB2FL](INFO): Powering up 2024-04-23T16:34:08.662Z,1713890048.662 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5595 2024-04-23T16:34:08.665Z,1713890048.665 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2024-04-23T16:34:08.665Z,1713890048.665 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2024-04-23T16:34:08.666Z,1713890048.666 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2024-04-23T16:34:08.666Z,1713890048.666 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2024-04-23T16:34:08.666Z,1713890048.666 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2024-04-23T16:34:08.666Z,1713890048.666 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2024-04-23T16:34:08.666Z,1713890048.666 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2024-04-23T16:34:08.666Z,1713890048.666 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2024-04-23T16:34:08.677Z,1713890048.677 [CBIT](DEBUG): Deactivating GF circuits. 2024-04-23T16:34:08.677Z,1713890048.677 [CBIT](DEBUG): Deactivating emergency mode. 2024-04-23T16:34:08.716Z,1713890048.716 [CBIT](DEBUG): Backplane powered. 2024-04-23T16:34:08.718Z,1713890048.718 [MissionManager](INFO): Loading Mission from file: Missions/Startup.tl 2024-04-23T16:34:08.718Z,1713890048.718 [MissionManager](IMPORTANT): Loading Compiled TethysL script from file Missions/Startup.tx 2024-04-23T16:34:08.740Z,1713890048.740 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2024-04-23T16:34:08.757Z,1713890048.757 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. mission Startup { behavior Guidance:GoToSurface { run in progression } aggregate StartupSatComms { run in sequence readDatum { timeout duration=P1M Universal:latitude_fix } readDatum { timeout duration=P1M Universal:platform_communications } } } 2024-04-23T16:34:08.758Z,1713890048.758 [MissionManager](INFO): Loading Mission from file: Missions/Default.tl 2024-04-23T16:34:08.758Z,1713890048.758 [MissionManager](IMPORTANT): Loading Compiled TethysL script from file Missions/Default.tx 2024-04-23T16:34:08.845Z,1713890048.845 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2024-04-23T16:34:08.846Z,1713890048.846 [Default:A.Wait](DEBUG): Construct Wait. 2024-04-23T16:34:08.857Z,1713890048.857 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2024-04-23T16:34:08.907Z,1713890048.907 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2024-04-23T16:34:08.938Z,1713890048.938 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2024-04-23T16:34:08.943Z,1713890048.943 [Default:E.Execute](DEBUG): Construct Execute. 2024-04-23T16:34:08.959Z,1713890048.959 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. mission Default { arguments { ElapsedSinceDefaultStarted = 0 minute } behavior Guidance:Wait { """ Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. """ run in sequence set duration = 13 second } behavior Guidance:GoToSurface { run in progression } aggregate CheckIn { run in sequence repeat=288 readDatum id="Read_GPS" { timeout duration=P5M Universal:time_fix } readDatum id="Read_Iridium" { timeout duration=P4H { behavior Guidance:Execute { run in sequence set command = "Burn on" } syslog critical "Dropped weight due to communications timeout." } Universal:platform_communications } behavior Guidance:Wait { run in sequence set duration = 5 minute } assign in sequence ElapsedSinceDefaultStarted = elapsed ( Universal:mission_started ) syslog important "Default mission has been running for " + ElapsedSinceDefaultStarted~minute } syslog important "Restarting logs and Default mission." behavior Guidance:Execute { run in sequence set command = "restart logs" } } 2024-04-23T16:34:08.964Z,1713890048.964 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,Sonardyne_Nano,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2024-04-23T16:34:08.977Z,1713890048.977 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2024-04-23T16:34:09.037Z,1713890049.037 [Radio_Surface](INFO): Powering up 2024-04-23T16:34:09.046Z,1713890049.046 [Depth_Keller](ERROR): Pressure or depth reading out of range: 916.699524 decibar, 0.000000 m 2024-04-23T16:34:09.054Z,1713890049.054 [Power24vConverter](INFO): Powering up. 2024-04-23T16:34:09.054Z,1713890049.054 [Sonardyne_Nano](INFO): Initializing. 2024-04-23T16:34:09.081Z,1713890049.081 [DepthRateCalculator](ERROR): Depth measurement is not active 2024-04-23T16:34:09.106Z,1713890049.106 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2024-04-23T16:34:09.113Z,1713890049.113 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2024-04-23T16:34:09.114Z,1713890049.114 [ElevatorServo](DEBUG): Initializing EZServoServo. 2024-04-23T16:34:09.121Z,1713890049.121 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2024-04-23T16:34:09.122Z,1713890049.122 [MassServo](DEBUG): Initializing EZServoServo. 2024-04-23T16:34:09.137Z,1713890049.137 [MassServo](DEBUG): Initializing MassServo. 2024-04-23T16:34:09.138Z,1713890049.138 [RudderServo](DEBUG): Initializing EZServoServo. 2024-04-23T16:34:09.145Z,1713890049.145 [RudderServo](DEBUG): Initializing RudderServo. 2024-04-23T16:34:09.146Z,1713890049.146 [ThrusterHE](DEBUG): Initializing EZServoServo. 2024-04-23T16:34:09.154Z,1713890049.154 [ThrusterHE](DEBUG): Initializing ThrusterHE. 2024-04-23T16:34:10.991Z,1713890050.991 [Sonardyne_Nano](ERROR): Failed to get valid response or reached max queue size, flushing UART 2024-04-23T16:34:11.273Z,1713890051.273 [WetLabsBB2FL](INFO): Powering down 2024-04-23T16:34:12.278Z,1713890052.278 [Sonardyne_Nano](IMPORTANT): Found beacon with acoustic ID 2207 2024-04-23T16:34:14.734Z,1713890054.734 [ThrusterHE](ERROR): Zero Speed Commanded. 2024-04-23T16:34:20.501Z,1713890060.501 [DAT](INFO): DAT read: 2024-04-23T16:34:20.502Z,1713890060.502 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2024-04-23T16:34:22.265Z,1713890062.265 [DAT](INFO): DAT read: MF Frequency Band 2024-04-23T16:34:22.267Z,1713890062.267 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0 2024-04-23T16:34:22.267Z,1713890062.267 [DAT](INFO): DAT read: Apr 23 2024 16:34:17 2024-04-23T16:34:23.274Z,1713890063.274 [DAT](INFO): DAT read: Features enabled [Bearing] 2024-04-23T16:34:23.275Z,1713890063.275 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2024-04-23T16:34:23.275Z,1713890063.275 [DAT](INFO): commRate: 800 2024-04-23T16:34:25.341Z,1713890065.341 [DAT](INFO): entering command mode 2024-04-23T16:34:25.541Z,1713890065.541 [DAT](INFO): DAT read: 2024-04-23T16:34:25.542Z,1713890065.542 [DAT](INFO): DAT read: user:1> 2024-04-23T16:34:25.542Z,1713890065.542 [DAT](INFO): setting verbose to 3 2024-04-23T16:34:25.793Z,1713890065.793 [DAT](INFO): DAT read: user:1> 2024-04-23T16:34:25.794Z,1713890065.794 [DAT](INFO): DAT read: Verbose | 3 2024-04-23T16:34:25.795Z,1713890065.795 [DAT](INFO): set verbose to 3 2024-04-23T16:34:25.795Z,1713890065.795 [DAT](INFO): setting DatVerbose to 27440 2024-04-23T16:34:26.045Z,1713890066.045 [DAT](INFO): DAT read: user:2> 2024-04-23T16:34:26.046Z,1713890066.046 [DAT](INFO): DAT read: DatVerbose | 27440 2024-04-23T16:34:26.047Z,1713890066.047 [DAT](INFO): set DatVerbose to 27440 2024-04-23T16:34:26.047Z,1713890066.047 [DAT](INFO): setting transmit power to 8 2024-04-23T16:34:26.298Z,1713890066.298 [DAT](INFO): DAT read: user:3> 2024-04-23T16:34:26.298Z,1713890066.298 [DAT](INFO): DAT read: TxPower | 8 (Max) 2024-04-23T16:34:26.299Z,1713890066.299 [DAT](INFO): set transmit power to 8 2024-04-23T16:34:26.299Z,1713890066.299 [DAT](INFO): setting local address to 11 2024-04-23T16:34:26.549Z,1713890066.549 [DAT](INFO): DAT read: user:4> 2024-04-23T16:34:26.550Z,1713890066.550 [DAT](INFO): DAT read: LocalAddr | 11 2024-04-23T16:34:26.551Z,1713890066.551 [DAT](INFO): set local address to 11 2024-04-23T16:34:26.552Z,1713890066.552 [DAT](INFO): Setting time to: 16:34:26 And date to:4/23/2024 2024-04-23T16:34:26.802Z,1713890066.802 [DAT](INFO): DAT read: user:5> 2024-04-23T16:34:26.803Z,1713890066.803 [DAT](INFO): DAT read: Tue Apr 23, 2024 16:34:26 2024-04-23T16:34:26.803Z,1713890066.803 [DAT](INFO): Local DAT time set to Tue Apr 23, 2024 16:34:26 2024-04-23T16:34:37.255Z,1713890077.255 [NAL9602](INFO): Powering up NAL9602 2024-04-23T16:34:48.197Z,1713890088.197 [NAL9602](INFO): NAL9602 initialized 2024-04-23T16:35:14.822Z,1713890114.822 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:35:29.771Z,1713890129.771 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:35:44.718Z,1713890144.718 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:35:59.667Z,1713890159.667 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:36:14.211Z,1713890174.211 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:36:28.763Z,1713890188.763 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:36:37.273Z,1713890197.273 [SBIT](IMPORTANT): Beginning Startup BIT 2024-04-23T16:36:37.278Z,1713890197.278 [CBIT](IMPORTANT): Beginning ground fault scan 2024-04-23T16:36:43.717Z,1713890203.717 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:36:48.175Z,1713890208.175 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.004537 CHAN A1 (24V): -0.001836 CHAN A2 (12V): 0.000031 CHAN A3 (5V): 0.000866 CHAN B0 (3.3V): 0.000455 CHAN B1 (3.15aV): 0.000525 CHAN B2 (3.15bV): 0.000400 CHAN B3 (GND): 0.000829 OPEN: 0.004752 Full Scale: +/- 1 mA 2024-04-23T16:36:58.257Z,1713890218.257 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:37:08.893Z,1713890228.893 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2024-04-23T16:37:08.893Z,1713890228.893 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2024-04-23T16:37:08.909Z,1713890228.909 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2024-04-23T16:37:09.270Z,1713890229.270 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2024-04-23T16:37:09.270Z,1713890229.270 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2024-04-23T16:37:13.252Z,1713890233.252 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:37:28.198Z,1713890248.198 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:37:31.484Z,1713890251.484 [SBIT](IMPORTANT): SBIT PASSED 2024-04-23T16:37:31.484Z,1713890251.484 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2024-04-23T16:37:31.485Z,1713890251.485 [SBIT](IMPORTANT): AHRS_M2.loadAtStartup=1 bool; 2024-04-23T16:37:31.485Z,1713890251.485 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=12 count; 2024-04-23T16:37:31.485Z,1713890251.485 [SBIT](IMPORTANT): DVL_micro.baud=19200 bit_per_second; 2024-04-23T16:37:31.485Z,1713890251.485 [SBIT](IMPORTANT): Depth_Keller.offset=3.6 decibar; 2024-04-23T16:37:31.485Z,1713890251.485 [SBIT](IMPORTANT): ESPComponent.sampleTimeout=3 minute; 2024-04-23T16:37:31.486Z,1713890251.486 [SBIT](IMPORTANT): ESPComponent.simulateHardware=0 bool; 2024-04-23T16:37:31.486Z,1713890251.486 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=410.582899 cubic_centimeter; 2024-04-23T16:37:31.486Z,1713890251.486 [SBIT](IMPORTANT): VerticalControl.massDefault=3.2 centimeter; 2024-04-23T16:37:31.875Z,1713890251.875 [MissionManager](IMPORTANT): Started mission Startup 2024-04-23T16:37:31.875Z,1713890251.875 [Startup] Running Loop=1 2024-04-23T16:37:31.875Z,1713890251.875 [Startup](DEBUG): Aggregate::initialize Startup 2024-04-23T16:37:31.875Z,1713890251.875 [Startup:A.GoToSurface] Running Loop=1 2024-04-23T16:37:31.875Z,1713890251.875 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2024-04-23T16:37:31.876Z,1713890251.876 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2024-04-23T16:37:31.876Z,1713890251.876 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2024-04-23T16:37:31.877Z,1713890251.877 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2024-04-23T16:37:31.877Z,1713890251.877 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2024-04-23T16:37:31.878Z,1713890251.878 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2024-04-23T16:37:31.879Z,1713890251.879 [Startup:StartupSatComms] Running Loop=1 2024-04-23T16:37:31.879Z,1713890251.879 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2024-04-23T16:37:31.879Z,1713890251.879 [Startup:StartupSatComms:A] Running Loop=1 2024-04-23T16:37:32.280Z,1713890252.280 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2024-04-23T16:37:38.315Z,1713890258.315 [DVL_micro](ERROR): Failed to parse: :SA,-04.42,+03.50,008.3 2024-04-23T16:37:55.850Z,1713890275.850 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004025 2024-04-23T16:38:32.077Z,1713890312.077 [Startup:StartupSatComms:A](INFO): Timed out from 2024-04-23T16:37:31.9Z 2024-04-23T16:38:32.077Z,1713890312.077 [Startup:StartupSatComms:A] Stopped 2024-04-23T16:38:32.077Z,1713890312.077 [Startup:StartupSatComms:B] Running Loop=1 2024-04-23T16:38:32.480Z,1713890312.480 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2024-04-23T16:38:40.212Z,1713890320.212 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20240423T161646/Courier0007.lzma 2024-04-23T16:38:41.214Z,1713890321.214 [DataOverHttps](INFO): Moved sent file to Logs/20240423T161646/Courier0007.lzma.bak 2024-04-23T16:38:41.215Z,1713890321.215 [DataOverHttps](INFO): SBD MOMSN=19422386 2024-04-23T16:38:56.996Z,1713890336.996 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20240423T163357/Courier0000.lzma 2024-04-23T16:38:57.998Z,1713890337.998 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0000.lzma.bak 2024-04-23T16:38:57.998Z,1713890337.998 [DataOverHttps](INFO): SBD MOMSN=19422388 2024-04-23T16:39:15.700Z,1713890355.700 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20240423T161646/Express0008.lzma 2024-04-23T16:39:16.703Z,1713890356.703 [DataOverHttps](INFO): Moved sent file to Logs/20240423T161646/Express0008.lzma.bak 2024-04-23T16:39:16.703Z,1713890356.703 [DataOverHttps](INFO): SBD MOMSN=19422391 2024-04-23T16:39:32.301Z,1713890372.301 [Startup:StartupSatComms:B](INFO): Timed out from 2024-04-23T16:38:32.1Z 2024-04-23T16:39:32.302Z,1713890372.302 [Startup:StartupSatComms:B] Stopped 2024-04-23T16:39:32.302Z,1713890372.302 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2024-04-23T16:39:32.302Z,1713890372.302 [Startup:StartupSatComms] Stopped 2024-04-23T16:39:32.302Z,1713890372.302 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2024-04-23T16:39:32.304Z,1713890372.304 [Startup](INFO): Completed Startup 2024-04-23T16:39:32.304Z,1713890372.304 [MissionManager](INFO): Startup is completed. 2024-04-23T16:39:32.304Z,1713890372.304 [MissionManager](INFO): Uninitializing Mission Startup 2024-04-23T16:39:32.304Z,1713890372.304 [Startup] Stopped 2024-04-23T16:39:32.309Z,1713890372.309 [Startup](DEBUG): Aggregate::uninitialize Startup 2024-04-23T16:39:32.309Z,1713890372.309 [Startup:A.GoToSurface] Stopped 2024-04-23T16:39:32.309Z,1713890372.309 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2024-04-23T16:39:32.723Z,1713890372.723 [MissionManager](IMPORTANT): Started mission Default 2024-04-23T16:39:32.723Z,1713890372.723 [Default] Running Loop=1 2024-04-23T16:39:32.723Z,1713890372.723 [Default](DEBUG): Aggregate::initialize Default 2024-04-23T16:39:32.723Z,1713890372.723 [Default:B.GoToSurface] Running Loop=1 2024-04-23T16:39:32.723Z,1713890372.723 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2024-04-23T16:39:32.724Z,1713890372.724 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2024-04-23T16:39:32.724Z,1713890372.724 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2024-04-23T16:39:32.724Z,1713890372.724 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2024-04-23T16:39:32.733Z,1713890372.733 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2024-04-23T16:39:32.733Z,1713890372.733 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2024-04-23T16:39:32.733Z,1713890372.733 [Default:A.Wait] Running Loop=1 2024-04-23T16:39:32.733Z,1713890372.733 [Default:A.Wait](DEBUG): Initialize Wait Component. 2024-04-23T16:39:34.333Z,1713890374.333 [DataOverHttps](INFO): Sending 908 bytes from file Logs/20240423T163357/Express0001.lzma 2024-04-23T16:39:35.334Z,1713890375.334 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0001.lzma.bak 2024-04-23T16:39:35.334Z,1713890375.334 [DataOverHttps](INFO): SBD MOMSN=19422395 2024-04-23T16:39:46.013Z,1713890386.013 [Default:A.Wait](INFO): Done Waiting. 2024-04-23T16:39:46.013Z,1713890386.013 [Default:A.Wait] Stopped 2024-04-23T16:39:46.013Z,1713890386.013 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T16:39:46.412Z,1713890386.412 [Default:CheckIn] Running Loop=1 2024-04-23T16:39:46.412Z,1713890386.412 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T16:39:46.412Z,1713890386.412 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T16:39:46.822Z,1713890386.822 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2024-04-23T16:39:49.361Z,1713890389.361 [CommandExec](IMPORTANT): got command failComponent 2024-04-23T16:39:49.361Z,1713890389.361 [CommandExec](IMPORTANT): Failed components: 2024-04-23T16:39:49.362Z,1713890389.362 [CommandExec](IMPORTANT): No failed Components. 2024-04-23T16:39:52.059Z,1713890392.059 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T16:39:55.406Z,1713890395.406 [CommandExec](IMPORTANT): got command strobe off 2024-04-23T16:39:55.407Z,1713890395.407 [CommandExec](IMPORTANT): Deactivating strobe 2024-04-23T16:40:09.855Z,1713890409.855 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2024-04-23T16:40:09.855Z,1713890409.855 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2024-04-23T16:40:09.866Z,1713890409.866 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2024-04-23T16:40:10.322Z,1713890410.322 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2024-04-23T16:40:10.322Z,1713890410.322 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2024-04-23T16:43:10.841Z,1713890590.841 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2024-04-23T16:43:10.841Z,1713890590.841 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2024-04-23T16:43:10.851Z,1713890590.851 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2024-04-23T16:43:11.244Z,1713890591.244 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2024-04-23T16:43:11.244Z,1713890591.244 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2024-04-23T16:44:46.607Z,1713890686.607 [Default:CheckIn:Read_GPS](INFO): Timed out from 2024-04-23T16:39:46.4Z 2024-04-23T16:44:46.607Z,1713890686.607 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T16:44:46.607Z,1713890686.607 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T16:44:47.008Z,1713890687.008 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2024-04-23T16:44:49.018Z,1713890689.018 [NAL9602](FAULT): GPS failed to acquire within timeout. 2024-04-23T16:44:49.018Z,1713890689.018 [NAL9602] Data Fault, FailCount= 1 2024-04-23T16:44:49.018Z,1713890689.018 [NAL9602](ERROR): Data Fault 2024-04-23T16:44:49.035Z,1713890689.035 [CBIT](ERROR): Data Fault in component: NAL9602 2024-04-23T16:44:49.434Z,1713890689.434 [NAL9602](INFO): Powering down 2024-04-23T16:44:50.285Z,1713890690.285 [CBIT](INFO): Clearing failed state for component NAL9602 2024-04-23T16:44:50.285Z,1713890690.285 [NAL9602] No Fault, FailCount= 1 2024-04-23T16:44:53.538Z,1713890693.538 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20240423T163357/Courier0004.lzma 2024-04-23T16:44:54.538Z,1713890694.538 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0004.lzma.bak 2024-04-23T16:44:54.538Z,1713890694.538 [DataOverHttps](INFO): SBD MOMSN=19422468 2024-04-23T16:44:57.561Z,1713890697.561 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2024-04-23T16:45:02.750Z,1713890702.750 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:45:11.817Z,1713890711.817 [DataOverHttps](INFO): Sending 278 bytes from file Logs/20240423T163357/Express0005.lzma 2024-04-23T16:45:12.818Z,1713890712.818 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0005.lzma.bak 2024-04-23T16:45:12.818Z,1713890712.818 [DataOverHttps](INFO): SBD MOMSN=19422470 2024-04-23T16:45:15.706Z,1713890715.706 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T16:45:15.706Z,1713890715.706 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T16:45:15.706Z,1713890715.706 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T16:45:18.102Z,1713890718.102 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:45:19.722Z,1713890719.722 [NAL9602](INFO): Powering up NAL9602 2024-04-23T16:45:30.635Z,1713890730.635 [NAL9602](INFO): NAL9602 initialized 2024-04-23T16:45:33.051Z,1713890733.051 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:45:47.999Z,1713890747.999 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:46:02.542Z,1713890762.542 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:46:11.870Z,1713890771.870 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2024-04-23T16:46:11.870Z,1713890771.870 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2024-04-23T16:46:11.881Z,1713890771.881 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2024-04-23T16:46:12.283Z,1713890772.283 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2024-04-23T16:46:12.283Z,1713890772.283 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2024-04-23T16:46:17.490Z,1713890777.490 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:46:32.034Z,1713890792.034 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:46:46.982Z,1713890806.982 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:47:01.937Z,1713890821.937 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:47:17.282Z,1713890837.282 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:49:12.842Z,1713890952.842 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2024-04-23T16:49:12.842Z,1713890952.842 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2024-04-23T16:49:12.881Z,1713890952.881 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2024-04-23T16:49:13.291Z,1713890953.291 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2024-04-23T16:49:13.291Z,1713890953.291 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2024-04-23T16:50:16.307Z,1713891016.307 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T16:50:16.307Z,1713891016.307 [Default:CheckIn:C.Wait] Stopped 2024-04-23T16:50:16.307Z,1713891016.307 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T16:50:16.307Z,1713891016.307 [Default:CheckIn:D] Running Loop=1 2024-04-23T16:50:16.700Z,1713891016.700 [Default:CheckIn:D] Stopped 2024-04-23T16:50:16.700Z,1713891016.700 [Default:CheckIn:E] Running Loop=1 2024-04-23T16:50:17.097Z,1713891017.097 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.732944 min 2024-04-23T16:50:17.097Z,1713891017.097 [Default:CheckIn:E] Stopped 2024-04-23T16:50:17.097Z,1713891017.097 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T16:50:17.097Z,1713891017.097 [Default:CheckIn] Stopped 2024-04-23T16:50:17.097Z,1713891017.097 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T16:50:17.098Z,1713891017.098 [Default:CheckIn](INFO): Running loop #2 2024-04-23T16:50:17.098Z,1713891017.098 [Default:CheckIn] Running Loop=2 2024-04-23T16:50:17.098Z,1713891017.098 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T16:50:17.098Z,1713891017.098 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T16:52:07.779Z,1713891127.779 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165204.00,A,3648.16145,N,12147.27408,W,0.058,0.00,230424,,,A*70 2024-04-23T16:52:07.789Z,1713891127.789 [NAL9602](INFO): GPS fix at 20240423T165204: (36.802691, -121.787901) 2024-04-23T16:52:07.801Z,1713891127.801 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T16:52:07.801Z,1713891127.801 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T16:52:16.436Z,1713891136.436 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20240423T163357/Courier0007.lzma 2024-04-23T16:52:18.462Z,1713891138.462 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0007.lzma.bak 2024-04-23T16:52:18.463Z,1713891138.463 [DataOverHttps](INFO): SBD MOMSN=19422542 2024-04-23T16:52:39.974Z,1713891159.974 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T16:52:44.097Z,1713891164.097 [DataOverHttps](INFO): Sending 307 bytes from file Logs/20240423T163357/Express0008.lzma 2024-04-23T16:52:45.098Z,1713891165.098 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0008.lzma.bak 2024-04-23T16:52:45.099Z,1713891165.099 [DataOverHttps](INFO): SBD MOMSN=19422545 2024-04-23T16:52:48.097Z,1713891168.097 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T16:52:48.097Z,1713891168.097 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T16:52:48.097Z,1713891168.097 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T16:53:49.054Z,1713891229.054 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-62 in onboard configuration file). 2024-04-23T16:54:52.072Z,1713891292.072 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:55:07.021Z,1713891307.021 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:55:21.969Z,1713891321.969 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:55:36.519Z,1713891336.519 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:55:51.460Z,1713891351.460 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:56:06.816Z,1713891366.816 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:56:21.765Z,1713891381.765 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:56:36.714Z,1713891396.714 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:56:51.660Z,1713891411.660 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:57:06.205Z,1713891426.205 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T16:57:48.676Z,1713891468.676 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T16:57:48.676Z,1713891468.676 [Default:CheckIn:C.Wait] Stopped 2024-04-23T16:57:48.676Z,1713891468.676 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T16:57:48.676Z,1713891468.676 [Default:CheckIn:D] Running Loop=1 2024-04-23T16:57:49.069Z,1713891469.069 [Default:CheckIn:D] Stopped 2024-04-23T16:57:49.069Z,1713891469.069 [Default:CheckIn:E] Running Loop=1 2024-04-23T16:57:49.454Z,1713891469.454 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.272441 min 2024-04-23T16:57:49.454Z,1713891469.454 [Default:CheckIn:E] Stopped 2024-04-23T16:57:49.455Z,1713891469.455 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T16:57:49.455Z,1713891469.455 [Default:CheckIn] Stopped 2024-04-23T16:57:49.455Z,1713891469.455 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T16:57:49.455Z,1713891469.455 [Default:CheckIn](INFO): Running loop #3 2024-04-23T16:57:49.455Z,1713891469.455 [Default:CheckIn] Running Loop=3 2024-04-23T16:57:49.455Z,1713891469.455 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T16:57:49.455Z,1713891469.455 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T16:57:51.464Z,1713891471.464 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165750.00,A,3648.16583,N,12147.27926,W,0.525,0.00,230424,,,A*74 2024-04-23T16:57:51.468Z,1713891471.468 [NAL9602](INFO): GPS fix at 20240423T165750: (36.802764, -121.787988) 2024-04-23T16:57:51.529Z,1713891471.529 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T16:57:51.529Z,1713891471.529 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T16:58:00.228Z,1713891480.228 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0010.lzma 2024-04-23T16:58:01.231Z,1713891481.231 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0010.lzma.bak 2024-04-23T16:58:01.231Z,1713891481.231 [DataOverHttps](INFO): SBD MOMSN=19422549 2024-04-23T16:58:20.096Z,1713891500.096 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20240423T163357/Express0011.lzma 2024-04-23T16:58:21.090Z,1713891501.090 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0011.lzma.bak 2024-04-23T16:58:21.091Z,1713891501.091 [DataOverHttps](INFO): SBD MOMSN=19422552 2024-04-23T16:58:25.894Z,1713891505.894 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T16:58:25.894Z,1713891505.894 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T16:58:25.894Z,1713891505.894 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:02:53.295Z,1713891773.295 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:03:24.020Z,1713891804.020 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:03:26.446Z,1713891806.446 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:03:26.446Z,1713891806.446 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:03:26.446Z,1713891806.446 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:03:26.446Z,1713891806.446 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:03:26.854Z,1713891806.854 [Default:CheckIn:D] Stopped 2024-04-23T17:03:26.855Z,1713891806.855 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:03:27.269Z,1713891807.269 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.902191 min 2024-04-23T17:03:27.269Z,1713891807.269 [Default:CheckIn:E] Stopped 2024-04-23T17:03:27.269Z,1713891807.269 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:03:27.269Z,1713891807.269 [Default:CheckIn] Stopped 2024-04-23T17:03:27.269Z,1713891807.269 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:03:27.270Z,1713891807.270 [Default:CheckIn](INFO): Running loop #4 2024-04-23T17:03:27.270Z,1713891807.270 [Default:CheckIn] Running Loop=4 2024-04-23T17:03:27.270Z,1713891807.270 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:03:27.270Z,1713891807.270 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:03:29.253Z,1713891809.253 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170328.00,A,3648.16799,N,12147.28038,W,0.330,171.50,230424,,,A*7B 2024-04-23T17:03:29.255Z,1713891809.255 [NAL9602](INFO): GPS fix at 20240423T170328: (36.802800, -121.788006) 2024-04-23T17:03:29.266Z,1713891809.266 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:03:29.266Z,1713891809.266 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:03:38.344Z,1713891818.344 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0013.lzma 2024-04-23T17:03:39.346Z,1713891819.346 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0013.lzma.bak 2024-04-23T17:03:39.347Z,1713891819.347 [DataOverHttps](INFO): SBD MOMSN=19422597 2024-04-23T17:03:57.932Z,1713891837.932 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0014.lzma 2024-04-23T17:03:58.935Z,1713891838.935 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0014.lzma.bak 2024-04-23T17:03:58.935Z,1713891838.935 [DataOverHttps](INFO): SBD MOMSN=19422600 2024-04-23T17:04:02.034Z,1713891842.034 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:04:02.034Z,1713891842.034 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:04:02.034Z,1713891842.034 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:04:42.816Z,1713891882.816 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T17:04:57.752Z,1713891897.752 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T17:05:09.469Z,1713891909.469 [BPC1](INFO): Calculating totals. Valid battery stick count: 43. Valid reserve battery stick count: 4. 2024-04-23T17:05:09.473Z,1713891909.473 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle. 2024-04-23T17:08:31.487Z,1713892111.487 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:09:02.186Z,1713892142.186 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:09:02.609Z,1713892142.609 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:09:02.609Z,1713892142.609 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:09:02.609Z,1713892142.609 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:09:02.609Z,1713892142.609 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:09:03.024Z,1713892143.024 [Default:CheckIn:D] Stopped 2024-04-23T17:09:03.024Z,1713892143.024 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:09:03.413Z,1713892143.413 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.505009 min 2024-04-23T17:09:03.413Z,1713892143.413 [Default:CheckIn:E] Stopped 2024-04-23T17:09:03.413Z,1713892143.413 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:09:03.413Z,1713892143.413 [Default:CheckIn] Stopped 2024-04-23T17:09:03.413Z,1713892143.413 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:09:03.413Z,1713892143.413 [Default:CheckIn](INFO): Running loop #5 2024-04-23T17:09:03.413Z,1713892143.413 [Default:CheckIn] Running Loop=5 2024-04-23T17:09:03.414Z,1713892143.414 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:09:03.414Z,1713892143.414 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:09:05.443Z,1713892145.443 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170904.00,A,3648.15649,N,12147.28377,W,0.058,185.51,230424,,,A*7F 2024-04-23T17:09:05.445Z,1713892145.445 [NAL9602](INFO): GPS fix at 20240423T170904: (36.802608, -121.788063) 2024-04-23T17:09:05.456Z,1713892145.456 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:09:05.456Z,1713892145.456 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:09:13.176Z,1713892153.176 [DataOverHttps](INFO): Sending 200 bytes from file Logs/20240423T163357/Courier0016.lzma 2024-04-23T17:09:14.178Z,1713892154.178 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0016.lzma.bak 2024-04-23T17:09:14.178Z,1713892154.178 [DataOverHttps](INFO): SBD MOMSN=19422604 2024-04-23T17:09:32.134Z,1713892172.134 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20240423T163357/Express0017.lzma 2024-04-23T17:09:33.122Z,1713892173.122 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0017.lzma.bak 2024-04-23T17:09:33.123Z,1713892173.123 [DataOverHttps](INFO): SBD MOMSN=19422607 2024-04-23T17:09:36.122Z,1713892176.122 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T17:09:36.197Z,1713892176.197 [NAL9602](ERROR): received: +CSQ:0 OK 2024-04-23T17:09:36.245Z,1713892176.245 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:09:36.245Z,1713892176.245 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:09:36.245Z,1713892176.245 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:14:01.676Z,1713892441.676 [CommandExec](IMPORTANT): got command failComponent 2024-04-23T17:14:01.677Z,1713892441.677 [CommandExec](IMPORTANT): Failed components: 2024-04-23T17:14:01.678Z,1713892441.678 [CommandExec](IMPORTANT): No failed Components. 2024-04-23T17:14:07.214Z,1713892447.214 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:14:36.721Z,1713892476.721 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:14:36.721Z,1713892476.721 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:14:36.721Z,1713892476.721 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:14:36.721Z,1713892476.721 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:14:37.141Z,1713892477.141 [Default:CheckIn:D] Stopped 2024-04-23T17:14:37.141Z,1713892477.141 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:14:37.546Z,1713892477.546 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.073633 min 2024-04-23T17:14:37.546Z,1713892477.546 [Default:CheckIn:E] Stopped 2024-04-23T17:14:37.546Z,1713892477.546 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:14:37.547Z,1713892477.547 [Default:CheckIn] Stopped 2024-04-23T17:14:37.547Z,1713892477.547 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:14:37.547Z,1713892477.547 [Default:CheckIn](INFO): Running loop #6 2024-04-23T17:14:37.547Z,1713892477.547 [Default:CheckIn] Running Loop=6 2024-04-23T17:14:37.547Z,1713892477.547 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:14:37.547Z,1713892477.547 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:14:37.914Z,1713892477.914 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:14:39.532Z,1713892479.532 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171438.00,A,3648.15496,N,12147.28160,W,0.311,194.53,230424,,,A*74 2024-04-23T17:14:39.534Z,1713892479.534 [NAL9602](INFO): GPS fix at 20240423T171438: (36.802583, -121.788027) 2024-04-23T17:14:39.575Z,1713892479.575 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:14:39.575Z,1713892479.575 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:14:48.312Z,1713892488.312 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0019.lzma 2024-04-23T17:14:49.314Z,1713892489.314 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0019.lzma.bak 2024-04-23T17:14:49.314Z,1713892489.314 [DataOverHttps](INFO): SBD MOMSN=19422655 2024-04-23T17:15:07.363Z,1713892507.363 [DataOverHttps](INFO): Sending 256 bytes from file Logs/20240423T163357/Express0020.lzma 2024-04-23T17:15:08.362Z,1713892508.362 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0020.lzma.bak 2024-04-23T17:15:08.363Z,1713892508.363 [DataOverHttps](INFO): SBD MOMSN=19422658 2024-04-23T17:15:10.231Z,1713892510.231 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T17:15:10.313Z,1713892510.313 [NAL9602](ERROR): received: +CSQ:0 OK 2024-04-23T17:15:11.480Z,1713892511.480 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:15:11.481Z,1713892511.481 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:15:11.481Z,1713892511.481 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:19:41.356Z,1713892781.356 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:20:12.062Z,1713892812.062 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:20:12.098Z,1713892812.098 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:20:12.098Z,1713892812.098 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:20:12.098Z,1713892812.098 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:20:12.098Z,1713892812.098 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:20:12.476Z,1713892812.476 [Default:CheckIn:D] Stopped 2024-04-23T17:20:12.476Z,1713892812.476 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:20:12.877Z,1713892812.877 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.662553 min 2024-04-23T17:20:12.877Z,1713892812.877 [Default:CheckIn:E] Stopped 2024-04-23T17:20:12.877Z,1713892812.877 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:20:12.877Z,1713892812.877 [Default:CheckIn] Stopped 2024-04-23T17:20:12.877Z,1713892812.877 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:20:12.877Z,1713892812.877 [Default:CheckIn](INFO): Running loop #7 2024-04-23T17:20:12.877Z,1713892812.877 [Default:CheckIn] Running Loop=7 2024-04-23T17:20:12.878Z,1713892812.878 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:20:12.878Z,1713892812.878 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:20:14.896Z,1713892814.896 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172014.00,A,3648.16246,N,12147.28733,W,0.253,154.98,230424,,,A*79 2024-04-23T17:20:14.902Z,1713892814.902 [NAL9602](INFO): GPS fix at 20240423T172014: (36.802708, -121.788122) 2024-04-23T17:20:14.917Z,1713892814.917 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:20:14.917Z,1713892814.917 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:20:26.812Z,1713892826.812 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0022.lzma 2024-04-23T17:20:27.815Z,1713892827.815 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0022.lzma.bak 2024-04-23T17:20:27.815Z,1713892827.815 [DataOverHttps](INFO): SBD MOMSN=19422667 2024-04-23T17:20:45.654Z,1713892845.654 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T17:20:45.732Z,1713892845.732 [NAL9602](ERROR): received: +CSQ:0 OK 2024-04-23T17:20:46.212Z,1713892846.212 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20240423T163357/Express0023.lzma 2024-04-23T17:20:47.214Z,1713892847.214 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0023.lzma.bak 2024-04-23T17:20:47.215Z,1713892847.215 [DataOverHttps](INFO): SBD MOMSN=19422670 2024-04-23T17:20:50.541Z,1713892850.541 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:20:50.541Z,1713892850.541 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:20:50.541Z,1713892850.541 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:22:26.376Z,1713892946.376 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 200 cubic_centimeter 2024-04-23T17:22:26.381Z,1713892946.381 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.buoyancyAction" handled in the control thread. 2024-04-23T17:22:26.741Z,1713892946.741 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,Sonardyne_Nano,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.buoyancyAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2024-04-23T17:25:17.549Z,1713893117.549 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:25:43.885Z,1713893143.885 [CommandExec](IMPORTANT): got command get VerticalControl.buoyancyAction 2024-04-23T17:25:43.886Z,1713893143.886 [CommandExec](IMPORTANT): VerticalControl.buoyancyAction 200.000000 cc 2024-04-23T17:25:48.259Z,1713893148.259 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:25:51.126Z,1713893151.126 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:25:51.126Z,1713893151.126 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:25:51.126Z,1713893151.126 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:25:51.126Z,1713893151.126 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:25:51.497Z,1713893151.497 [Default:CheckIn:D] Stopped 2024-04-23T17:25:51.497Z,1713893151.497 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:25:51.906Z,1713893151.906 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.312899 min 2024-04-23T17:25:51.906Z,1713893151.906 [Default:CheckIn:E] Stopped 2024-04-23T17:25:51.906Z,1713893151.906 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:25:51.906Z,1713893151.906 [Default:CheckIn] Stopped 2024-04-23T17:25:51.907Z,1713893151.907 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:25:51.907Z,1713893151.907 [Default:CheckIn](INFO): Running loop #8 2024-04-23T17:25:51.907Z,1713893151.907 [Default:CheckIn] Running Loop=8 2024-04-23T17:25:51.907Z,1713893151.907 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:25:51.907Z,1713893151.907 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:25:53.926Z,1713893153.926 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172553.00,A,3648.15759,N,12147.28344,W,0.214,154.98,230424,,,A*70 2024-04-23T17:25:53.928Z,1713893153.928 [NAL9602](INFO): GPS fix at 20240423T172553: (36.802627, -121.788057) 2024-04-23T17:25:53.940Z,1713893153.940 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:25:53.940Z,1713893153.940 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:26:02.936Z,1713893162.936 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0025.lzma 2024-04-23T17:26:03.938Z,1713893163.938 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0025.lzma.bak 2024-04-23T17:26:03.939Z,1713893163.939 [DataOverHttps](INFO): SBD MOMSN=19422722 2024-04-23T17:26:24.663Z,1713893184.663 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T17:26:24.745Z,1713893184.745 [NAL9602](ERROR): received: +CSQ:0 OK 2024-04-23T17:26:24.829Z,1713893184.829 [DataOverHttps](INFO): Sending 304 bytes from file Logs/20240423T163357/Express0026.lzma 2024-04-23T17:26:25.831Z,1713893185.831 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0026.lzma.bak 2024-04-23T17:26:25.831Z,1713893185.831 [DataOverHttps](INFO): SBD MOMSN=19422725 2024-04-23T17:26:30.405Z,1713893190.405 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:26:30.405Z,1713893190.405 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:26:30.405Z,1713893190.405 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:30:56.640Z,1713893456.640 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:31:09.570Z,1713893469.570 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.99,+9999.99 2024-04-23T17:31:27.344Z,1713893487.344 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:31:31.010Z,1713893491.010 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:31:31.010Z,1713893491.010 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:31:31.010Z,1713893491.010 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:31:31.010Z,1713893491.010 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:31:31.416Z,1713893491.416 [Default:CheckIn:D] Stopped 2024-04-23T17:31:31.416Z,1713893491.416 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:31:31.834Z,1713893491.834 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 51.978210 min 2024-04-23T17:31:31.834Z,1713893491.834 [Default:CheckIn:E] Stopped 2024-04-23T17:31:31.834Z,1713893491.834 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:31:31.834Z,1713893491.834 [Default:CheckIn] Stopped 2024-04-23T17:31:31.834Z,1713893491.834 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:31:31.834Z,1713893491.834 [Default:CheckIn](INFO): Running loop #9 2024-04-23T17:31:31.834Z,1713893491.834 [Default:CheckIn] Running Loop=9 2024-04-23T17:31:31.835Z,1713893491.835 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:31:31.835Z,1713893491.835 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:31:33.814Z,1713893493.814 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173133.00,A,3648.15817,N,12147.28542,W,0.758,0.00,230424,,,A*7A 2024-04-23T17:31:33.816Z,1713893493.816 [NAL9602](INFO): GPS fix at 20240423T173133: (36.802636, -121.788090) 2024-04-23T17:31:33.848Z,1713893493.848 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:31:33.848Z,1713893493.848 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:31:42.756Z,1713893502.756 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0028.lzma 2024-04-23T17:31:43.759Z,1713893503.759 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0028.lzma.bak 2024-04-23T17:31:43.760Z,1713893503.760 [DataOverHttps](INFO): SBD MOMSN=19422732 2024-04-23T17:32:02.008Z,1713893522.008 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0029.lzma 2024-04-23T17:32:03.010Z,1713893523.010 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0029.lzma.bak 2024-04-23T17:32:03.011Z,1713893523.011 [DataOverHttps](INFO): SBD MOMSN=19422735 2024-04-23T17:32:06.149Z,1713893526.149 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:32:06.150Z,1713893526.150 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:32:06.150Z,1713893526.150 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:35:45.233Z,1713893745.233 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T17:35:45.233Z,1713893745.233 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T17:36:36.523Z,1713893796.523 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:37:06.875Z,1713893826.875 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:37:06.875Z,1713893826.875 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:37:06.875Z,1713893826.875 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:37:06.875Z,1713893826.875 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:37:07.236Z,1713893827.236 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:37:07.255Z,1713893827.255 [Default:CheckIn:D] Stopped 2024-04-23T17:37:07.255Z,1713893827.255 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 57.575529 min 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn:E] Stopped 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn] Stopped 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn](INFO): Running loop #10 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn] Running Loop=10 2024-04-23T17:37:07.664Z,1713893827.664 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:37:07.665Z,1713893827.665 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:37:09.653Z,1713893829.653 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173708.00,A,3648.16175,N,12147.28216,W,0.330,0.00,230424,,,A*76 2024-04-23T17:37:09.655Z,1713893829.655 [NAL9602](INFO): GPS fix at 20240423T173708: (36.802696, -121.788036) 2024-04-23T17:37:09.666Z,1713893829.666 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:37:09.666Z,1713893829.666 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:37:18.230Z,1713893838.230 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0031.lzma 2024-04-23T17:37:18.650Z,1713893838.650 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0031.lzma.bak 2024-04-23T17:37:18.651Z,1713893838.651 [DataOverHttps](INFO): SBD MOMSN=19422782 2024-04-23T17:37:36.415Z,1713893856.415 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20240423T163357/Express0032.lzma 2024-04-23T17:37:37.414Z,1713893857.414 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0032.lzma.bak 2024-04-23T17:37:37.415Z,1713893857.415 [DataOverHttps](INFO): SBD MOMSN=19422785 2024-04-23T17:37:40.362Z,1713893860.362 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T17:37:40.437Z,1713893860.437 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T17:37:40.500Z,1713893860.500 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:37:40.511Z,1713893860.511 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:37:40.511Z,1713893860.511 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:42:12.300Z,1713894132.300 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:42:40.978Z,1713894160.978 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:42:40.978Z,1713894160.978 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:42:40.979Z,1713894160.979 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:42:40.979Z,1713894160.979 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:42:41.397Z,1713894161.397 [Default:CheckIn:D] Stopped 2024-04-23T17:42:41.397Z,1713894161.397 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:42:41.805Z,1713894161.805 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.144560 min 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn:E] Stopped 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn] Stopped 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn](INFO): Running loop #11 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn] Running Loop=11 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:42:41.806Z,1713894161.806 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:42:43.796Z,1713894163.796 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174243.00,A,3648.16589,N,12147.28269,W,0.525,42.85,230424,,,A*4D 2024-04-23T17:42:43.799Z,1713894163.799 [NAL9602](INFO): GPS fix at 20240423T174243: (36.802765, -121.788045) 2024-04-23T17:42:43.810Z,1713894163.810 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:42:43.810Z,1713894163.810 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:42:52.348Z,1713894172.348 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0034.lzma 2024-04-23T17:42:53.350Z,1713894173.350 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0034.lzma.bak 2024-04-23T17:42:53.351Z,1713894173.351 [DataOverHttps](INFO): SBD MOMSN=19422832 2024-04-23T17:43:12.640Z,1713894192.640 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20240423T163357/Express0035.lzma 2024-04-23T17:43:13.642Z,1713894193.642 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0035.lzma.bak 2024-04-23T17:43:13.643Z,1713894193.643 [DataOverHttps](INFO): SBD MOMSN=19422835 2024-04-23T17:43:16.522Z,1713894196.522 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:43:16.961Z,1713894196.961 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:43:16.961Z,1713894196.961 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:43:16.961Z,1713894196.961 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:48:17.542Z,1713894497.542 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:48:17.542Z,1713894497.542 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:48:17.542Z,1713894497.542 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:48:17.542Z,1713894497.542 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:48:17.951Z,1713894497.951 [Default:CheckIn:D] Stopped 2024-04-23T17:48:17.951Z,1713894497.951 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:48:18.367Z,1713894498.367 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 68.753792 min 2024-04-23T17:48:18.367Z,1713894498.367 [Default:CheckIn:E] Stopped 2024-04-23T17:48:18.367Z,1713894498.367 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:48:18.367Z,1713894498.367 [Default:CheckIn] Stopped 2024-04-23T17:48:18.367Z,1713894498.367 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:48:18.367Z,1713894498.367 [Default:CheckIn](INFO): Running loop #12 2024-04-23T17:48:18.367Z,1713894498.367 [Default:CheckIn] Running Loop=12 2024-04-23T17:48:18.368Z,1713894498.368 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:48:18.368Z,1713894498.368 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:48:20.336Z,1713894500.336 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174819.00,A,3648.16220,N,12147.28459,W,0.447,42.85,230424,,,A*4C 2024-04-23T17:48:20.338Z,1713894500.338 [NAL9602](INFO): GPS fix at 20240423T174819: (36.802703, -121.788077) 2024-04-23T17:48:20.378Z,1713894500.378 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:48:20.378Z,1713894500.378 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:48:31.648Z,1713894511.648 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0037.lzma 2024-04-23T17:48:32.650Z,1713894512.650 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0037.lzma.bak 2024-04-23T17:48:32.651Z,1713894512.651 [DataOverHttps](INFO): SBD MOMSN=19422839 2024-04-23T17:48:51.964Z,1713894531.964 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20240423T163357/Express0038.lzma 2024-04-23T17:48:52.966Z,1713894532.966 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0038.lzma.bak 2024-04-23T17:48:52.967Z,1713894532.967 [DataOverHttps](INFO): SBD MOMSN=19422842 2024-04-23T17:48:56.273Z,1713894536.273 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:48:56.273Z,1713894536.273 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:48:56.273Z,1713894536.273 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:53:22.126Z,1713894802.126 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:53:52.834Z,1713894832.834 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:53:56.877Z,1713894836.877 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:53:56.877Z,1713894836.877 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:53:56.877Z,1713894836.877 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:53:56.878Z,1713894836.878 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:53:57.291Z,1713894837.291 [Default:CheckIn:D] Stopped 2024-04-23T17:53:57.291Z,1713894837.291 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:53:57.712Z,1713894837.712 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 74.409465 min 2024-04-23T17:53:57.712Z,1713894837.712 [Default:CheckIn:E] Stopped 2024-04-23T17:53:57.713Z,1713894837.713 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:53:57.713Z,1713894837.713 [Default:CheckIn] Stopped 2024-04-23T17:53:57.713Z,1713894837.713 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:53:57.713Z,1713894837.713 [Default:CheckIn](INFO): Running loop #13 2024-04-23T17:53:57.713Z,1713894837.713 [Default:CheckIn] Running Loop=13 2024-04-23T17:53:57.713Z,1713894837.713 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:53:57.713Z,1713894837.713 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:53:59.696Z,1713894839.696 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175359.00,A,3648.15392,N,12147.29187,W,0.039,350.31,230424,,,A*7C 2024-04-23T17:53:59.698Z,1713894839.698 [NAL9602](INFO): GPS fix at 20240423T175359: (36.802565, -121.788198) 2024-04-23T17:53:59.710Z,1713894839.710 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:53:59.710Z,1713894839.710 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:54:07.936Z,1713894847.936 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0040.lzma 2024-04-23T17:54:08.939Z,1713894848.939 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0040.lzma.bak 2024-04-23T17:54:08.939Z,1713894848.939 [DataOverHttps](INFO): SBD MOMSN=19422893 2024-04-23T17:54:30.108Z,1713894870.108 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20240423T163357/Express0041.lzma 2024-04-23T17:54:30.479Z,1713894870.479 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T17:54:30.560Z,1713894870.560 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T17:54:31.110Z,1713894871.110 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0041.lzma.bak 2024-04-23T17:54:31.111Z,1713894871.111 [DataOverHttps](INFO): SBD MOMSN=19422896 2024-04-23T17:54:34.153Z,1713894874.153 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T17:54:34.153Z,1713894874.153 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T17:54:34.154Z,1713894874.154 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T17:59:02.430Z,1713895142.430 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T17:59:33.130Z,1713895173.130 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T17:59:34.765Z,1713895174.765 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T17:59:34.766Z,1713895174.766 [Default:CheckIn:C.Wait] Stopped 2024-04-23T17:59:34.766Z,1713895174.766 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T17:59:34.766Z,1713895174.766 [Default:CheckIn:D] Running Loop=1 2024-04-23T17:59:35.157Z,1713895175.157 [Default:CheckIn:D] Stopped 2024-04-23T17:59:35.157Z,1713895175.157 [Default:CheckIn:E] Running Loop=1 2024-04-23T17:59:35.573Z,1713895175.573 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.040568 min 2024-04-23T17:59:35.573Z,1713895175.573 [Default:CheckIn:E] Stopped 2024-04-23T17:59:35.573Z,1713895175.573 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T17:59:35.573Z,1713895175.573 [Default:CheckIn] Stopped 2024-04-23T17:59:35.574Z,1713895175.574 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T17:59:35.574Z,1713895175.574 [Default:CheckIn](INFO): Running loop #14 2024-04-23T17:59:35.574Z,1713895175.574 [Default:CheckIn] Running Loop=14 2024-04-23T17:59:35.574Z,1713895175.574 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T17:59:35.574Z,1713895175.574 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T17:59:37.576Z,1713895177.576 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175936.00,A,3648.15934,N,12147.28264,W,0.641,350.31,230424,,,A*7F 2024-04-23T17:59:37.578Z,1713895177.578 [NAL9602](INFO): GPS fix at 20240423T175936: (36.802656, -121.788044) 2024-04-23T17:59:37.613Z,1713895177.613 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T17:59:37.613Z,1713895177.613 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T17:59:45.892Z,1713895185.892 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0043.lzma 2024-04-23T17:59:46.894Z,1713895186.894 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0043.lzma.bak 2024-04-23T17:59:46.895Z,1713895186.895 [DataOverHttps](INFO): SBD MOMSN=19422900 2024-04-23T18:00:05.208Z,1713895205.208 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20240423T163357/Express0044.lzma 2024-04-23T18:00:06.212Z,1713895206.212 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0044.lzma.bak 2024-04-23T18:00:06.212Z,1713895206.212 [DataOverHttps](INFO): SBD MOMSN=19422903 2024-04-23T18:00:09.127Z,1713895209.127 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:00:09.128Z,1713895209.128 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:00:09.128Z,1713895209.128 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:03:02.465Z,1713895382.465 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T18:03:02.465Z,1713895382.465 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T18:03:30.762Z,1713895410.762 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T18:03:30.762Z,1713895410.762 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T18:03:59.038Z,1713895439.038 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T18:03:59.038Z,1713895439.038 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T18:04:39.443Z,1713895479.443 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:05:09.749Z,1713895509.749 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:05:09.749Z,1713895509.749 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:05:09.749Z,1713895509.749 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:05:09.749Z,1713895509.749 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:05:10.162Z,1713895510.162 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:05:10.175Z,1713895510.175 [Default:CheckIn:D] Stopped 2024-04-23T18:05:10.175Z,1713895510.175 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:05:10.545Z,1713895510.545 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 85.624194 min 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn:E] Stopped 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn] Stopped 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn](INFO): Running loop #15 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn] Running Loop=15 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:05:10.546Z,1713895510.546 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:05:12.561Z,1713895512.561 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180511.00,A,3648.16033,N,12147.28576,W,0.156,0.00,230424,,,A*70 2024-04-23T18:05:12.563Z,1713895512.563 [NAL9602](INFO): GPS fix at 20240423T180511: (36.802672, -121.788096) 2024-04-23T18:05:12.574Z,1713895512.574 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:05:12.575Z,1713895512.575 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:05:21.160Z,1713895521.160 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0046.lzma 2024-04-23T18:05:22.163Z,1713895522.163 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0046.lzma.bak 2024-04-23T18:05:22.163Z,1713895522.163 [DataOverHttps](INFO): SBD MOMSN=19422950 2024-04-23T18:05:40.956Z,1713895540.956 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20240423T163357/Express0047.lzma 2024-04-23T18:05:41.962Z,1713895541.962 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0047.lzma.bak 2024-04-23T18:05:41.962Z,1713895541.962 [DataOverHttps](INFO): SBD MOMSN=19422953 2024-04-23T18:05:43.284Z,1713895543.284 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:05:43.365Z,1713895543.365 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:05:44.910Z,1713895544.910 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:05:44.910Z,1713895544.910 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:05:44.910Z,1713895544.910 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:07:39.635Z,1713895659.635 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2024-04-23T18:07:42.045Z,1713895662.045 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2024-04-23T18:10:14.443Z,1713895814.443 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:10:45.175Z,1713895845.175 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:10:45.614Z,1713895845.614 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:10:45.614Z,1713895845.614 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:10:45.614Z,1713895845.614 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:10:45.614Z,1713895845.614 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:10:45.971Z,1713895845.971 [Default:CheckIn:D] Stopped 2024-04-23T18:10:45.971Z,1713895845.971 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:10:46.390Z,1713895846.390 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 91.220801 min 2024-04-23T18:10:46.390Z,1713895846.390 [Default:CheckIn:E] Stopped 2024-04-23T18:10:46.390Z,1713895846.390 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:10:46.390Z,1713895846.390 [Default:CheckIn] Stopped 2024-04-23T18:10:46.390Z,1713895846.390 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:10:46.391Z,1713895846.391 [Default:CheckIn](INFO): Running loop #16 2024-04-23T18:10:46.391Z,1713895846.391 [Default:CheckIn] Running Loop=16 2024-04-23T18:10:46.391Z,1713895846.391 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:10:46.391Z,1713895846.391 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:10:48.405Z,1713895848.405 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181047.00,A,3648.16079,N,12147.28875,W,0.272,45.99,230424,,,A*43 2024-04-23T18:10:48.407Z,1713895848.407 [NAL9602](INFO): GPS fix at 20240423T181047: (36.802680, -121.788146) 2024-04-23T18:10:48.419Z,1713895848.419 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:10:48.419Z,1713895848.419 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:10:56.876Z,1713895856.876 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0049.lzma 2024-04-23T18:10:58.287Z,1713895858.287 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0049.lzma.bak 2024-04-23T18:10:58.287Z,1713895858.287 [DataOverHttps](INFO): SBD MOMSN=19422957 2024-04-23T18:11:18.257Z,1713895878.257 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0050.lzma 2024-04-23T18:11:19.122Z,1713895879.122 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:11:19.205Z,1713895879.205 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:11:19.291Z,1713895879.291 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0050.lzma.bak 2024-04-23T18:11:19.291Z,1713895879.291 [DataOverHttps](INFO): SBD MOMSN=19422960 2024-04-23T18:11:22.439Z,1713895882.439 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:11:22.439Z,1713895882.439 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:11:22.439Z,1713895882.439 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:12:06.800Z,1713895926.800 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T18:12:06.800Z,1713895926.800 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T18:12:46.384Z,1713895966.384 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:13:01.333Z,1713895981.333 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:13:16.684Z,1713895996.684 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:13:31.634Z,1713896011.634 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:13:46.588Z,1713896026.588 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:14:01.125Z,1713896041.125 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:14:15.669Z,1713896055.669 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:14:30.630Z,1713896070.630 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:14:45.162Z,1713896085.162 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:15:00.108Z,1713896100.108 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:15:50.223Z,1713896150.223 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:16:20.938Z,1713896180.938 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:16:23.018Z,1713896183.018 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:16:23.018Z,1713896183.018 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:16:23.018Z,1713896183.018 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:16:23.018Z,1713896183.018 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:16:23.454Z,1713896183.454 [Default:CheckIn:D] Stopped 2024-04-23T18:16:23.454Z,1713896183.454 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 96.845516 min 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn:E] Stopped 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn] Stopped 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn](INFO): Running loop #17 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn] Running Loop=17 2024-04-23T18:16:23.859Z,1713896183.859 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:16:23.860Z,1713896183.860 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:16:25.832Z,1713896185.832 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181625.00,A,3648.16554,N,12147.28791,W,0.194,290.72,230424,,,A*7A 2024-04-23T18:16:25.835Z,1713896185.835 [NAL9602](INFO): GPS fix at 20240423T181625: (36.802759, -121.788132) 2024-04-23T18:16:25.854Z,1713896185.854 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:16:25.854Z,1713896185.854 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:16:28.502Z,1713896188.502 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0052.lzma 2024-04-23T18:16:29.506Z,1713896189.506 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0052.lzma.bak 2024-04-23T18:16:29.507Z,1713896189.507 [DataOverHttps](INFO): SBD MOMSN=19423022 2024-04-23T18:16:48.937Z,1713896208.937 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20240423T163357/Express0053.lzma 2024-04-23T18:16:49.938Z,1713896209.938 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0053.lzma.bak 2024-04-23T18:16:49.939Z,1713896209.939 [DataOverHttps](INFO): SBD MOMSN=19423025 2024-04-23T18:16:52.918Z,1713896212.918 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:16:52.918Z,1713896212.918 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:16:52.918Z,1713896212.918 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:16:56.557Z,1713896216.557 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:16:56.632Z,1713896216.632 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:20:56.143Z,1713896456.143 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T18:20:56.144Z,1713896456.144 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T18:21:28.471Z,1713896488.471 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:21:53.548Z,1713896513.548 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:21:53.548Z,1713896513.548 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:21:53.548Z,1713896513.548 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:21:53.548Z,1713896513.548 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:21:53.937Z,1713896513.937 [Default:CheckIn:D] Stopped 2024-04-23T18:21:53.937Z,1713896513.937 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:21:54.341Z,1713896514.341 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 102.353564 min 2024-04-23T18:21:54.341Z,1713896514.341 [Default:CheckIn:E] Stopped 2024-04-23T18:21:54.342Z,1713896514.342 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:21:54.342Z,1713896514.342 [Default:CheckIn] Stopped 2024-04-23T18:21:54.342Z,1713896514.342 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:21:54.342Z,1713896514.342 [Default:CheckIn](INFO): Running loop #18 2024-04-23T18:21:54.342Z,1713896514.342 [Default:CheckIn] Running Loop=18 2024-04-23T18:21:54.342Z,1713896514.342 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:21:54.342Z,1713896514.342 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:21:56.375Z,1713896516.375 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182155.00,A,3648.16436,N,12147.27649,W,0.564,290.72,230424,,,A*7C 2024-04-23T18:21:56.377Z,1713896516.377 [NAL9602](INFO): GPS fix at 20240423T182155: (36.802739, -121.787942) 2024-04-23T18:21:56.426Z,1713896516.426 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:21:56.426Z,1713896516.426 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:22:04.776Z,1713896524.776 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0055.lzma 2024-04-23T18:22:05.778Z,1713896525.778 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0055.lzma.bak 2024-04-23T18:22:05.779Z,1713896525.779 [DataOverHttps](INFO): SBD MOMSN=19423029 2024-04-23T18:22:28.061Z,1713896548.061 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0056.lzma 2024-04-23T18:22:28.327Z,1713896548.327 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:22:29.063Z,1713896549.063 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0056.lzma.bak 2024-04-23T18:22:29.063Z,1713896549.063 [DataOverHttps](INFO): SBD MOMSN=19423032 2024-04-23T18:22:31.989Z,1713896551.989 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:22:31.990Z,1713896551.990 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:22:31.990Z,1713896551.990 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:22:32.769Z,1713896552.769 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:22:38.021Z,1713896558.021 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:22:52.968Z,1713896572.968 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:23:08.321Z,1713896588.321 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:23:23.268Z,1713896603.268 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:23:38.216Z,1713896618.216 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:23:52.761Z,1713896632.761 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:24:07.710Z,1713896647.710 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:24:22.253Z,1713896662.253 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:24:37.199Z,1713896677.199 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:24:52.148Z,1713896692.148 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:27:32.656Z,1713896852.656 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:27:32.664Z,1713896852.664 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:27:32.665Z,1713896852.665 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:27:32.665Z,1713896852.665 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:27:33.043Z,1713896853.043 [Default:CheckIn:D] Stopped 2024-04-23T18:27:33.043Z,1713896853.043 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:27:33.444Z,1713896853.444 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.005322 min 2024-04-23T18:27:33.444Z,1713896853.444 [Default:CheckIn:E] Stopped 2024-04-23T18:27:33.444Z,1713896853.444 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:27:33.444Z,1713896853.444 [Default:CheckIn] Stopped 2024-04-23T18:27:33.444Z,1713896853.444 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:27:33.444Z,1713896853.444 [Default:CheckIn](INFO): Running loop #19 2024-04-23T18:27:33.445Z,1713896853.445 [Default:CheckIn] Running Loop=19 2024-04-23T18:27:33.445Z,1713896853.445 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:27:33.445Z,1713896853.445 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:27:35.447Z,1713896855.447 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182734.00,A,3648.16322,N,12147.28620,W,0.408,344.22,230424,,,A*79 2024-04-23T18:27:35.449Z,1713896855.449 [NAL9602](INFO): GPS fix at 20240423T182734: (36.802720, -121.788103) 2024-04-23T18:27:35.460Z,1713896855.460 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:27:35.460Z,1713896855.460 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:27:43.540Z,1713896863.540 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0058.lzma 2024-04-23T18:27:44.542Z,1713896864.542 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0058.lzma.bak 2024-04-23T18:27:44.543Z,1713896864.543 [DataOverHttps](INFO): SBD MOMSN=19423095 2024-04-23T18:28:03.704Z,1713896883.704 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20240423T163357/Express0059.lzma 2024-04-23T18:28:04.707Z,1713896884.707 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0059.lzma.bak 2024-04-23T18:28:04.707Z,1713896884.707 [DataOverHttps](INFO): SBD MOMSN=19423098 2024-04-23T18:28:06.142Z,1713896886.142 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:28:06.217Z,1713896886.217 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:28:07.774Z,1713896887.774 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:28:07.774Z,1713896887.774 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:28:07.774Z,1713896887.774 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:32:28.544Z,1713897148.544 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:32:37.298Z,1713897157.298 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:32:43.353Z,1713897163.353 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:32:58.715Z,1713897178.715 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:33:08.020Z,1713897188.020 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:33:08.453Z,1713897188.453 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:33:08.453Z,1713897188.453 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:33:08.453Z,1713897188.453 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:33:08.453Z,1713897188.453 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:33:08.825Z,1713897188.825 [Default:CheckIn:D] Stopped 2024-04-23T18:33:08.825Z,1713897188.825 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:33:09.228Z,1713897189.228 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 113.601701 min 2024-04-23T18:33:09.228Z,1713897189.228 [Default:CheckIn:E] Stopped 2024-04-23T18:33:09.228Z,1713897189.228 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:33:09.228Z,1713897189.228 [Default:CheckIn] Stopped 2024-04-23T18:33:09.229Z,1713897189.229 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:33:09.229Z,1713897189.229 [Default:CheckIn](INFO): Running loop #20 2024-04-23T18:33:09.229Z,1713897189.229 [Default:CheckIn] Running Loop=20 2024-04-23T18:33:09.229Z,1713897189.229 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:33:09.229Z,1713897189.229 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:33:11.237Z,1713897191.237 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183310.00,A,3648.16442,N,12147.28934,W,0.700,43.55,230424,,,A*4E 2024-04-23T18:33:11.239Z,1713897191.239 [NAL9602](INFO): GPS fix at 20240423T183310: (36.802740, -121.788156) 2024-04-23T18:33:11.250Z,1713897191.250 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:33:11.250Z,1713897191.250 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:33:13.717Z,1713897193.717 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:33:19.552Z,1713897199.552 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0061.lzma 2024-04-23T18:33:20.555Z,1713897200.555 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0061.lzma.bak 2024-04-23T18:33:20.555Z,1713897200.555 [DataOverHttps](INFO): SBD MOMSN=19423101 2024-04-23T18:33:28.664Z,1713897208.664 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:33:38.461Z,1713897218.461 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0062.lzma 2024-04-23T18:33:39.459Z,1713897219.459 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0062.lzma.bak 2024-04-23T18:33:39.459Z,1713897219.459 [DataOverHttps](INFO): SBD MOMSN=19423104 2024-04-23T18:33:42.002Z,1713897222.002 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:33:42.077Z,1713897222.077 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:33:42.849Z,1713897222.849 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:33:42.849Z,1713897222.849 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:33:42.849Z,1713897222.849 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:33:43.612Z,1713897223.612 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:33:58.156Z,1713897238.156 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:34:13.117Z,1713897253.117 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:34:28.058Z,1713897268.058 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:34:43.404Z,1713897283.404 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T18:36:10.668Z,1713897370.668 [BPC1](INFO): Calculating totals. Valid battery stick count: 41. Valid reserve battery stick count: 4. 2024-04-23T18:36:10.671Z,1713897370.671 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle. 2024-04-23T18:38:13.553Z,1713897493.553 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:38:43.482Z,1713897523.482 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:38:43.482Z,1713897523.482 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:38:43.482Z,1713897523.482 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:38:43.482Z,1713897523.482 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:38:43.873Z,1713897523.873 [Default:CheckIn:D] Stopped 2024-04-23T18:38:43.873Z,1713897523.873 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:38:44.258Z,1713897524.258 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:38:44.271Z,1713897524.271 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.185832 min 2024-04-23T18:38:44.271Z,1713897524.271 [Default:CheckIn:E] Stopped 2024-04-23T18:38:44.271Z,1713897524.271 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:38:44.271Z,1713897524.271 [Default:CheckIn] Stopped 2024-04-23T18:38:44.271Z,1713897524.271 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:38:44.271Z,1713897524.271 [Default:CheckIn](INFO): Running loop #21 2024-04-23T18:38:44.271Z,1713897524.271 [Default:CheckIn] Running Loop=21 2024-04-23T18:38:44.272Z,1713897524.272 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:38:44.272Z,1713897524.272 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:38:46.287Z,1713897526.287 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183845.00,A,3648.16652,N,12147.28518,W,0.097,43.55,230424,,,A*4D 2024-04-23T18:38:46.290Z,1713897526.290 [NAL9602](INFO): GPS fix at 20240423T183845: (36.802775, -121.788086) 2024-04-23T18:38:46.300Z,1713897526.300 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:38:46.301Z,1713897526.301 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:38:55.324Z,1713897535.324 [DataOverHttps](INFO): Sending 83 bytes from file Logs/20240423T163357/Courier0064.lzma 2024-04-23T18:38:56.327Z,1713897536.327 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0064.lzma.bak 2024-04-23T18:38:56.327Z,1713897536.327 [DataOverHttps](INFO): SBD MOMSN=19423108 2024-04-23T18:39:15.760Z,1713897555.760 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20240423T163357/Express0065.lzma 2024-04-23T18:39:16.763Z,1713897556.763 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0065.lzma.bak 2024-04-23T18:39:16.763Z,1713897556.763 [DataOverHttps](INFO): SBD MOMSN=19423111 2024-04-23T18:39:19.830Z,1713897559.830 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:39:19.830Z,1713897559.830 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:39:19.830Z,1713897559.830 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:43:48.484Z,1713897828.484 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:44:19.190Z,1713897859.190 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:44:20.450Z,1713897860.450 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:44:20.450Z,1713897860.450 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:44:20.450Z,1713897860.450 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:44:20.450Z,1713897860.450 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:44:20.860Z,1713897860.860 [Default:CheckIn:D] Stopped 2024-04-23T18:44:20.860Z,1713897860.860 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:44:21.296Z,1713897861.296 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 124.802279 min 2024-04-23T18:44:21.296Z,1713897861.296 [Default:CheckIn:E] Stopped 2024-04-23T18:44:21.296Z,1713897861.296 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:44:21.296Z,1713897861.296 [Default:CheckIn] Stopped 2024-04-23T18:44:21.301Z,1713897861.301 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:44:21.301Z,1713897861.301 [Default:CheckIn](INFO): Running loop #22 2024-04-23T18:44:21.301Z,1713897861.301 [Default:CheckIn] Running Loop=22 2024-04-23T18:44:21.301Z,1713897861.301 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:44:21.301Z,1713897861.301 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:44:23.240Z,1713897863.240 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184422.00,A,3648.16708,N,12147.28383,W,0.428,43.55,230424,,,A*4D 2024-04-23T18:44:23.251Z,1713897863.251 [NAL9602](INFO): GPS fix at 20240423T184422: (36.802785, -121.788064) 2024-04-23T18:44:23.306Z,1713897863.306 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:44:23.306Z,1713897863.306 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:44:34.396Z,1713897874.396 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0067.lzma 2024-04-23T18:44:35.399Z,1713897875.399 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0067.lzma.bak 2024-04-23T18:44:35.399Z,1713897875.399 [DataOverHttps](INFO): SBD MOMSN=19423185 2024-04-23T18:44:53.671Z,1713897893.671 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:44:53.749Z,1713897893.749 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:44:54.358Z,1713897894.358 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20240423T163357/Express0068.lzma 2024-04-23T18:44:55.359Z,1713897895.359 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0068.lzma.bak 2024-04-23T18:44:55.359Z,1713897895.359 [DataOverHttps](INFO): SBD MOMSN=19423188 2024-04-23T18:44:58.559Z,1713897898.559 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:44:58.559Z,1713897898.559 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:44:58.559Z,1713897898.559 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:46:07.941Z,1713897967.941 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.238865 2024-04-23T18:46:49.113Z,1713898009.113 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2024-04-23T18:47:04.957Z,1713898024.957 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002993 2024-04-23T18:49:25.206Z,1713898165.206 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:49:55.915Z,1713898195.915 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:49:59.162Z,1713898199.162 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:49:59.162Z,1713898199.162 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:49:59.162Z,1713898199.162 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:49:59.162Z,1713898199.162 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:49:59.566Z,1713898199.566 [Default:CheckIn:D] Stopped 2024-04-23T18:49:59.566Z,1713898199.566 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 130.447380 min 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn:E] Stopped 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn] Stopped 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn](INFO): Running loop #23 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn] Running Loop=23 2024-04-23T18:49:59.969Z,1713898199.969 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:49:59.970Z,1713898199.970 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:50:01.978Z,1713898201.978 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185001.00,A,3648.16098,N,12147.28185,W,0.875,0.00,230424,,,A*70 2024-04-23T18:50:01.980Z,1713898201.980 [NAL9602](INFO): GPS fix at 20240423T185001: (36.802683, -121.788031) 2024-04-23T18:50:02.007Z,1713898202.007 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:50:02.007Z,1713898202.007 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:50:10.212Z,1713898210.212 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0070.lzma 2024-04-23T18:50:11.214Z,1713898211.214 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0070.lzma.bak 2024-04-23T18:50:11.215Z,1713898211.215 [DataOverHttps](INFO): SBD MOMSN=19423194 2024-04-23T18:50:32.715Z,1713898232.715 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:50:32.784Z,1713898232.784 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20240423T163357/Express0071.lzma 2024-04-23T18:50:32.801Z,1713898232.801 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:50:33.787Z,1713898233.787 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0071.lzma.bak 2024-04-23T18:50:33.787Z,1713898233.787 [DataOverHttps](INFO): SBD MOMSN=19423197 2024-04-23T18:50:36.788Z,1713898236.788 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:50:36.788Z,1713898236.788 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:50:36.788Z,1713898236.788 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T18:55:04.264Z,1713898504.264 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T18:55:34.962Z,1713898534.962 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T18:55:37.398Z,1713898537.398 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T18:55:37.398Z,1713898537.398 [Default:CheckIn:C.Wait] Stopped 2024-04-23T18:55:37.398Z,1713898537.398 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T18:55:37.398Z,1713898537.398 [Default:CheckIn:D] Running Loop=1 2024-04-23T18:55:37.805Z,1713898537.805 [Default:CheckIn:D] Stopped 2024-04-23T18:55:37.805Z,1713898537.805 [Default:CheckIn:E] Running Loop=1 2024-04-23T18:55:38.203Z,1713898538.203 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 136.084701 min 2024-04-23T18:55:38.203Z,1713898538.203 [Default:CheckIn:E] Stopped 2024-04-23T18:55:38.203Z,1713898538.203 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T18:55:38.203Z,1713898538.203 [Default:CheckIn] Stopped 2024-04-23T18:55:38.203Z,1713898538.203 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T18:55:38.203Z,1713898538.203 [Default:CheckIn](INFO): Running loop #24 2024-04-23T18:55:38.203Z,1713898538.203 [Default:CheckIn] Running Loop=24 2024-04-23T18:55:38.204Z,1713898538.204 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T18:55:38.204Z,1713898538.204 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T18:55:40.221Z,1713898540.221 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185539.00,A,3648.16024,N,12147.27319,W,0.428,0.00,230424,,,A*75 2024-04-23T18:55:40.223Z,1713898540.223 [NAL9602](INFO): GPS fix at 20240423T185539: (36.802671, -121.787886) 2024-04-23T18:55:40.234Z,1713898540.234 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T18:55:40.234Z,1713898540.234 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T18:55:49.000Z,1713898550.000 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0073.lzma 2024-04-23T18:55:51.002Z,1713898551.002 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0073.lzma.bak 2024-04-23T18:55:51.003Z,1713898551.003 [DataOverHttps](INFO): SBD MOMSN=19423290 2024-04-23T18:56:10.852Z,1713898570.852 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20240423T163357/Express0074.lzma 2024-04-23T18:56:10.922Z,1713898570.922 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T18:56:10.000Z,1713898571.000 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T18:56:11.855Z,1713898571.855 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0074.lzma.bak 2024-04-23T18:56:11.855Z,1713898571.855 [DataOverHttps](INFO): SBD MOMSN=19423293 2024-04-23T18:56:14.990Z,1713898574.990 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T18:56:14.990Z,1713898574.990 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T18:56:14.990Z,1713898574.990 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:00:42.510Z,1713898842.510 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:01:13.218Z,1713898873.218 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:01:15.649Z,1713898875.649 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:01:15.649Z,1713898875.649 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:01:15.649Z,1713898875.649 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:01:15.649Z,1713898875.649 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:01:16.058Z,1713898876.058 [Default:CheckIn:D] Stopped 2024-04-23T19:01:16.058Z,1713898876.058 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:01:16.482Z,1713898876.482 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 141.722249 min 2024-04-23T19:01:16.482Z,1713898876.482 [Default:CheckIn:E] Stopped 2024-04-23T19:01:16.483Z,1713898876.483 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:01:16.483Z,1713898876.483 [Default:CheckIn] Stopped 2024-04-23T19:01:16.483Z,1713898876.483 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:01:16.483Z,1713898876.483 [Default:CheckIn](INFO): Running loop #25 2024-04-23T19:01:16.483Z,1713898876.483 [Default:CheckIn] Running Loop=25 2024-04-23T19:01:16.483Z,1713898876.483 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:01:16.483Z,1713898876.483 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:01:18.472Z,1713898878.472 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190117.00,A,3648.16075,N,12147.28220,W,0.136,56.68,230424,,,A*4E 2024-04-23T19:01:18.474Z,1713898878.474 [NAL9602](INFO): GPS fix at 20240423T190117: (36.802679, -121.788037) 2024-04-23T19:01:18.524Z,1713898878.524 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:01:18.524Z,1713898878.524 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:01:21.079Z,1713898881.079 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0076.lzma 2024-04-23T19:01:22.087Z,1713898882.087 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0076.lzma.bak 2024-04-23T19:01:22.087Z,1713898882.087 [DataOverHttps](INFO): SBD MOMSN=19423297 2024-04-23T19:01:40.040Z,1713898900.040 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0077.lzma 2024-04-23T19:01:41.043Z,1713898901.043 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0077.lzma.bak 2024-04-23T19:01:41.043Z,1713898901.043 [DataOverHttps](INFO): SBD MOMSN=19423304 2024-04-23T19:01:45.640Z,1713898905.640 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:01:45.641Z,1713898905.641 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:01:45.641Z,1713898905.641 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:01:49.234Z,1713898909.234 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:01:49.309Z,1713898909.309 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T19:06:20.415Z,1713899180.415 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:06:46.299Z,1713899206.299 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:06:46.299Z,1713899206.299 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:06:46.299Z,1713899206.299 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:06:46.299Z,1713899206.299 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:06:46.693Z,1713899206.693 [Default:CheckIn:D] Stopped 2024-04-23T19:06:46.693Z,1713899206.693 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 147.232829 min 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn:E] Stopped 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn] Stopped 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn](INFO): Running loop #26 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn] Running Loop=26 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:06:47.102Z,1713899207.102 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:06:49.109Z,1713899209.109 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190648.00,A,3648.16364,N,12147.28095,W,0.194,56.68,230424,,,A*44 2024-04-23T19:06:49.111Z,1713899209.111 [NAL9602](INFO): GPS fix at 20240423T190648: (36.802727, -121.788016) 2024-04-23T19:06:49.142Z,1713899209.142 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:06:49.142Z,1713899209.142 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:06:57.336Z,1713899217.336 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0079.lzma 2024-04-23T19:06:58.339Z,1713899218.339 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0079.lzma.bak 2024-04-23T19:06:58.339Z,1713899218.339 [DataOverHttps](INFO): SBD MOMSN=19423387 2024-04-23T19:07:16.168Z,1713899236.168 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20240423T163357/Express0080.lzma 2024-04-23T19:07:17.171Z,1713899237.171 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0080.lzma.bak 2024-04-23T19:07:17.171Z,1713899237.171 [DataOverHttps](INFO): SBD MOMSN=19423427 2024-04-23T19:07:20.222Z,1713899240.222 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:07:20.222Z,1713899240.222 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:07:20.222Z,1713899240.222 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:07:21.414Z,1713899241.414 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:12:20.832Z,1713899540.832 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:12:20.832Z,1713899540.832 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:12:20.832Z,1713899540.832 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:12:20.833Z,1713899540.833 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:12:21.234Z,1713899541.234 [Default:CheckIn:D] Stopped 2024-04-23T19:12:21.234Z,1713899541.234 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 152.808512 min 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn:E] Stopped 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn] Stopped 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn](INFO): Running loop #27 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn] Running Loop=27 2024-04-23T19:12:21.646Z,1713899541.646 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:12:21.647Z,1713899541.647 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:12:23.652Z,1713899543.652 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191222.00,A,3648.16485,N,12147.28742,W,1.011,47.19,230424,,,A*43 2024-04-23T19:12:23.654Z,1713899543.654 [NAL9602](INFO): GPS fix at 20240423T191222: (36.802748, -121.788124) 2024-04-23T19:12:23.693Z,1713899543.693 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:12:23.694Z,1713899543.694 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:12:32.236Z,1713899552.236 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0082.lzma 2024-04-23T19:12:33.239Z,1713899553.239 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0082.lzma.bak 2024-04-23T19:12:33.239Z,1713899553.239 [DataOverHttps](INFO): SBD MOMSN=19423531 2024-04-23T19:12:51.412Z,1713899571.412 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20240423T163357/Express0083.lzma 2024-04-23T19:12:52.415Z,1713899572.415 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0083.lzma.bak 2024-04-23T19:12:52.415Z,1713899572.415 [DataOverHttps](INFO): SBD MOMSN=19423538 2024-04-23T19:12:54.366Z,1713899574.366 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:12:54.445Z,1713899574.445 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T19:12:55.625Z,1713899575.625 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:12:55.625Z,1713899575.625 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:12:55.625Z,1713899575.625 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:17:26.310Z,1713899846.310 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:17:56.212Z,1713899876.212 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:17:56.212Z,1713899876.212 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:17:56.228Z,1713899876.228 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:17:56.229Z,1713899876.229 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:17:56.626Z,1713899876.626 [Default:CheckIn:D] Stopped 2024-04-23T19:17:56.626Z,1713899876.626 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:17:57.014Z,1713899877.014 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:17:57.027Z,1713899877.027 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 158.398389 min 2024-04-23T19:17:57.027Z,1713899877.027 [Default:CheckIn:E] Stopped 2024-04-23T19:17:57.027Z,1713899877.027 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:17:57.027Z,1713899877.027 [Default:CheckIn] Stopped 2024-04-23T19:17:57.027Z,1713899877.027 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:17:57.028Z,1713899877.028 [Default:CheckIn](INFO): Running loop #28 2024-04-23T19:17:57.028Z,1713899877.028 [Default:CheckIn] Running Loop=28 2024-04-23T19:17:57.028Z,1713899877.028 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:17:57.028Z,1713899877.028 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:17:59.041Z,1713899879.041 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191758.00,A,3648.15800,N,12147.28557,W,0.078,41.48,230424,,,A*43 2024-04-23T19:17:59.044Z,1713899879.044 [NAL9602](INFO): GPS fix at 20240423T191758: (36.802633, -121.788093) 2024-04-23T19:17:59.062Z,1713899879.062 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:17:59.062Z,1713899879.062 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:18:07.424Z,1713899887.424 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0085.lzma 2024-04-23T19:18:08.427Z,1713899888.427 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0085.lzma.bak 2024-04-23T19:18:08.427Z,1713899888.427 [DataOverHttps](INFO): SBD MOMSN=19423595 2024-04-23T19:18:26.324Z,1713899906.324 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0086.lzma 2024-04-23T19:18:27.327Z,1713899907.327 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0086.lzma.bak 2024-04-23T19:18:27.327Z,1713899907.327 [DataOverHttps](INFO): SBD MOMSN=19423603 2024-04-23T19:18:29.735Z,1713899909.735 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:18:29.814Z,1713899909.814 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T19:18:30.607Z,1713899910.607 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:18:30.607Z,1713899910.607 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:18:30.608Z,1713899910.608 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:23:01.260Z,1713900181.260 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:23:31.149Z,1713900211.149 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:23:31.149Z,1713900211.149 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:23:31.149Z,1713900211.149 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:23:31.149Z,1713900211.149 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:23:31.537Z,1713900211.537 [Default:CheckIn:D] Stopped 2024-04-23T19:23:31.537Z,1713900211.537 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:23:31.930Z,1713900211.930 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 163.980225 min 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn:E] Stopped 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn] Stopped 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn](INFO): Running loop #29 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn] Running Loop=29 2024-04-23T19:23:31.943Z,1713900211.943 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:23:31.944Z,1713900211.944 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:23:33.951Z,1713900213.951 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192333.00,A,3648.16222,N,12147.28092,W,0.058,302.74,230424,,,A*75 2024-04-23T19:23:33.954Z,1713900213.954 [NAL9602](INFO): GPS fix at 20240423T192333: (36.802704, -121.788015) 2024-04-23T19:23:33.965Z,1713900213.966 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:23:33.966Z,1713900213.966 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:23:42.764Z,1713900222.764 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0088.lzma 2024-04-23T19:23:43.767Z,1713900223.767 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0088.lzma.bak 2024-04-23T19:23:43.767Z,1713900223.767 [DataOverHttps](INFO): SBD MOMSN=19423660 2024-04-23T19:24:04.718Z,1713900244.718 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:24:04.793Z,1713900244.793 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T19:24:05.736Z,1713900245.736 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0089.lzma 2024-04-23T19:24:06.739Z,1713900246.739 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0089.lzma.bak 2024-04-23T19:24:06.739Z,1713900246.739 [DataOverHttps](INFO): SBD MOMSN=19423663 2024-04-23T19:24:09.586Z,1713900249.586 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:24:09.586Z,1713900249.586 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:24:09.587Z,1713900249.587 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:28:36.234Z,1713900516.234 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:29:06.957Z,1713900546.957 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:29:10.191Z,1713900550.191 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:29:10.191Z,1713900550.191 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:29:10.191Z,1713900550.191 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:29:10.191Z,1713900550.191 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:29:10.585Z,1713900550.585 [Default:CheckIn:D] Stopped 2024-04-23T19:29:10.585Z,1713900550.585 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:29:10.989Z,1713900550.989 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 169.631038 min 2024-04-23T19:29:10.989Z,1713900550.989 [Default:CheckIn:E] Stopped 2024-04-23T19:29:10.990Z,1713900550.990 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:29:10.990Z,1713900550.990 [Default:CheckIn] Stopped 2024-04-23T19:29:10.990Z,1713900550.990 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:29:10.990Z,1713900550.990 [Default:CheckIn](INFO): Running loop #30 2024-04-23T19:29:10.990Z,1713900550.990 [Default:CheckIn] Running Loop=30 2024-04-23T19:29:10.990Z,1713900550.990 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:29:10.990Z,1713900550.990 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:29:13.006Z,1713900553.006 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192912.00,A,3648.15779,N,12147.28536,W,0.525,302.74,230424,,,A*70 2024-04-23T19:29:13.008Z,1713900553.008 [NAL9602](INFO): GPS fix at 20240423T192912: (36.802630, -121.788089) 2024-04-23T19:29:13.024Z,1713900553.024 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:29:13.024Z,1713900553.024 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:29:22.710Z,1713900562.710 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0091.lzma 2024-04-23T19:29:23.711Z,1713900563.711 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0091.lzma.bak 2024-04-23T19:29:23.711Z,1713900563.711 [DataOverHttps](INFO): SBD MOMSN=19423674 2024-04-23T19:29:43.553Z,1713900583.553 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20240423T163357/Express0092.lzma 2024-04-23T19:29:43.706Z,1713900583.706 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:29:43.789Z,1713900583.789 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T19:29:44.564Z,1713900584.564 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0092.lzma.bak 2024-04-23T19:29:44.564Z,1713900584.564 [DataOverHttps](INFO): SBD MOMSN=19423681 2024-04-23T19:29:49.487Z,1713900589.487 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:29:49.487Z,1713900589.487 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:29:49.487Z,1713900589.487 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:31:01.759Z,1713900661.759 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T19:31:01.759Z,1713900661.759 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T19:34:15.291Z,1713900855.291 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:34:46.016Z,1713900886.016 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:34:50.087Z,1713900890.087 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:34:50.087Z,1713900890.087 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:34:50.088Z,1713900890.088 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:34:50.088Z,1713900890.088 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:34:50.473Z,1713900890.473 [Default:CheckIn:D] Stopped 2024-04-23T19:34:50.474Z,1713900890.474 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:34:50.892Z,1713900890.892 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 175.295833 min 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn:E] Stopped 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn] Stopped 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn](INFO): Running loop #31 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn] Running Loop=31 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:34:50.893Z,1713900890.893 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:34:52.880Z,1713900892.880 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193452.00,A,3648.15741,N,12147.28706,W,0.175,68.66,230424,,,A*4F 2024-04-23T19:34:52.882Z,1713900892.882 [NAL9602](INFO): GPS fix at 20240423T193452: (36.802624, -121.788118) 2024-04-23T19:34:52.963Z,1713900892.963 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:34:52.963Z,1713900892.963 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:34:54.816Z,1713900894.816 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20240423T163357/Courier0094.lzma 2024-04-23T19:34:55.834Z,1713900895.834 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0094.lzma.bak 2024-04-23T19:34:55.835Z,1713900895.835 [DataOverHttps](INFO): SBD MOMSN=19423731 2024-04-23T19:35:16.108Z,1713900916.108 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20240423T163357/Express0095.lzma 2024-04-23T19:35:17.111Z,1713900917.111 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0095.lzma.bak 2024-04-23T19:35:17.111Z,1713900917.111 [DataOverHttps](INFO): SBD MOMSN=19423734 2024-04-23T19:35:20.064Z,1713900920.064 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:35:20.065Z,1713900920.065 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:35:20.065Z,1713900920.065 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:35:23.670Z,1713900923.670 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:35:23.749Z,1713900923.749 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T19:38:45.284Z,1713901125.284 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T19:38:45.284Z,1713901125.284 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T19:39:52.744Z,1713901192.744 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T19:39:52.744Z,1713901192.744 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T19:39:55.175Z,1713901195.175 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:40:20.625Z,1713901220.625 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:40:20.625Z,1713901220.625 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:40:20.625Z,1713901220.625 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:40:20.625Z,1713901220.625 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:40:21.037Z,1713901221.037 [Default:CheckIn:D] Stopped 2024-04-23T19:40:21.037Z,1713901221.037 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:40:21.435Z,1713901221.435 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 180.805225 min 2024-04-23T19:40:21.435Z,1713901221.435 [Default:CheckIn:E] Stopped 2024-04-23T19:40:21.435Z,1713901221.435 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:40:21.435Z,1713901221.435 [Default:CheckIn] Stopped 2024-04-23T19:40:21.436Z,1713901221.436 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:40:21.436Z,1713901221.436 [Default:CheckIn](INFO): Running loop #32 2024-04-23T19:40:21.436Z,1713901221.436 [Default:CheckIn] Running Loop=32 2024-04-23T19:40:21.436Z,1713901221.436 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:40:21.436Z,1713901221.436 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:40:23.452Z,1713901223.452 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194022.00,A,3648.16250,N,12147.28439,W,1.225,68.66,230424,,,A*45 2024-04-23T19:40:23.456Z,1713901223.456 [NAL9602](INFO): GPS fix at 20240423T194022: (36.802708, -121.788073) 2024-04-23T19:40:23.470Z,1713901223.470 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:40:23.470Z,1713901223.470 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:40:32.274Z,1713901232.274 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0097.lzma 2024-04-23T19:40:33.275Z,1713901233.275 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0097.lzma.bak 2024-04-23T19:40:33.275Z,1713901233.275 [DataOverHttps](INFO): SBD MOMSN=19423788 2024-04-23T19:40:51.476Z,1713901251.476 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0098.lzma 2024-04-23T19:40:52.479Z,1713901252.479 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0098.lzma.bak 2024-04-23T19:40:52.479Z,1713901252.479 [DataOverHttps](INFO): SBD MOMSN=19423791 2024-04-23T19:40:55.376Z,1713901255.376 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:40:55.925Z,1713901255.925 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:40:55.925Z,1713901255.925 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:40:55.925Z,1713901255.925 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:43:49.614Z,1713901429.614 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:44:04.505Z,1713901444.505 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:44:19.454Z,1713901459.454 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:44:33.996Z,1713901473.996 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:44:48.945Z,1713901488.945 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:45:03.894Z,1713901503.894 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:45:19.245Z,1713901519.245 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:45:34.205Z,1713901534.205 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:45:49.142Z,1713901549.142 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:45:56.432Z,1713901556.432 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:45:56.432Z,1713901556.432 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:45:56.432Z,1713901556.432 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:45:56.432Z,1713901556.432 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:45:56.830Z,1713901556.830 [Default:CheckIn:D] Stopped 2024-04-23T19:45:56.830Z,1713901556.830 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:45:57.242Z,1713901557.242 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 186.401790 min 2024-04-23T19:45:57.242Z,1713901557.242 [Default:CheckIn:E] Stopped 2024-04-23T19:45:57.243Z,1713901557.243 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:45:57.243Z,1713901557.243 [Default:CheckIn] Stopped 2024-04-23T19:45:57.243Z,1713901557.243 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:45:57.243Z,1713901557.243 [Default:CheckIn](INFO): Running loop #33 2024-04-23T19:45:57.243Z,1713901557.243 [Default:CheckIn] Running Loop=33 2024-04-23T19:45:57.243Z,1713901557.243 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:45:57.243Z,1713901557.243 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:45:59.252Z,1713901559.252 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194558.00,A,3648.16056,N,12147.28518,W,0.156,193.93,230424,,,A*72 2024-04-23T19:45:59.254Z,1713901559.254 [NAL9602](INFO): GPS fix at 20240423T194558: (36.802676, -121.788086) 2024-04-23T19:45:59.290Z,1713901559.290 [UniversalFixResidualReporter](INFO): Fix residual: 72.8 %DT, over the last 538.1 m. Residual distance 391.5 m at bearing -67.9 degrees. Fix at (36.8027, -121.7881) with 3.8 m made good. 2024-04-23T19:45:59.291Z,1713901559.291 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:45:59.291Z,1713901559.291 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:46:03.684Z,1713901563.684 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:46:08.200Z,1713901568.200 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Courier0100.lzma 2024-04-23T19:46:09.203Z,1713901569.203 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0100.lzma.bak 2024-04-23T19:46:09.203Z,1713901569.203 [DataOverHttps](INFO): SBD MOMSN=19423795 2024-04-23T19:46:30.006Z,1713901590.006 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:46:30.088Z,1713901590.088 [NAL9602](ERROR): received: +SBDI: 2, 19449, 2, 0, 0, 0 OK 2024-04-23T19:46:31.016Z,1713901591.016 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20240423T163357/Express0101.lzma 2024-04-23T19:46:32.019Z,1713901592.019 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0101.lzma.bak 2024-04-23T19:46:32.019Z,1713901592.019 [DataOverHttps](INFO): SBD MOMSN=19423798 2024-04-23T19:46:35.295Z,1713901595.295 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:46:35.295Z,1713901595.295 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:46:35.295Z,1713901595.295 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:47:03.861Z,1713901623.861 [CommandExec](IMPORTANT): got command failComponent 2024-04-23T19:47:03.861Z,1713901623.861 [CommandExec](IMPORTANT): Failed components: 2024-04-23T19:47:03.861Z,1713901623.861 [CommandExec](IMPORTANT): No failed Components. 2024-04-23T19:47:41.182Z,1713901661.182 [CommandExec](IMPORTANT): got command show variable limitfwd 2024-04-23T19:47:41.294Z,1713901661.294 [CommandExec](IMPORTANT): VerticalControl.massPositionLimitFwd (millimeter) 2024-04-23T19:47:55.190Z,1713901675.190 [CommandExec](IMPORTANT): got command get VerticalControl.massPositionLimitFwd 2024-04-23T19:47:55.191Z,1713901675.191 [CommandExec](IMPORTANT): VerticalControl.massPositionLimitFwd 32.000000 mm 2024-04-23T19:48:08.268Z,1713901688.268 [CommandExec](IMPORTANT): got command get VerticalControl.massPositionLimitAft 2024-04-23T19:48:08.269Z,1713901688.269 [CommandExec](IMPORTANT): VerticalControl.massPositionLimitAft -28.000000 mm 2024-04-23T19:48:23.928Z,1713901703.928 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T19:48:23.928Z,1713901703.928 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T19:48:26.938Z,1713901706.938 [CommandExec](IMPORTANT): got command get platform_mass_position millimeter 2024-04-23T19:48:26.939Z,1713901706.939 [CommandExec](IMPORTANT): platform_mass_position 32.001564 mm 2024-04-23T19:49:07.163Z,1713901747.163 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T19:49:07.163Z,1713901747.163 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T19:49:32.594Z,1713901772.594 [NAL9602](INFO): SBD MO Status=2, MOMSN=19449, MT Status=2, MTMSN=0 2024-04-23T19:49:32.594Z,1713901772.594 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2024-04-23T19:51:01.286Z,1713901861.286 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:51:31.986Z,1713901891.986 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:51:36.066Z,1713901896.066 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:51:36.066Z,1713901896.066 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:51:36.066Z,1713901896.066 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:51:36.067Z,1713901896.067 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:51:36.457Z,1713901896.457 [Default:CheckIn:D] Stopped 2024-04-23T19:51:36.457Z,1713901896.457 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:51:36.847Z,1713901896.847 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 192.062223 min 2024-04-23T19:51:36.847Z,1713901896.847 [Default:CheckIn:E] Stopped 2024-04-23T19:51:36.847Z,1713901896.847 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:51:36.847Z,1713901896.847 [Default:CheckIn] Stopped 2024-04-23T19:51:36.847Z,1713901896.847 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:51:36.848Z,1713901896.848 [Default:CheckIn](INFO): Running loop #34 2024-04-23T19:51:36.848Z,1713901896.848 [Default:CheckIn] Running Loop=34 2024-04-23T19:51:36.848Z,1713901896.848 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:51:36.848Z,1713901896.848 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:51:38.988Z,1713901898.988 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195138.00,A,3648.16376,N,12147.28532,W,0.097,214.22,230424,,,A*72 2024-04-23T19:51:38.990Z,1713901898.990 [NAL9602](INFO): GPS fix at 20240423T195138: (36.802729, -121.788089) 2024-04-23T19:51:39.024Z,1713901899.024 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:51:39.024Z,1713901899.024 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:51:47.536Z,1713901907.536 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0103.lzma 2024-04-23T19:51:48.539Z,1713901908.539 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0103.lzma.bak 2024-04-23T19:51:48.539Z,1713901908.539 [DataOverHttps](INFO): SBD MOMSN=19423844 2024-04-23T19:52:06.625Z,1713901926.625 [DataOverHttps](INFO): Sending 405 bytes from file Logs/20240423T163357/Express0104.lzma 2024-04-23T19:52:07.628Z,1713901927.628 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0104.lzma.bak 2024-04-23T19:52:07.628Z,1713901927.628 [DataOverHttps](INFO): SBD MOMSN=19423847 2024-04-23T19:52:11.234Z,1713901931.234 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:52:11.234Z,1713901931.234 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:52:11.234Z,1713901931.234 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:52:18.498Z,1713901938.498 [CommandExec](IMPORTANT): got command get VerticalControl.massDefault 2024-04-23T19:52:18.499Z,1713901938.499 [CommandExec](IMPORTANT): VerticalControl.massDefault 3.200000 cm 2024-04-23T19:53:23.308Z,1713902003.308 [CommandExec](IMPORTANT): got command configSet VerticalControl.massDefault 2.5 centimeter persist 2024-04-23T19:53:36.214Z,1713902016.214 [CommandExec](IMPORTANT): got command get platform_mass_position millimeter 2024-04-23T19:53:36.215Z,1713902016.215 [CommandExec](IMPORTANT): platform_mass_position 25.000160 mm 2024-04-23T19:53:39.268Z,1713902019.268 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:53:53.813Z,1713902033.813 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:54:08.763Z,1713902048.763 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:54:23.714Z,1713902063.714 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:54:39.062Z,1713902079.062 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:54:54.008Z,1713902094.008 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:55:09.006Z,1713902109.006 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:55:19.080Z,1713902119.080 [DVL_micro](ERROR): only read 0 of 4 data items for beam range. Device response is::RD,,+0010.47,+0000.30,+0011.12 2024-04-23T19:55:19.081Z,1713902119.081 [DVL_micro](ERROR): Failed to parse: :RD,,+0010.47,+0000.30,+0011.12 2024-04-23T19:55:23.500Z,1713902123.500 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:55:38.449Z,1713902138.449 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:55:53.396Z,1713902153.396 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T19:56:41.480Z,1713902201.480 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T19:57:11.813Z,1713902231.813 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T19:57:11.814Z,1713902231.814 [Default:CheckIn:C.Wait] Stopped 2024-04-23T19:57:11.814Z,1713902231.814 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T19:57:11.814Z,1713902231.814 [Default:CheckIn:D] Running Loop=1 2024-04-23T19:57:12.182Z,1713902232.182 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T19:57:12.234Z,1713902232.234 [Default:CheckIn:D] Stopped 2024-04-23T19:57:12.234Z,1713902232.234 [Default:CheckIn:E] Running Loop=1 2024-04-23T19:57:12.638Z,1713902232.638 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 197.658512 min 2024-04-23T19:57:12.638Z,1713902232.638 [Default:CheckIn:E] Stopped 2024-04-23T19:57:12.638Z,1713902232.638 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T19:57:12.639Z,1713902232.639 [Default:CheckIn] Stopped 2024-04-23T19:57:12.639Z,1713902232.639 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T19:57:12.639Z,1713902232.639 [Default:CheckIn](INFO): Running loop #35 2024-04-23T19:57:12.639Z,1713902232.639 [Default:CheckIn] Running Loop=35 2024-04-23T19:57:12.639Z,1713902232.639 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T19:57:12.639Z,1713902232.639 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T19:57:14.612Z,1713902234.612 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195713.00,A,3648.16554,N,12147.28272,W,1.458,221.05,230424,,,A*7D 2024-04-23T19:57:14.615Z,1713902234.615 [NAL9602](INFO): GPS fix at 20240423T195713: (36.802759, -121.788045) 2024-04-23T19:57:14.669Z,1713902234.669 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T19:57:14.669Z,1713902234.669 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T19:57:16.806Z,1713902236.806 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0106.lzma 2024-04-23T19:57:17.867Z,1713902237.867 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0106.lzma.bak 2024-04-23T19:57:17.867Z,1713902237.867 [DataOverHttps](INFO): SBD MOMSN=19423862 2024-04-23T19:57:36.223Z,1713902256.223 [DataOverHttps](INFO): Sending 346 bytes from file Logs/20240423T163357/Express0107.lzma 2024-04-23T19:57:37.223Z,1713902257.223 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0107.lzma.bak 2024-04-23T19:57:37.223Z,1713902257.223 [DataOverHttps](INFO): SBD MOMSN=19423865 2024-04-23T19:57:40.090Z,1713902260.090 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T19:57:40.090Z,1713902260.090 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T19:57:40.090Z,1713902260.090 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T19:57:45.310Z,1713902265.310 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T19:57:45.385Z,1713902265.385 [NAL9602](ERROR): received: +CSQ:1 OK449, 2, 0, 0, 0 OK 2024-04-23T20:02:17.286Z,1713902537.286 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T20:02:40.747Z,1713902560.747 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T20:02:40.747Z,1713902560.747 [Default:CheckIn:C.Wait] Stopped 2024-04-23T20:02:40.747Z,1713902560.747 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T20:02:40.747Z,1713902560.747 [Default:CheckIn:D] Running Loop=1 2024-04-23T20:02:41.248Z,1713902561.248 [Default:CheckIn:D] Stopped 2024-04-23T20:02:41.248Z,1713902561.248 [Default:CheckIn:E] Running Loop=1 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 203.142074 min 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn:E] Stopped 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn] Stopped 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn](INFO): Running loop #36 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn] Running Loop=36 2024-04-23T20:02:41.586Z,1713902561.586 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T20:02:41.587Z,1713902561.587 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T20:02:43.544Z,1713902563.544 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200242.00,A,3648.16535,N,12147.28599,W,0.097,182.98,230424,,,A*7E 2024-04-23T20:02:43.547Z,1713902563.547 [NAL9602](INFO): GPS fix at 20240423T200242: (36.802756, -121.788100) 2024-04-23T20:02:43.557Z,1713902563.557 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T20:02:43.557Z,1713902563.557 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T20:02:51.692Z,1713902571.692 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0109.lzma 2024-04-23T20:02:52.698Z,1713902572.698 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0109.lzma.bak 2024-04-23T20:02:52.698Z,1713902572.698 [DataOverHttps](INFO): SBD MOMSN=19423916 2024-04-23T20:03:10.680Z,1713902590.680 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20240423T163357/Express0110.lzma 2024-04-23T20:03:11.683Z,1713902591.683 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0110.lzma.bak 2024-04-23T20:03:11.683Z,1713902591.683 [DataOverHttps](INFO): SBD MOMSN=19423919 2024-04-23T20:03:14.678Z,1713902594.678 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T20:03:14.678Z,1713902594.678 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T20:03:14.678Z,1713902594.678 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T20:03:15.462Z,1713902595.462 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T20:03:39.293Z,1713902619.293 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:03:54.241Z,1713902634.241 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:04:09.249Z,1713902649.249 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:04:23.733Z,1713902663.733 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:04:38.680Z,1713902678.680 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:04:53.628Z,1713902693.628 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:05:08.980Z,1713902708.980 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:05:23.940Z,1713902723.940 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:05:38.877Z,1713902738.877 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:05:53.876Z,1713902753.876 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2024-04-23T20:07:11.853Z,1713902831.853 [BPC1](INFO): Calculating totals. Valid battery stick count: 41. Valid reserve battery stick count: 4. 2024-04-23T20:07:11.856Z,1713902831.856 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle. 2024-04-23T20:08:15.298Z,1713902895.298 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T20:08:15.298Z,1713902895.298 [Default:CheckIn:C.Wait] Stopped 2024-04-23T20:08:15.298Z,1713902895.298 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T20:08:15.298Z,1713902895.298 [Default:CheckIn:D] Running Loop=1 2024-04-23T20:08:15.698Z,1713902895.698 [Default:CheckIn:D] Stopped 2024-04-23T20:08:15.698Z,1713902895.698 [Default:CheckIn:E] Running Loop=1 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 208.716243 min 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn:E] Stopped 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn] Stopped 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn](INFO): Running loop #37 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn] Running Loop=37 2024-04-23T20:08:16.109Z,1713902896.109 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T20:08:16.110Z,1713902896.110 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T20:08:18.113Z,1713902898.113 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200817.00,A,3648.17338,N,12147.27726,W,1.438,36.11,230424,,,A*48 2024-04-23T20:08:18.115Z,1713902898.115 [NAL9602](INFO): GPS fix at 20240423T200817: (36.802890, -121.787954) 2024-04-23T20:08:18.174Z,1713902898.174 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T20:08:18.174Z,1713902898.174 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T20:08:30.660Z,1713902910.660 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20240423T163357/Courier0112.lzma 2024-04-23T20:08:31.663Z,1713902911.663 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0112.lzma.bak 2024-04-23T20:08:31.663Z,1713902911.663 [DataOverHttps](INFO): SBD MOMSN=19423925 2024-04-23T20:08:48.892Z,1713902928.892 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T20:08:48.968Z,1713902928.968 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T20:08:49.840Z,1713902929.840 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20240423T163357/Express0113.lzma 2024-04-23T20:08:50.843Z,1713902930.843 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0113.lzma.bak 2024-04-23T20:08:50.843Z,1713902930.843 [DataOverHttps](INFO): SBD MOMSN=19423928 2024-04-23T20:08:53.754Z,1713902933.754 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T20:08:53.754Z,1713902933.754 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T20:08:53.755Z,1713902933.755 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T20:13:20.426Z,1713903200.426 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T20:13:51.166Z,1713903231.166 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T20:13:54.418Z,1713903234.418 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T20:13:54.418Z,1713903234.418 [Default:CheckIn:C.Wait] Stopped 2024-04-23T20:13:54.418Z,1713903234.418 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T20:13:54.418Z,1713903234.418 [Default:CheckIn:D] Running Loop=1 2024-04-23T20:13:54.805Z,1713903234.805 [Default:CheckIn:D] Stopped 2024-04-23T20:13:54.805Z,1713903234.805 [Default:CheckIn:E] Running Loop=1 2024-04-23T20:13:55.214Z,1713903235.214 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 214.368034 min 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn:E] Stopped 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn] Stopped 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn](INFO): Running loop #38 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn] Running Loop=38 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T20:13:55.215Z,1713903235.215 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T20:13:57.196Z,1713903237.196 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201356.00,A,3648.16782,N,12147.28697,W,0.311,139.31,230424,,,A*76 2024-04-23T20:13:57.198Z,1713903237.198 [NAL9602](INFO): GPS fix at 20240423T201356: (36.802797, -121.788116) 2024-04-23T20:13:57.283Z,1713903237.283 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T20:13:57.283Z,1713903237.283 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T20:13:59.028Z,1713903239.028 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20240423T163357/Courier0115.lzma 2024-04-23T20:14:00.035Z,1713903240.035 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0115.lzma.bak 2024-04-23T20:14:00.035Z,1713903240.035 [DataOverHttps](INFO): SBD MOMSN=19423973 2024-04-23T20:14:18.473Z,1713903258.473 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0116.lzma 2024-04-23T20:14:19.475Z,1713903259.475 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0116.lzma.bak 2024-04-23T20:14:19.475Z,1713903259.475 [DataOverHttps](INFO): SBD MOMSN=19423976 2024-04-23T20:14:24.073Z,1713903264.073 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T20:14:24.073Z,1713903264.073 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T20:14:24.073Z,1713903264.073 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T20:14:27.655Z,1713903267.655 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2024-04-23T20:14:27.733Z,1713903267.733 [NAL9602](ERROR): received: +CSQ:0 OK449, 2, 0, 0, 0 OK 2024-04-23T20:18:59.704Z,1713903539.704 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2024-04-23T20:19:24.810Z,1713903564.810 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T20:19:24.810Z,1713903564.810 [Default:CheckIn:C.Wait] Stopped 2024-04-23T20:19:24.810Z,1713903564.810 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T20:19:24.810Z,1713903564.810 [Default:CheckIn:D] Running Loop=1 2024-04-23T20:19:25.177Z,1713903565.177 [Default:CheckIn:D] Stopped 2024-04-23T20:19:25.178Z,1713903565.178 [Default:CheckIn:E] Running Loop=1 2024-04-23T20:19:25.604Z,1713903565.604 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 219.874235 min 2024-04-23T20:19:25.604Z,1713903565.604 [Default:CheckIn:E] Stopped 2024-04-23T20:19:25.604Z,1713903565.604 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T20:19:25.604Z,1713903565.604 [Default:CheckIn] Stopped 2024-04-23T20:19:25.604Z,1713903565.604 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T20:19:25.609Z,1713903565.609 [Default:CheckIn](INFO): Running loop #39 2024-04-23T20:19:25.609Z,1713903565.609 [Default:CheckIn] Running Loop=39 2024-04-23T20:19:25.609Z,1713903565.609 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T20:19:25.609Z,1713903565.609 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T20:19:27.584Z,1713903567.584 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201926.00,A,3648.16952,N,12147.28752,W,0.253,200.36,230424,,,A*79 2024-04-23T20:19:27.586Z,1713903567.586 [NAL9602](INFO): GPS fix at 20240423T201926: (36.802825, -121.788125) 2024-04-23T20:19:27.635Z,1713903567.635 [Default:CheckIn:Read_GPS] Stopped 2024-04-23T20:19:27.635Z,1713903567.635 [Default:CheckIn:Read_Iridium] Running Loop=1 2024-04-23T20:19:29.661Z,1713903569.661 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20240423T163357/Courier0118.lzma 2024-04-23T20:19:30.767Z,1713903570.767 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Courier0118.lzma.bak 2024-04-23T20:19:30.767Z,1713903570.767 [DataOverHttps](INFO): SBD MOMSN=19423982 2024-04-23T20:19:51.841Z,1713903591.841 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20240423T163357/Express0119.lzma 2024-04-23T20:19:52.843Z,1713903592.843 [DataOverHttps](INFO): Moved sent file to Logs/20240423T163357/Express0119.lzma.bak 2024-04-23T20:19:52.843Z,1713903592.843 [DataOverHttps](INFO): SBD MOMSN=19423985 2024-04-23T20:19:57.459Z,1713903597.459 [Default:CheckIn:Read_Iridium] Stopped 2024-04-23T20:19:57.459Z,1713903597.459 [Default:CheckIn:C.Wait] Running Loop=1 2024-04-23T20:19:57.459Z,1713903597.459 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2024-04-23T20:20:00.614Z,1713903600.614 [NAL9602](INFO): Not Powering down - fast GPS 2024-04-23T20:21:17.039Z,1713903677.039 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2024-04-23T20:24:58.058Z,1713903898.058 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2024-04-23T20:24:58.058Z,1713903898.058 [Default:CheckIn:C.Wait] Stopped 2024-04-23T20:24:58.058Z,1713903898.058 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2024-04-23T20:24:58.058Z,1713903898.058 [Default:CheckIn:D] Running Loop=1 2024-04-23T20:24:58.456Z,1713903898.456 [Default:CheckIn:D] Stopped 2024-04-23T20:24:58.476Z,1713903898.476 [Default:CheckIn:E] Running Loop=1 2024-04-23T20:24:58.858Z,1713903898.858 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 225.428890 min 2024-04-23T20:24:58.858Z,1713903898.858 [Default:CheckIn:E] Stopped 2024-04-23T20:24:58.858Z,1713903898.858 [Default:CheckIn](INFO): Completed Default:CheckIn 2024-04-23T20:24:58.858Z,1713903898.858 [Default:CheckIn] Stopped 2024-04-23T20:24:58.858Z,1713903898.858 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2024-04-23T20:24:58.859Z,1713903898.859 [Default:CheckIn](INFO): Running loop #40 2024-04-23T20:24:58.859Z,1713903898.859 [Default:CheckIn] Running Loop=40 2024-04-23T20:24:58.859Z,1713903898.859 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2024-04-23T20:24:58.859Z,1713903898.859 [Default:CheckIn:Read_GPS] Running Loop=1 2024-04-23T20:25:00.870Z,1713903900.870 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202500.00,A,3648.16331,N,12147.28621,W,0.797,200.36,230424,,,A*75 2024-04-23T20:25:00.874Z,1713903900.874 [NAL9602](INFO): GPS fix at 20240423T202500: (36.802722, -121.788104) 2024-04-23T20:25:00.885Z,1713903900.885 [Default:CheckIn:Rea