2023-05-18T17:13:35.900Z,1684430015.900 [Supervisor](DEBUG): Initializing supervisor.
2023-05-18T17:13:35.904Z,1684430015.904 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2023-05-18T17:13:35.905Z,1684430015.905 [SyncHandler](INFO): Protected caller Thread ID is 1198
2023-05-18T17:13:35.905Z,1684430015.905 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2023-05-18T17:13:35.906Z,1684430015.906 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2023-05-18T17:13:35.906Z,1684430015.906 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1199
2023-05-18T17:13:35.910Z,1684430015.910 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2023-05-18T17:13:35.928Z,1684430015.928 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2023-05-18T17:13:35.928Z,1684430015.928 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2023-05-18T17:13:35.929Z,1684430015.929 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 1200
2023-05-18T17:13:35.933Z,1684430015.933 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2023-05-18T17:13:35.934Z,1684430015.934 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2023-05-18T17:13:35.934Z,1684430015.934 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1201
2023-05-18T17:13:35.936Z,1684430015.936 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2023-05-18T17:13:35.937Z,1684430015.937 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2023-05-18T17:13:35.938Z,1684430015.938 [logger ThreadHandler](INFO): Protected caller Thread ID is 1202
2023-05-18T17:13:35.941Z,1684430015.941 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2023-05-18T17:13:35.942Z,1684430015.942 [Supervisor](INFO): Looking for Config files in directory: Config/
2023-05-18T17:13:35.943Z,1684430015.943 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2023-05-18T17:13:36.264Z,1684430016.264 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2023-05-18T17:13:36.264Z,1684430016.264 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2023-05-18T17:13:36.911Z,1684430016.911 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2023-05-18T17:13:36.912Z,1684430016.912 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2023-05-18T17:13:37.017Z,1684430017.017 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2023-05-18T17:13:37.018Z,1684430017.018 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2023-05-18T17:13:37.494Z,1684430017.494 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2023-05-18T17:13:37.495Z,1684430017.495 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2023-05-18T17:13:37.589Z,1684430017.589 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2023-05-18T17:13:37.590Z,1684430017.590 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2023-05-18T17:13:37.670Z,1684430017.670 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2023-05-18T17:13:38.050Z,1684430018.050 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2023-05-18T17:13:38.051Z,1684430018.051 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2023-05-18T17:13:38.270Z,1684430018.270 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2023-05-18T17:13:38.270Z,1684430018.270 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2023-05-18T17:13:38.403Z,1684430018.403 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2023-05-18T17:13:38.404Z,1684430018.404 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2023-05-18T17:13:38.627Z,1684430018.627 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2023-05-18T17:13:38.627Z,1684430018.627 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2023-05-18T17:13:39.122Z,1684430019.122 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2023-05-18T17:13:39.123Z,1684430019.123 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2023-05-18T17:13:39.481Z,1684430019.481 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2023-05-18T17:13:39.482Z,1684430019.482 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2023-05-18T17:13:39.561Z,1684430019.561 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2023-05-18T17:13:39.739Z,1684430019.739 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2023-05-18T17:13:39.740Z,1684430019.740 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2023-05-18T17:13:39.951Z,1684430019.951 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2023-05-18T17:13:39.952Z,1684430019.952 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2023-05-18T17:13:40.344Z,1684430020.344 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2023-05-18T17:13:40.346Z,1684430020.346 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2023-05-18T17:13:40.347Z,1684430020.347 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2023-05-18T17:13:40.512Z,1684430020.512 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2023-05-18T17:13:40.681Z,1684430020.681 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2023-05-18T17:13:40.861Z,1684430020.861 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2023-05-18T17:13:40.943Z,1684430020.943 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2023-05-18T17:13:41.049Z,1684430021.049 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2023-05-18T17:13:41.217Z,1684430021.217 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2023-05-18T17:13:41.474Z,1684430021.474 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2023-05-18T17:13:41.475Z,1684430021.475 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2023-05-18T17:13:41.602Z,1684430021.602 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2023-05-18T17:13:41.693Z,1684430021.693 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2023-05-18T17:13:41.795Z,1684430021.795 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2023-05-18T17:13:41.895Z,1684430021.895 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/root/
2023-05-18T17:13:41.895Z,1684430021.895 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2023-05-18T17:13:41.920Z,1684430021.920 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2023-05-18T17:13:42.016Z,1684430022.016 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2023-05-18T17:13:42.017Z,1684430022.017 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2023-05-18T17:13:42.027Z,1684430022.027 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2023-05-18T17:13:42.027Z,1684430022.027 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2023-05-18T17:13:42.077Z,1684430022.077 [DepthRateCalculator] Loaded
2023-05-18T17:13:42.077Z,1684430022.077 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2023-05-18T17:13:42.083Z,1684430022.083 [PitchRateCalculator] Loaded
2023-05-18T17:13:42.083Z,1684430022.083 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2023-05-18T17:13:42.093Z,1684430022.093 [SpeedCalculator] Loaded
2023-05-18T17:13:42.093Z,1684430022.093 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2023-05-18T17:13:42.098Z,1684430022.098 [YawRateCalculator] Loaded
2023-05-18T17:13:42.098Z,1684430022.098 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2023-05-18T17:13:42.119Z,1684430022.119 [ElevatorOffsetCalculator] Loaded
2023-05-18T17:13:42.120Z,1684430022.120 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2023-05-18T17:13:42.120Z,1684430022.120 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2023-05-18T17:13:42.121Z,1684430022.121 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2023-05-18T17:13:42.169Z,1684430022.169 [VerticalControl](DEBUG): Construct VerticalControl.
2023-05-18T17:13:42.224Z,1684430022.224 [VerticalControl] Loaded
2023-05-18T17:13:42.225Z,1684430022.225 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2023-05-18T17:13:42.227Z,1684430022.227 [HorizontalControl](DEBUG): Construct HorizontalControl.
2023-05-18T17:13:42.268Z,1684430022.268 [HorizontalControl] Loaded
2023-05-18T17:13:42.268Z,1684430022.268 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2023-05-18T17:13:42.270Z,1684430022.270 [SpeedControl](DEBUG): Construct SpeedControl.
2023-05-18T17:13:42.273Z,1684430022.273 [SpeedControl] Loaded
2023-05-18T17:13:42.273Z,1684430022.273 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2023-05-18T17:13:42.276Z,1684430022.276 [LoopControl](DEBUG): Construct LoopControl.
2023-05-18T17:13:42.276Z,1684430022.276 [LoopControl] Loaded
2023-05-18T17:13:42.277Z,1684430022.277 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2023-05-18T17:13:42.277Z,1684430022.277 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2023-05-18T17:13:42.278Z,1684430022.278 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2023-05-18T17:13:42.386Z,1684430022.386 [DeadReckonUsingMultipleVelocitySources] Loaded
2023-05-18T17:13:42.387Z,1684430022.387 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2023-05-18T17:13:42.400Z,1684430022.400 [NavChart] Loaded
2023-05-18T17:13:42.400Z,1684430022.400 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2023-05-18T17:13:42.406Z,1684430022.406 [UniversalFixResidualReporter] Loaded
2023-05-18T17:13:42.406Z,1684430022.406 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2023-05-18T17:13:42.407Z,1684430022.407 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2023-05-18T17:13:42.407Z,1684430022.407 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2023-05-18T17:13:42.551Z,1684430022.551 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2023-05-18T17:13:42.552Z,1684430022.552 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2023-05-18T17:13:43.005Z,1684430023.005 [AHRS_M2] Loaded
2023-05-18T17:13:43.005Z,1684430023.005 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2023-05-18T17:13:43.040Z,1684430023.040 [BackseatComponent] Loaded
2023-05-18T17:13:43.040Z,1684430023.040 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2023-05-18T17:13:43.041Z,1684430023.041 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 4090D4E0
2023-05-18T17:13:43.041Z,1684430023.041 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 1284
2023-05-18T17:13:43.044Z,1684430023.044 [LcmUniversalReporter] Loaded
2023-05-18T17:13:43.044Z,1684430023.044 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2023-05-18T17:13:43.842Z,1684430023.842 [BPC1] Loaded
2023-05-18T17:13:43.842Z,1684430023.842 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2023-05-18T17:13:43.929Z,1684430023.929 [DAT] Loaded
2023-05-18T17:13:43.929Z,1684430023.929 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2023-05-18T17:13:43.930Z,1684430023.930 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 4093D4E0
2023-05-18T17:13:43.931Z,1684430023.931 [DAT ThreadHandler](INFO): Protected caller Thread ID is 1285
2023-05-18T17:13:44.002Z,1684430024.002 [DataOverHttps] Loaded
2023-05-18T17:13:44.002Z,1684430024.002 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2023-05-18T17:13:44.003Z,1684430024.003 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4096D4E0
2023-05-18T17:13:44.003Z,1684430024.003 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1286
2023-05-18T17:13:44.023Z,1684430024.023 [Depth_Keller] Loaded
2023-05-18T17:13:44.024Z,1684430024.024 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2023-05-18T17:13:44.061Z,1684430024.061 [DVL_micro] Loaded
2023-05-18T17:13:44.061Z,1684430024.061 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2023-05-18T17:13:44.122Z,1684430024.122 [NAL9602] Loaded
2023-05-18T17:13:44.122Z,1684430024.122 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2023-05-18T17:13:44.151Z,1684430024.151 [Onboard] Loaded
2023-05-18T17:13:44.152Z,1684430024.152 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2023-05-18T17:13:44.153Z,1684430024.153 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4099D4E0
2023-05-18T17:13:44.153Z,1684430024.153 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 1287
2023-05-18T17:13:44.165Z,1684430024.165 [Power24vConverter] Loaded
2023-05-18T17:13:44.165Z,1684430024.165 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2023-05-18T17:13:44.178Z,1684430024.178 [Radio_Surface] Loaded
2023-05-18T17:13:44.178Z,1684430024.178 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2023-05-18T17:13:44.179Z,1684430024.179 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409CD4E0
2023-05-18T17:13:44.179Z,1684430024.179 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1288
2023-05-18T17:13:44.181Z,1684430024.181 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2023-05-18T17:13:44.181Z,1684430024.181 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2023-05-18T17:13:44.309Z,1684430024.309 [BuoyancyServo] Loaded
2023-05-18T17:13:44.309Z,1684430024.309 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2023-05-18T17:13:44.330Z,1684430024.330 [ElevatorServo] Loaded
2023-05-18T17:13:44.330Z,1684430024.330 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2023-05-18T17:13:44.350Z,1684430024.350 [MassServo] Loaded
2023-05-18T17:13:44.350Z,1684430024.350 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2023-05-18T17:13:44.368Z,1684430024.368 [RudderServo] Loaded
2023-05-18T17:13:44.368Z,1684430024.368 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2023-05-18T17:13:44.383Z,1684430024.383 [ThrusterHE] Loaded
2023-05-18T17:13:44.383Z,1684430024.383 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2023-05-18T17:13:44.383Z,1684430024.383 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2023-05-18T17:13:44.384Z,1684430024.384 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2023-05-18T17:13:44.451Z,1684430024.451 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2023-05-18T17:13:44.452Z,1684430024.452 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2023-05-18T17:13:44.478Z,1684430024.478 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2023-05-18T17:13:44.479Z,1684430024.479 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2023-05-18T17:13:44.780Z,1684430024.780 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2023-05-18T17:13:44.780Z,1684430024.780 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2023-05-18T17:13:44.946Z,1684430024.946 [CTD_Seabird] Loaded
2023-05-18T17:13:44.947Z,1684430024.947 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2023-05-18T17:13:44.948Z,1684430024.948 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B634E0
2023-05-18T17:13:44.948Z,1684430024.948 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1289
2023-05-18T17:13:44.980Z,1684430024.980 [ESPComponent] Loaded
2023-05-18T17:13:44.981Z,1684430024.981 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2023-05-18T17:13:44.000Z,1684430025.000 [PAR_Licor] Loaded
2023-05-18T17:13:45.000Z,1684430025.000 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2023-05-18T17:13:45.032Z,1684430025.032 [WetLabsBB2FL] Loaded
2023-05-18T17:13:45.032Z,1684430025.032 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2023-05-18T17:13:45.033Z,1684430025.033 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B934E0
2023-05-18T17:13:45.033Z,1684430025.033 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1290
2023-05-18T17:13:45.034Z,1684430025.034 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2023-05-18T17:13:45.035Z,1684430025.035 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2023-05-18T17:13:45.175Z,1684430025.175 [SBIT](DEBUG): Construct Startup Built In Test.
2023-05-18T17:13:45.184Z,1684430025.184 [SBIT] Loaded
2023-05-18T17:13:45.184Z,1684430025.184 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2023-05-18T17:13:45.187Z,1684430025.187 [IBIT](DEBUG): Construct Initiated Built In Test.
2023-05-18T17:13:45.200Z,1684430025.200 [IBIT] Loaded
2023-05-18T17:13:45.200Z,1684430025.200 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2023-05-18T17:13:45.206Z,1684430025.206 [CBIT](DEBUG): Construct Continuous Built In Test.
2023-05-18T17:13:45.309Z,1684430025.309 [CBIT] Loaded
2023-05-18T17:13:45.309Z,1684430025.309 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2023-05-18T17:13:45.310Z,1684430025.310 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2023-05-18T17:13:45.316Z,1684430025.316 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2023-05-18T17:13:45.318Z,1684430025.318 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2023-05-18T17:13:45.329Z,1684430025.329 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2023-05-18T17:13:45.330Z,1684430025.330 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C014E0
2023-05-18T17:13:45.331Z,1684430025.331 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1291
2023-05-18T17:13:45.335Z,1684430025.335 [Supervisor](INFO): Main Thread ID is 828
2023-05-18T17:13:45.335Z,1684430025.335 [Supervisor](DEBUG): Running supervisor.
2023-05-18T17:13:45.336Z,1684430025.336 [CommandExec ThreadHandler](INFO): Handler Thread ID is 1292
2023-05-18T17:13:45.336Z,1684430025.336 [CommandExec](INFO): Initializing the command executive.
2023-05-18T17:13:45.338Z,1684430025.338 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1293
2023-05-18T17:13:45.341Z,1684430025.341 [controlThread ThreadHandler](INFO): Handler Thread ID is 1294
2023-05-18T17:13:45.341Z,1684430025.341 [controlThread](DEBUG): Initializing ControlThread
2023-05-18T17:13:45.342Z,1684430025.342 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2023-05-18T17:13:45.342Z,1684430025.342 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2023-05-18T17:13:45.343Z,1684430025.343 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2023-05-18T17:13:45.343Z,1684430025.343 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2023-05-18T17:13:45.343Z,1684430025.343 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2023-05-18T17:13:45.344Z,1684430025.344 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2023-05-18T17:13:45.346Z,1684430025.346 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2023-05-18T17:13:45.347Z,1684430025.347 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2023-05-18T17:13:45.347Z,1684430025.347 [LoopControl](DEBUG): Initialize LoopControlComponent.
2023-05-18T17:13:45.348Z,1684430025.348 [NavChart](DEBUG): Initialize NavChart Navigation.
2023-05-18T17:13:45.348Z,1684430025.348 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2023-05-18T17:13:45.356Z,1684430025.356 [SBIT](INFO): Initialize SBIT Component.
2023-05-18T17:13:45.357Z,1684430025.357 [SBIT](IMPORTANT): git: 2023-05-16
2023-05-18T17:13:45.357Z,1684430025.357 [SBIT](INFO): git hash: e007e0a7bd79249c04679d833c4d8cc0d57fc61d
2023-05-18T17:13:45.357Z,1684430025.357 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2023-05-18T17:13:45.358Z,1684430025.358 [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
2023-05-18T17:13:45.360Z,1684430025.360 [SBIT](INFO): Beginning SBIT in 59.000000 seconds.
2023-05-18T17:13:45.360Z,1684430025.360 [IBIT](INFO): Initialize IBIT Component.
2023-05-18T17:13:45.361Z,1684430025.361 [CBIT](DEBUG): Initialize CBIT Component.
2023-05-18T17:13:45.362Z,1684430025.362 [logger ThreadHandler](INFO): Handler Thread ID is 1295
2023-05-18T17:13:45.372Z,1684430025.372 [CBIT](DEBUG): Initialized mux pins.
2023-05-18T17:13:45.372Z,1684430025.372 [CBIT](DEBUG): Initializing the watchdog timer.
2023-05-18T17:13:45.396Z,1684430025.396 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2023-05-18T17:13:45.397Z,1684430025.397 [CBIT](DEBUG): Initializing heartbeat.
2023-05-18T17:13:45.408Z,1684430025.408 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 1296
2023-05-18T17:13:45.421Z,1684430025.421 [DAT ThreadHandler](INFO): Handler Thread ID is 1297
2023-05-18T17:13:45.422Z,1684430025.422 [DAT](INFO): Powering up
2023-05-18T17:13:45.422Z,1684430025.422 [DAT](DEBUG): Initializing DAT.
2023-05-18T17:13:45.423Z,1684430025.423 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1299
2023-05-18T17:13:45.424Z,1684430025.424 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2023-05-18T17:13:45.427Z,1684430025.427 [Onboard ThreadHandler](INFO): Handler Thread ID is 1300
2023-05-18T17:13:45.456Z,1684430025.456 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1302
2023-05-18T17:13:45.461Z,1684430025.461 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2023-05-18T17:13:45.466Z,1684430025.466 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1301
2023-05-18T17:13:45.468Z,1684430025.468 [CBIT](DEBUG): Deactivating GF circuits.
2023-05-18T17:13:45.468Z,1684430025.468 [CBIT](DEBUG): Deactivating emergency mode.
2023-05-18T17:13:45.473Z,1684430025.473 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1304
2023-05-18T17:13:45.476Z,1684430025.476 [WetLabsBB2FL](INFO): Powering up
2023-05-18T17:13:45.508Z,1684430025.508 [CBIT](DEBUG): Backplane powered.
2023-05-18T17:13:45.509Z,1684430025.509 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2023-05-18T17:13:45.522Z,1684430025.522 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-18T17:13:45.529Z,1684430025.529 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1306
2023-05-18T17:13:45.531Z,1684430025.531 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2023-05-18T17:13:45.531Z,1684430025.531 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2023-05-18T17:13:45.532Z,1684430025.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2023-05-18T17:13:45.532Z,1684430025.532 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2023-05-18T17:13:45.532Z,1684430025.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2023-05-18T17:13:45.532Z,1684430025.532 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2023-05-18T17:13:45.532Z,1684430025.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2023-05-18T17:13:45.533Z,1684430025.533 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2023-05-18T17:13:45.593Z,1684430025.593 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2023-05-18T17:13:45.594Z,1684430025.594 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2023-05-18T17:13:45.708Z,1684430025.708 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2023-05-18T17:13:45.709Z,1684430025.709 [Default:A.Wait](DEBUG): Construct Wait.
2023-05-18T17:13:45.712Z,1684430025.712 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-18T17:13:45.767Z,1684430025.767 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2023-05-18T17:13:45.785Z,1684430025.785 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2023-05-18T17:13:45.791Z,1684430025.791 [Default:E.Execute](DEBUG): Construct Execute.
2023-05-18T17:13:45.810Z,1684430025.810 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P4H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2023-05-18T17:13:45.815Z,1684430025.815 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DVL_micro,NAL9602,Power24vConverter,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,
2023-05-18T17:13:45.837Z,1684430025.837 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2023-05-18T17:13:45.868Z,1684430025.868 [Radio_Surface](INFO): Powering up
2023-05-18T17:13:45.926Z,1684430025.926 [Power24vConverter](INFO): Powering up.
2023-05-18T17:13:45.962Z,1684430025.962 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2023-05-18T17:13:45.968Z,1684430025.968 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2023-05-18T17:13:45.969Z,1684430025.969 [ElevatorServo](DEBUG): Initializing EZServoServo.
2023-05-18T17:13:45.977Z,1684430025.977 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2023-05-18T17:13:45.978Z,1684430025.978 [MassServo](DEBUG): Initializing EZServoServo.
2023-05-18T17:13:45.984Z,1684430025.984 [MassServo](DEBUG): Initializing MassServo.
2023-05-18T17:13:45.985Z,1684430025.985 [RudderServo](DEBUG): Initializing EZServoServo.
2023-05-18T17:13:45.992Z,1684430025.992 [RudderServo](DEBUG): Initializing RudderServo.
2023-05-18T17:13:45.993Z,1684430025.993 [ThrusterHE](DEBUG): Initializing EZServoServo.
2023-05-18T17:13:46.000Z,1684430026.000 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2023-05-18T17:13:48.088Z,1684430028.088 [WetLabsBB2FL](INFO): Powering down
2023-05-18T17:13:51.641Z,1684430031.641 [ThrusterHE](ERROR): Zero Speed Commanded.
2023-05-18T17:13:52.489Z,1684430032.489 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2023-05-18T17:14:00.038Z,1684430040.038 [DAT](INFO): commRate: 800
2023-05-18T17:14:02.116Z,1684430042.116 [DAT](INFO): entering command mode
2023-05-18T17:14:02.116Z,1684430042.116 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:02.305Z,1684430042.305 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:02.305Z,1684430042.305 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:02.557Z,1684430042.557 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:02.557Z,1684430042.557 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:02.809Z,1684430042.809 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:02.809Z,1684430042.809 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.060Z,1684430043.060 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.061Z,1684430043.061 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.313Z,1684430043.313 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.313Z,1684430043.313 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.564Z,1684430043.564 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.565Z,1684430043.565 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.817Z,1684430043.817 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:03.817Z,1684430043.817 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.069Z,1684430044.069 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.069Z,1684430044.069 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.321Z,1684430044.321 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.321Z,1684430044.321 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.573Z,1684430044.573 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.573Z,1684430044.573 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.824Z,1684430044.824 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:04.824Z,1684430044.824 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.077Z,1684430045.077 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.077Z,1684430045.077 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.331Z,1684430045.331 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.331Z,1684430045.331 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.580Z,1684430045.580 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.580Z,1684430045.580 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.833Z,1684430045.833 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:05.833Z,1684430045.833 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.084Z,1684430046.084 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.085Z,1684430046.085 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.338Z,1684430046.338 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.338Z,1684430046.338 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.589Z,1684430046.589 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.589Z,1684430046.589 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.841Z,1684430046.841 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:06.841Z,1684430046.841 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.093Z,1684430047.093 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.093Z,1684430047.093 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.345Z,1684430047.345 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.345Z,1684430047.345 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.597Z,1684430047.597 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.597Z,1684430047.597 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.849Z,1684430047.849 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:07.849Z,1684430047.849 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.101Z,1684430048.101 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.101Z,1684430048.101 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.353Z,1684430048.353 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.353Z,1684430048.353 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.605Z,1684430048.605 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.605Z,1684430048.605 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.856Z,1684430048.856 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:08.857Z,1684430048.857 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.108Z,1684430049.108 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.109Z,1684430049.109 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.361Z,1684430049.361 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.361Z,1684430049.361 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.613Z,1684430049.613 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.613Z,1684430049.613 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.865Z,1684430049.865 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:09.865Z,1684430049.865 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.118Z,1684430050.118 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.118Z,1684430050.118 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.368Z,1684430050.368 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.368Z,1684430050.368 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.621Z,1684430050.621 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.621Z,1684430050.621 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.872Z,1684430050.872 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:10.873Z,1684430050.873 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.124Z,1684430051.124 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.125Z,1684430051.125 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.377Z,1684430051.377 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.377Z,1684430051.377 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.628Z,1684430051.628 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.629Z,1684430051.629 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.881Z,1684430051.881 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:11.881Z,1684430051.881 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.133Z,1684430052.133 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.134Z,1684430052.134 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.385Z,1684430052.385 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.385Z,1684430052.385 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.637Z,1684430052.637 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.637Z,1684430052.637 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.888Z,1684430052.888 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:12.889Z,1684430052.889 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.142Z,1684430053.142 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.143Z,1684430053.143 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.393Z,1684430053.393 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.393Z,1684430053.393 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.645Z,1684430053.645 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.645Z,1684430053.645 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.897Z,1684430053.897 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:13.897Z,1684430053.897 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.149Z,1684430054.149 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.149Z,1684430054.149 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.401Z,1684430054.401 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.401Z,1684430054.401 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.510Z,1684430054.510 [NAL9602](INFO): Powering up NAL9602
2023-05-18T17:14:14.653Z,1684430054.653 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.653Z,1684430054.653 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.905Z,1684430054.905 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:14.905Z,1684430054.905 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.156Z,1684430055.156 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.157Z,1684430055.157 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.409Z,1684430055.409 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.409Z,1684430055.409 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.661Z,1684430055.661 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.661Z,1684430055.661 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.913Z,1684430055.913 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:15.913Z,1684430055.913 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.165Z,1684430056.165 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.165Z,1684430056.165 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.416Z,1684430056.416 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.417Z,1684430056.417 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.669Z,1684430056.669 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.669Z,1684430056.669 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.921Z,1684430056.921 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:16.921Z,1684430056.921 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:17.173Z,1684430057.173 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:17.173Z,1684430057.173 [DAT](FAULT): failed to enter command mode
2023-05-18T17:14:17.488Z,1684430057.488 [DAT](INFO): entering command mode
2023-05-18T17:14:17.488Z,1684430057.488 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-18T17:14:17.677Z,1684430057.677 [DAT](INFO): setting verbose to 3
2023-05-18T17:14:17.930Z,1684430057.930 [DAT](INFO): set verbose to 3
2023-05-18T17:14:17.930Z,1684430057.930 [DAT](INFO): setting DatVerbose to 27440
2023-05-18T17:14:18.182Z,1684430058.182 [DAT](INFO): set DatVerbose to 27440
2023-05-18T17:14:18.182Z,1684430058.182 [DAT](INFO): setting transmit power to 8
2023-05-18T17:14:18.434Z,1684430058.434 [DAT](INFO): set transmit power to 8
2023-05-18T17:14:18.434Z,1684430058.434 [DAT](INFO): setting local address to 11
2023-05-18T17:14:18.686Z,1684430058.686 [DAT](INFO): set local address to 11
2023-05-18T17:14:18.687Z,1684430058.687 [DAT](INFO): Setting time to: 17:14:18 And date to:5/18/2023
2023-05-18T17:14:18.938Z,1684430058.938 [DAT](INFO): Local DAT time set to Thu May 18, 2023  17:14:18  

2023-05-18T17:14:25.431Z,1684430065.431 [NAL9602](INFO): NAL9602 initialized
2023-05-18T17:14:44.831Z,1684430084.831 [SBIT](IMPORTANT): Beginning Startup BIT
2023-05-18T17:14:44.835Z,1684430084.835 [CBIT](IMPORTANT): Beginning ground fault scan
2023-05-18T17:14:55.872Z,1684430095.872 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004031
CHAN A1 (24V): 0.000299
CHAN A2 (12V): 0.001550
CHAN A3 (5V): -0.000051
CHAN B0 (3.3V): 0.001139
CHAN B1 (3.15aV): 0.000610
CHAN B2 (3.15bV): 0.000644
CHAN B3 (GND): 0.000238
OPEN: 0.008155
Full Scale: +/- 1 mA
2023-05-18T17:15:31.285Z,1684430131.285 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T17:15:31.286Z,1684430131.286 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T17:15:38.977Z,1684430138.977 [SBIT](IMPORTANT): SBIT PASSED
2023-05-18T17:15:38.978Z,1684430138.978 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2023-05-18T17:15:38.978Z,1684430138.978 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=12 count;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): DAT.maxAckTimeouts=1 count;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): DAT.sbdAddress=-1 enum;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): DAT.verbosity=1 count;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): DATMMP.loadAtStartup=0 bool;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): DATMMP.simulateHardware=0 bool;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): Depth_Keller.offset=3.6 decibar;

2023-05-18T17:15:38.979Z,1684430138.979 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2023-05-18T17:15:38.980Z,1684430138.980 [SBIT](IMPORTANT): ESPComponent.sampleTimeout=3 minute;

2023-05-18T17:15:38.980Z,1684430138.980 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2023-05-18T17:15:38.980Z,1684430138.980 [SBIT](IMPORTANT): Express none CBIT.ampHoursUsed;

2023-05-18T17:15:38.980Z,1684430138.980 [SBIT](IMPORTANT): Express linearApproximation TrackAcousticContact.azimuth_to_contact_vehicle_frame 10.000000 angular_degree;

2023-05-18T17:15:38.980Z,1684430138.980 [SBIT](IMPORTANT): Express linearApproximation TrackAcousticContact.range_to_contact 10.000000 meter;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): Express none VerticalHomogeneityIndexCalculator.vertical_salinity_homogeneity_index;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): Express none VerticalHomogeneityIndexCalculator.vertical_temperature_homogeneity_index;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): Express none height_above_sea_floor;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): StratificationFrontDetector.loadAtStartup=0 bool;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): StratificationFrontDetector.threshold_VTHI=0.1 celsius;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): StratificationFrontDetector.verbosity=1 count;

2023-05-18T17:15:38.981Z,1684430138.981 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=208.61 cubic_centimeter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalControl.massDefault=-1 centimeter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalControl.massPositionLimitAft=-28 millimeter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalControl.massPositionLimitFwd=32 millimeter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=1.5 meter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth1=3 meter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth2=5 meter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth3=10 meter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth4=15 meter;

2023-05-18T17:15:38.982Z,1684430138.982 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.loadAtStartup=0 bool;

2023-05-18T17:15:39.359Z,1684430139.359 [MissionManager](IMPORTANT): Started mission Startup
2023-05-18T17:15:39.359Z,1684430139.359 [Startup] Running Loop=1
2023-05-18T17:15:39.359Z,1684430139.359 [Startup](DEBUG): Aggregate::initialize Startup
2023-05-18T17:15:39.359Z,1684430139.359 [Startup:A.GoToSurface] Running Loop=1
2023-05-18T17:15:39.359Z,1684430139.359 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-18T17:15:39.360Z,1684430139.360 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-18T17:15:39.360Z,1684430139.360 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-18T17:15:39.361Z,1684430139.361 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-18T17:15:39.361Z,1684430139.361 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-18T17:15:39.361Z,1684430139.361 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-18T17:15:39.362Z,1684430139.362 [Startup:StartupSatComms] Running Loop=1
2023-05-18T17:15:39.363Z,1684430139.363 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2023-05-18T17:15:39.363Z,1684430139.363 [Startup:StartupSatComms:A] Running Loop=1
2023-05-18T17:15:39.775Z,1684430139.775 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2023-05-18T17:15:49.867Z,1684430149.867 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T17:15:49.867Z,1684430149.867 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T17:16:39.554Z,1684430199.554 [Startup:StartupSatComms:A](INFO): Timed out from 2023-05-18T17:15:39.4Z
2023-05-18T17:16:39.554Z,1684430199.554 [Startup:StartupSatComms:A] Stopped
2023-05-18T17:16:39.555Z,1684430199.555 [Startup:StartupSatComms:B] Running Loop=1
2023-05-18T17:16:39.966Z,1684430199.966 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-18T17:16:45.624Z,1684430205.624 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2023-05-18T17:16:45.624Z,1684430205.624 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-18T17:16:45.651Z,1684430205.651 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-18T17:16:46.030Z,1684430206.030 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-18T17:16:46.030Z,1684430206.030 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2023-05-18T17:17:32.722Z,1684430252.722 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004172
2023-05-18T17:17:39.776Z,1684430259.776 [Startup:StartupSatComms:B](INFO): Timed out from 2023-05-18T17:16:39.6Z
2023-05-18T17:17:39.776Z,1684430259.776 [Startup:StartupSatComms:B] Stopped
2023-05-18T17:17:39.776Z,1684430259.776 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2023-05-18T17:17:39.776Z,1684430259.776 [Startup:StartupSatComms] Stopped
2023-05-18T17:17:39.776Z,1684430259.776 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2023-05-18T17:17:39.777Z,1684430259.777 [Startup](INFO): Completed Startup
2023-05-18T17:17:39.777Z,1684430259.777 [MissionManager](INFO): Startup is completed.
2023-05-18T17:17:39.777Z,1684430259.777 [MissionManager](INFO): Uninitializing Mission Startup
2023-05-18T17:17:39.777Z,1684430259.777 [Startup] Stopped
2023-05-18T17:17:39.778Z,1684430259.778 [Startup](DEBUG): Aggregate::uninitialize Startup
2023-05-18T17:17:39.778Z,1684430259.778 [Startup:A.GoToSurface] Stopped
2023-05-18T17:17:39.778Z,1684430259.778 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-18T17:17:39.976Z,1684430259.976 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230518T165612/Courier0010.lzma
2023-05-18T17:17:40.155Z,1684430260.155 [MissionManager](IMPORTANT): Started mission Default
2023-05-18T17:17:40.155Z,1684430260.155 [Default] Running Loop=1
2023-05-18T17:17:40.155Z,1684430260.155 [Default](DEBUG): Aggregate::initialize Default
2023-05-18T17:17:40.156Z,1684430260.156 [Default:B.GoToSurface] Running Loop=1
2023-05-18T17:17:40.156Z,1684430260.156 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-18T17:17:40.156Z,1684430260.156 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-18T17:17:40.156Z,1684430260.156 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-18T17:17:40.157Z,1684430260.157 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-18T17:17:40.157Z,1684430260.157 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-18T17:17:40.157Z,1684430260.157 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-18T17:17:40.158Z,1684430260.158 [Default:A.Wait] Running Loop=1
2023-05-18T17:17:40.158Z,1684430260.158 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:17:40.978Z,1684430260.978 [DataOverHttps](INFO): Moved sent file to Logs/20230518T165612/Courier0010.lzma.bak
2023-05-18T17:17:40.978Z,1684430260.978 [DataOverHttps](INFO): SBD MOMSN=18327090
2023-05-18T17:17:53.179Z,1684430273.179 [Default:A.Wait](INFO): Done Waiting.
2023-05-18T17:17:53.179Z,1684430273.179 [Default:A.Wait] Stopped
2023-05-18T17:17:53.179Z,1684430273.179 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:17:53.592Z,1684430273.592 [Default:CheckIn] Running Loop=1
2023-05-18T17:17:53.592Z,1684430273.592 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:17:53.592Z,1684430273.592 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:17:53.983Z,1684430273.983 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-05-18T17:17:54.769Z,1684430274.769 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:17:54.769Z,1684430274.769 [DVL_micro](ERROR): Failed to parse:
:RD,+09999.99,+0010.78,+0010.63
2023-05-18T17:19:28.890Z,1684430368.890 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-18T17:19:33.739Z,1684430373.739 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171933.00,A,3648.16571,N,12147.27983,W,0.039,20.97,180523,,,D*47
2023-05-18T17:19:33.743Z,1684430373.743 [NAL9602](INFO): GPS fix at 20230518T171933: (36.802762, -121.787997)
2023-05-18T17:19:33.797Z,1684430373.797 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:19:33.797Z,1684430373.797 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:19:34.185Z,1684430374.185 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-18T17:19:34.925Z,1684430374.925 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20230518T171335/Courier0000.lzma
2023-05-18T17:19:35.922Z,1684430375.922 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0000.lzma.bak
2023-05-18T17:19:35.922Z,1684430375.922 [DataOverHttps](INFO): SBD MOMSN=18327094
2023-05-18T17:19:58.295Z,1684430398.295 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20230518T171335/Courier0004.lzma
2023-05-18T17:19:59.290Z,1684430399.290 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0004.lzma.bak
2023-05-18T17:19:59.290Z,1684430399.290 [DataOverHttps](INFO): SBD MOMSN=18327097
2023-05-18T17:20:06.298Z,1684430406.298 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T17:20:18.652Z,1684430418.652 [DataOverHttps](INFO): Sending 192 bytes from file Logs/20230518T165612/Express0011.lzma
2023-05-18T17:20:19.654Z,1684430419.654 [DataOverHttps](INFO): Moved sent file to Logs/20230518T165612/Express0011.lzma.bak
2023-05-18T17:20:19.654Z,1684430419.654 [DataOverHttps](INFO): SBD MOMSN=18327100
2023-05-18T17:20:35.854Z,1684430435.854 [DataOverHttps](INFO): Sending 1239 bytes from file Logs/20230518T171335/Express0001.lzma
2023-05-18T17:20:36.854Z,1684430436.854 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0001.lzma.bak
2023-05-18T17:20:36.854Z,1684430436.854 [DataOverHttps](INFO): SBD MOMSN=18327105
2023-05-18T17:20:53.128Z,1684430453.128 [DataOverHttps](INFO): Sending 311 bytes from file Logs/20230518T171335/Express0005.lzma
2023-05-18T17:20:54.148Z,1684430454.148 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0005.lzma.bak
2023-05-18T17:20:54.149Z,1684430454.149 [DataOverHttps](INFO): SBD MOMSN=18327148
2023-05-18T17:20:55.319Z,1684430455.319 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:20:55.319Z,1684430455.319 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:20:55.319Z,1684430455.319 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:21:21.163Z,1684430481.163 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-18T17:21:21.170Z,1684430481.170 [BPC1](INFO): Calculating totals. Valid battery stick count: 48. Valid reserve battery stick count: 5.
2023-05-18T17:21:21.194Z,1684430481.194 [BPC1](INFO): Received data from all battery sticks.
2023-05-18T17:21:55.947Z,1684430515.947 [DVL_micro](ERROR): Failed to parse:
:WI,+00094,-0076,+00000,A
2023-05-18T17:22:06.022Z,1684430526.022 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:22:06.023Z,1684430526.023 [DVL_micro](ERROR): Failed to parse:
:RD,+00010.58,+0010.69,+0010.62
2023-05-18T17:25:01.904Z,1684430701.904 [CommandExec](IMPORTANT): got command maintain control VerticalControl.massPositionAction 2 centimeter
2023-05-18T17:25:01.908Z,1684430701.908 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.massPositionAction" handled in the control thread.
2023-05-18T17:25:02.192Z,1684430702.192 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DVL_micro,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.massPositionAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-18T17:25:14.858Z,1684430714.858 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 200 cubic_centimeter
2023-05-18T17:25:14.862Z,1684430714.862 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.buoyancyAction" handled in the control thread.
2023-05-18T17:25:15.139Z,1684430715.139 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DVL_micro,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.massPositionAction,Maintain_VerticalControl.buoyancyAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-18T17:25:23.584Z,1684430723.584 [DVL_micro](ERROR): Failed to parse:
:WI,-00253,-00120,+00002,+00000,A
2023-05-18T17:25:25.202Z,1684430725.202 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:25:25.202Z,1684430725.202 [DVL_micro](ERROR): Failed to parse:
:BI,+00000,+0002,+00000,A
2023-05-18T17:25:29.227Z,1684430729.227 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:25:29.227Z,1684430729.227 [DVL_micro](ERROR): Failed to parse:
:RD,+0010.74,+9999.992,+0010.54
2023-05-18T17:25:43.403Z,1684430743.403 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T17:25:43.404Z,1684430743.404 [DVL_micro](ERROR): Failed to parse:
:TS,000000.0,1489.0,000
2023-05-18T17:25:51.525Z,1684430751.525 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:25:51.525Z,1684430751.525 [DVL_micro](ERROR): Failed to parse:
:RD,+00010.63,+0010.78,+0010.48
2023-05-18T17:25:55.986Z,1684430755.986 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T17:25:55.986Z,1684430755.986 [Default:CheckIn:C.Wait] Stopped
2023-05-18T17:25:55.986Z,1684430755.986 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:25:55.986Z,1684430755.986 [Default:CheckIn:D] Running Loop=1
2023-05-18T17:25:56.395Z,1684430756.395 [Default:CheckIn:D] Stopped
2023-05-18T17:25:56.396Z,1684430756.396 [Default:CheckIn:E] Running Loop=1
2023-05-18T17:25:56.781Z,1684430756.781 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.270667 min 
2023-05-18T17:25:56.781Z,1684430756.781 [Default:CheckIn:E] Stopped
2023-05-18T17:25:56.782Z,1684430756.782 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T17:25:56.782Z,1684430756.782 [Default:CheckIn] Stopped
2023-05-18T17:25:56.782Z,1684430756.782 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T17:25:56.782Z,1684430756.782 [Default:CheckIn](INFO): Running loop #2
2023-05-18T17:25:56.782Z,1684430756.782 [Default:CheckIn] Running Loop=2
2023-05-18T17:25:56.782Z,1684430756.782 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:25:56.782Z,1684430756.782 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:25:58.796Z,1684430758.796 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172558.00,A,3648.16449,N,12147.28269,W,0.039,331.79,180523,,,D*7C
2023-05-18T17:25:58.802Z,1684430758.802 [NAL9602](INFO): GPS fix at 20230518T172558: (36.802742, -121.788045)
2023-05-18T17:25:58.867Z,1684430758.867 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:25:58.867Z,1684430758.867 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:26:03.255Z,1684430763.255 [CommandExec](IMPORTANT): got command maintain control VerticalControl.massPositionAction 2.5 centimeter
2023-05-18T17:26:13.604Z,1684430773.604 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20230518T171335/Courier0007.lzma
2023-05-18T17:26:14.607Z,1684430774.607 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0007.lzma.bak
2023-05-18T17:26:14.608Z,1684430774.608 [DataOverHttps](INFO): SBD MOMSN=18327174
2023-05-18T17:26:17.185Z,1684430777.185 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:26:17.185Z,1684430777.185 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.24,+0000.53,+00000.13
2023-05-18T17:26:23.551Z,1684430783.551 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 300 cubic_centimeter
2023-05-18T17:26:29.282Z,1684430789.282 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-18T17:26:29.356Z,1684430789.356 [NAL9602](ERROR): received: 
+CSQ:0

OK313, 2, 0, 0, 0

OK
2023-05-18T17:26:31.640Z,1684430791.640 [DataOverHttps](INFO): Sending 266 bytes from file Logs/20230518T171335/Express0008.lzma
2023-05-18T17:26:32.642Z,1684430792.642 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0008.lzma.bak
2023-05-18T17:26:32.642Z,1684430792.642 [DataOverHttps](INFO): SBD MOMSN=18327178
2023-05-18T17:26:33.741Z,1684430793.741 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:26:33.741Z,1684430793.741 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:26:33.741Z,1684430793.741 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:26:46.119Z,1684430806.119 [CommandExec](IMPORTANT): got command report mod platform_buoyancy_position
2023-05-18T17:26:46.283Z,1684430806.283 [Reporter](INFO): platform_buoyancy_position 291.940948 cc
2023-05-18T17:26:47.467Z,1684430807.467 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T17:26:47.467Z,1684430807.467 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T17:28:09.653Z,1684430889.653 [CommandExec](IMPORTANT): got command maintain control VerticalControl.massPositionAction 3 centimeter
2023-05-18T17:30:18.798Z,1684431018.798 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 250 cubic_centimeter
2023-05-18T17:30:20.567Z,1684431020.567 [Reporter](INFO): platform_buoyancy_position 296.372833 cc
2023-05-18T17:30:21.393Z,1684431021.393 [Reporter](INFO): platform_buoyancy_position 294.224030 cc
2023-05-18T17:30:21.754Z,1684431021.754 [Reporter](INFO): platform_buoyancy_position 288.583435 cc
2023-05-18T17:30:22.170Z,1684431022.170 [Reporter](INFO): platform_buoyancy_position 285.494537 cc
2023-05-18T17:30:22.582Z,1684431022.582 [Reporter](INFO): platform_buoyancy_position 279.316742 cc
2023-05-18T17:30:22.970Z,1684431022.970 [Reporter](INFO): platform_buoyancy_position 274.750549 cc
2023-05-18T17:30:23.374Z,1684431023.374 [Reporter](INFO): platform_buoyancy_position 270.452942 cc
2023-05-18T17:30:23.791Z,1684431023.791 [Reporter](INFO): platform_buoyancy_position 265.752441 cc
2023-05-18T17:30:24.230Z,1684431024.230 [Reporter](INFO): platform_buoyancy_position 259.843231 cc
2023-05-18T17:31:01.704Z,1684431061.704 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-18T17:31:32.401Z,1684431092.401 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T17:31:34.435Z,1684431094.435 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T17:31:34.436Z,1684431094.436 [Default:CheckIn:C.Wait] Stopped
2023-05-18T17:31:34.436Z,1684431094.436 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:31:34.436Z,1684431094.436 [Default:CheckIn:D] Running Loop=1
2023-05-18T17:31:34.843Z,1684431094.843 [Default:CheckIn:D] Stopped
2023-05-18T17:31:34.843Z,1684431094.843 [Default:CheckIn:E] Running Loop=1
2023-05-18T17:31:35.254Z,1684431095.254 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.911453 min 
2023-05-18T17:31:35.254Z,1684431095.254 [Default:CheckIn:E] Stopped
2023-05-18T17:31:35.254Z,1684431095.254 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T17:31:35.254Z,1684431095.254 [Default:CheckIn] Stopped
2023-05-18T17:31:35.255Z,1684431095.255 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T17:31:35.255Z,1684431095.255 [Default:CheckIn](INFO): Running loop #3
2023-05-18T17:31:35.255Z,1684431095.255 [Default:CheckIn] Running Loop=3
2023-05-18T17:31:35.255Z,1684431095.255 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:31:35.255Z,1684431095.255 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:31:37.255Z,1684431097.255 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173136.00,A,3648.16881,N,12147.27999,W,0.058,19.16,180523,,,D*45
2023-05-18T17:31:37.258Z,1684431097.258 [NAL9602](INFO): GPS fix at 20230518T173136: (36.802813, -121.788000)
2023-05-18T17:31:37.296Z,1684431097.296 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:31:37.296Z,1684431097.296 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:31:48.320Z,1684431108.320 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230518T171335/Courier0010.lzma
2023-05-18T17:31:49.322Z,1684431109.322 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0010.lzma.bak
2023-05-18T17:31:49.322Z,1684431109.322 [DataOverHttps](INFO): SBD MOMSN=18327189
2023-05-18T17:31:51.520Z,1684431111.520 [DVL_micro](ERROR): only read 0 of 4 data items
2023-05-18T17:31:51.520Z,1684431111.520 [DVL_micro](ERROR): Failed to parse:
:RD,,+0000.43,+0010.85,+0010.52
2023-05-18T17:32:05.516Z,1684431125.516 [DataOverHttps](INFO): Sending 350 bytes from file Logs/20230518T171335/Express0011.lzma
2023-05-18T17:32:06.518Z,1684431126.518 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0011.lzma.bak
2023-05-18T17:32:06.518Z,1684431126.518 [DataOverHttps](INFO): SBD MOMSN=18327192
2023-05-18T17:32:07.635Z,1684431127.635 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:32:07.635Z,1684431127.635 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:32:07.635Z,1684431127.635 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:32:08.018Z,1684431128.018 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-18T17:32:08.092Z,1684431128.092 [NAL9602](ERROR): received: 
+CSQ:0

OK313, 2, 0, 0, 0

OK
2023-05-18T17:32:48.419Z,1684431168.419 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T17:32:48.419Z,1684431168.419 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T17:33:04.989Z,1684431184.989 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T17:33:04.989Z,1684431184.989 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T17:34:59.328Z,1684431299.328 [DVL_micro](ERROR): Failed to parse:
:.99,+99999.99,+9999.99
2023-05-18T17:36:39.571Z,1684431399.571 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-18T17:37:08.274Z,1684431428.274 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T17:37:08.275Z,1684431428.275 [Default:CheckIn:C.Wait] Stopped
2023-05-18T17:37:08.275Z,1684431428.275 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:37:08.275Z,1684431428.275 [Default:CheckIn:D] Running Loop=1
2023-05-18T17:37:08.673Z,1684431428.673 [Default:CheckIn:D] Stopped
2023-05-18T17:37:08.673Z,1684431428.673 [Default:CheckIn:E] Running Loop=1
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 19.475293 min 
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn:E] Stopped
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn] Stopped
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn](INFO): Running loop #4
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn] Running Loop=4
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:37:09.081Z,1684431429.081 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:37:11.082Z,1684431431.082 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173710.00,A,3648.16896,N,12147.28146,W,0.136,6.31,180523,,,A*73
2023-05-18T17:37:11.097Z,1684431431.097 [NAL9602](INFO): GPS fix at 20230518T173710: (36.802816, -121.788024)
2023-05-18T17:37:11.108Z,1684431431.108 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:37:11.108Z,1684431431.108 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:37:18.663Z,1684431438.663 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0013.lzma
2023-05-18T17:37:19.666Z,1684431439.666 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0013.lzma.bak
2023-05-18T17:37:19.666Z,1684431439.666 [DataOverHttps](INFO): SBD MOMSN=18327261
2023-05-18T17:37:35.616Z,1684431455.616 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20230518T171335/Express0014.lzma
2023-05-18T17:37:36.618Z,1684431456.618 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0014.lzma.bak
2023-05-18T17:37:36.618Z,1684431456.618 [DataOverHttps](INFO): SBD MOMSN=18327264
2023-05-18T17:37:37.756Z,1684431457.756 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:37:37.756Z,1684431457.756 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:37:37.756Z,1684431457.756 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:37:43.437Z,1684431463.437 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T17:39:30.887Z,1684431570.887 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 200 cubic_centimeter
2023-05-18T17:39:33.114Z,1684431573.114 [Reporter](INFO): platform_buoyancy_position 253.262558 cc
2023-05-18T17:39:33.882Z,1684431573.882 [Reporter](INFO): platform_buoyancy_position 251.248047 cc
2023-05-18T17:39:34.301Z,1684431574.301 [Reporter](INFO): platform_buoyancy_position 245.607422 cc
2023-05-18T17:39:34.710Z,1684431574.710 [Reporter](INFO): platform_buoyancy_position 242.115631 cc
2023-05-18T17:39:35.086Z,1684431575.086 [Reporter](INFO): platform_buoyancy_position 238.086639 cc
2023-05-18T17:39:35.506Z,1684431575.506 [Reporter](INFO): platform_buoyancy_position 232.043121 cc
2023-05-18T17:39:35.902Z,1684431575.902 [Reporter](INFO): platform_buoyancy_position 227.611237 cc
2023-05-18T17:39:36.318Z,1684431576.318 [Reporter](INFO): platform_buoyancy_position 221.164825 cc
2023-05-18T17:39:36.747Z,1684431576.747 [Reporter](INFO): platform_buoyancy_position 216.598633 cc
2023-05-18T17:39:37.128Z,1684431577.128 [Reporter](INFO): platform_buoyancy_position 212.569641 cc
2023-05-18T17:39:37.542Z,1684431577.542 [Reporter](INFO): platform_buoyancy_position 207.197632 cc
2023-05-18T17:39:47.165Z,1684431587.165 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:39:47.165Z,1684431587.165 [DVL_micro](ERROR): Failed to parse:
:BI,+0585,+00811,+00000,I
2023-05-18T17:42:38.528Z,1684431758.528 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T17:42:38.528Z,1684431758.528 [Default:CheckIn:C.Wait] Stopped
2023-05-18T17:42:38.528Z,1684431758.528 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:42:38.528Z,1684431758.528 [Default:CheckIn:D] Running Loop=1
2023-05-18T17:42:38.931Z,1684431758.931 [Default:CheckIn:D] Stopped
2023-05-18T17:42:38.932Z,1684431758.932 [Default:CheckIn:E] Running Loop=1
2023-05-18T17:42:39.347Z,1684431759.347 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.979600 min 
2023-05-18T17:42:39.347Z,1684431759.347 [Default:CheckIn:E] Stopped
2023-05-18T17:42:39.347Z,1684431759.347 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T17:42:39.347Z,1684431759.347 [Default:CheckIn] Stopped
2023-05-18T17:42:39.347Z,1684431759.347 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T17:42:39.348Z,1684431759.348 [Default:CheckIn](INFO): Running loop #5
2023-05-18T17:42:39.348Z,1684431759.348 [Default:CheckIn] Running Loop=5
2023-05-18T17:42:39.348Z,1684431759.348 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:42:39.352Z,1684431759.352 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:42:41.353Z,1684431761.353 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174240.00,A,3648.16484,N,12147.28547,W,0.097,6.31,180523,,,A*74
2023-05-18T17:42:41.355Z,1684431761.355 [NAL9602](INFO): GPS fix at 20230518T174240: (36.802747, -121.788091)
2023-05-18T17:42:41.373Z,1684431761.373 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:42:41.373Z,1684431761.373 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:42:49.443Z,1684431769.443 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230518T171335/Courier0016.lzma
2023-05-18T17:42:50.446Z,1684431770.446 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0016.lzma.bak
2023-05-18T17:42:50.446Z,1684431770.446 [DataOverHttps](INFO): SBD MOMSN=18327327
2023-05-18T17:43:06.424Z,1684431786.424 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20230518T171335/Express0017.lzma
2023-05-18T17:43:07.426Z,1684431787.426 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0017.lzma.bak
2023-05-18T17:43:07.426Z,1684431787.426 [DataOverHttps](INFO): SBD MOMSN=18327330
2023-05-18T17:43:08.454Z,1684431788.454 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:43:08.454Z,1684431788.454 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:43:08.454Z,1684431788.454 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:43:12.050Z,1684431792.050 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-18T17:43:12.124Z,1684431792.124 [NAL9602](ERROR): received: 
+CSQ:0

OK313, 2, 0, 0, 0

OK
2023-05-18T17:43:49.713Z,1684431829.713 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T17:43:49.713Z,1684431829.713 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T17:44:21.595Z,1684431861.595 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T17:44:21.596Z,1684431861.596 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T17:44:27.258Z,1684431867.258 [DVL_micro](ERROR): only read 0 of 4 data items
2023-05-18T17:44:27.258Z,1684431867.258 [DVL_micro](ERROR): Failed to parse:
:RD,,+0002.93,+0000.27,+0002.98
2023-05-18T17:44:51.030Z,1684431891.030 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 150 cubic_centimeter
2023-05-18T17:44:53.210Z,1684431893.210 [Reporter](INFO): platform_buoyancy_position 201.959930 cc
2023-05-18T17:44:53.974Z,1684431893.974 [Reporter](INFO): platform_buoyancy_position 199.811127 cc
2023-05-18T17:44:54.387Z,1684431894.387 [Reporter](INFO): platform_buoyancy_position 195.379242 cc
2023-05-18T17:44:54.786Z,1684431894.786 [Reporter](INFO): platform_buoyancy_position 190.813019 cc
2023-05-18T17:44:55.223Z,1684431895.223 [Reporter](INFO): platform_buoyancy_position 184.500916 cc
2023-05-18T17:44:55.598Z,1684431895.598 [Reporter](INFO): platform_buoyancy_position 180.203339 cc
2023-05-18T17:44:55.991Z,1684431895.991 [Reporter](INFO): platform_buoyancy_position 175.905731 cc
2023-05-18T17:44:56.408Z,1684431896.408 [Reporter](INFO): platform_buoyancy_position 170.533722 cc
2023-05-18T17:44:56.786Z,1684431896.786 [Reporter](INFO): platform_buoyancy_position 165.296021 cc
2023-05-18T17:44:57.270Z,1684431897.270 [Reporter](INFO): platform_buoyancy_position 158.849640 cc
2023-05-18T17:46:40.976Z,1684432000.976 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 100 cubic_centimeter
2023-05-18T17:46:42.714Z,1684432002.714 [Reporter](INFO): platform_buoyancy_position 152.403229 cc
2023-05-18T17:46:43.102Z,1684432003.102 [Reporter](INFO): platform_buoyancy_position 152.268921 cc
2023-05-18T17:46:43.481Z,1684432003.481 [Reporter](INFO): platform_buoyancy_position 152.000336 cc
2023-05-18T17:46:43.894Z,1684432003.894 [Reporter](INFO): platform_buoyancy_position 145.822540 cc
2023-05-18T17:46:44.344Z,1684432004.344 [Reporter](INFO): platform_buoyancy_position 141.659210 cc
2023-05-18T17:46:44.758Z,1684432004.758 [Reporter](INFO): platform_buoyancy_position 136.152924 cc
2023-05-18T17:46:45.149Z,1684432005.149 [Reporter](INFO): platform_buoyancy_position 130.780914 cc
2023-05-18T17:46:45.565Z,1684432005.565 [Reporter](INFO): platform_buoyancy_position 124.737434 cc
2023-05-18T17:46:45.958Z,1684432005.958 [Reporter](INFO): platform_buoyancy_position 120.305511 cc
2023-05-18T17:46:46.357Z,1684432006.357 [Reporter](INFO): platform_buoyancy_position 115.873627 cc
2023-05-18T17:46:46.798Z,1684432006.798 [Reporter](INFO): platform_buoyancy_position 109.830109 cc
2023-05-18T17:47:32.321Z,1684432052.321 [DVL_micro](ERROR): only read 2 of 4 data items
2023-05-18T17:47:32.321Z,1684432052.321 [DVL_micro](ERROR): Failed to parse:
:BI,00000,+0000,I
2023-05-18T17:47:43.225Z,1684432063.225 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-18T17:48:09.107Z,1684432089.107 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T17:48:09.107Z,1684432089.107 [Default:CheckIn:C.Wait] Stopped
2023-05-18T17:48:09.107Z,1684432089.107 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:48:09.107Z,1684432089.107 [Default:CheckIn:D] Running Loop=1
2023-05-18T17:48:09.497Z,1684432089.497 [Default:CheckIn:D] Stopped
2023-05-18T17:48:09.497Z,1684432089.497 [Default:CheckIn:E] Running Loop=1
2023-05-18T17:48:09.910Z,1684432089.910 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 30.489022 min 
2023-05-18T17:48:09.910Z,1684432089.910 [Default:CheckIn:E] Stopped
2023-05-18T17:48:09.910Z,1684432089.910 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T17:48:09.910Z,1684432089.910 [Default:CheckIn] Stopped
2023-05-18T17:48:09.910Z,1684432089.910 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T17:48:09.910Z,1684432089.910 [Default:CheckIn](INFO): Running loop #6
2023-05-18T17:48:09.910Z,1684432089.910 [Default:CheckIn] Running Loop=6
2023-05-18T17:48:09.911Z,1684432089.911 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:48:09.911Z,1684432089.911 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:48:11.912Z,1684432091.912 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174811.00,A,3648.16263,N,12147.28074,W,0.292,6.31,180523,,,A*77
2023-05-18T17:48:11.924Z,1684432091.924 [NAL9602](INFO): GPS fix at 20230518T174811: (36.802711, -121.788012)
2023-05-18T17:48:11.935Z,1684432091.935 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:48:11.935Z,1684432091.935 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:48:20.031Z,1684432100.031 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0019.lzma
2023-05-18T17:48:21.037Z,1684432101.037 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0019.lzma.bak
2023-05-18T17:48:21.037Z,1684432101.037 [DataOverHttps](INFO): SBD MOMSN=18327342
2023-05-18T17:48:37.028Z,1684432117.028 [DataOverHttps](INFO): Sending 284 bytes from file Logs/20230518T171335/Express0020.lzma
2023-05-18T17:48:38.036Z,1684432118.036 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0020.lzma.bak
2023-05-18T17:48:38.036Z,1684432118.036 [DataOverHttps](INFO): SBD MOMSN=18327345
2023-05-18T17:48:39.391Z,1684432119.391 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:48:39.391Z,1684432119.391 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:48:39.391Z,1684432119.391 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:48:44.636Z,1684432124.636 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T17:48:52.993Z,1684432132.993 [CommandExec](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 72 cubic_centimeter
2023-05-18T17:48:54.802Z,1684432134.802 [Reporter](INFO): platform_buoyancy_position 101.637817 cc
2023-05-18T17:48:55.190Z,1684432135.190 [Reporter](INFO): platform_buoyancy_position 102.846527 cc
2023-05-18T17:48:55.606Z,1684432135.606 [Reporter](INFO): platform_buoyancy_position 100.697723 cc
2023-05-18T17:48:56.038Z,1684432136.038 [Reporter](INFO): platform_buoyancy_position 94.251312 cc
2023-05-18T17:48:56.422Z,1684432136.422 [Reporter](INFO): platform_buoyancy_position 89.953735 cc
2023-05-18T17:48:56.813Z,1684432136.813 [Reporter](INFO): platform_buoyancy_position 85.656128 cc
2023-05-18T17:48:57.238Z,1684432137.238 [Reporter](INFO): platform_buoyancy_position 81.224213 cc
2023-05-18T17:49:44.792Z,1684432184.792 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T17:49:46.801Z,1684432186.801 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.243134
2023-05-18T17:50:19.948Z,1684432219.948 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T17:50:46.604Z,1684432246.604 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003162
2023-05-18T17:51:26.822Z,1684432286.822 [CommandExec](IMPORTANT): got command maintain clear
2023-05-18T17:51:27.071Z,1684432287.071 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DVL_micro,NAL9602,Power24vConverter,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,
2023-05-18T17:51:29.610Z,1684432289.610 [Reporter](INFO): platform_buoyancy_position 74.912109 cc
2023-05-18T17:51:30.766Z,1684432290.766 [Reporter](INFO): platform_buoyancy_position 77.329529 cc
2023-05-18T17:51:31.191Z,1684432291.191 [Reporter](INFO): platform_buoyancy_position 83.507324 cc
2023-05-18T17:51:31.582Z,1684432291.582 [Reporter](INFO): platform_buoyancy_position 89.416534 cc
2023-05-18T17:51:31.982Z,1684432291.982 [Reporter](INFO): platform_buoyancy_position 94.251312 cc
2023-05-18T17:51:32.382Z,1684432292.382 [Reporter](INFO): platform_buoyancy_position 100.697723 cc
2023-05-18T17:51:32.791Z,1684432292.791 [Reporter](INFO): platform_buoyancy_position 104.995331 cc
2023-05-18T17:51:33.206Z,1684432293.206 [Reporter](INFO): platform_buoyancy_position 111.441711 cc
2023-05-18T17:51:33.597Z,1684432293.597 [CommandExec](IMPORTANT): got command report clear
2023-05-18T17:52:13.929Z,1684432333.929 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:52:13.930Z,1684432333.930 [DVL_micro](ERROR): Failed to parse:
:BI,+00228,-0148,+00000,I
2023-05-18T17:53:37.982Z,1684432417.982 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T17:53:37.982Z,1684432417.982 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+190,1489.0,000
2023-05-18T17:53:40.029Z,1684432420.029 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T17:53:40.029Z,1684432420.029 [Default:CheckIn:C.Wait] Stopped
2023-05-18T17:53:40.029Z,1684432420.029 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:53:40.029Z,1684432420.029 [Default:CheckIn:D] Running Loop=1
2023-05-18T17:53:40.430Z,1684432420.430 [Default:CheckIn:D] Stopped
2023-05-18T17:53:40.430Z,1684432420.430 [Default:CheckIn:E] Running Loop=1
2023-05-18T17:53:40.833Z,1684432420.833 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 36.004582 min 
2023-05-18T17:53:40.833Z,1684432420.833 [Default:CheckIn:E] Stopped
2023-05-18T17:53:40.833Z,1684432420.833 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T17:53:40.833Z,1684432420.833 [Default:CheckIn] Stopped
2023-05-18T17:53:40.833Z,1684432420.833 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T17:53:40.834Z,1684432420.834 [Default:CheckIn](INFO): Running loop #7
2023-05-18T17:53:40.834Z,1684432420.834 [Default:CheckIn] Running Loop=7
2023-05-18T17:53:40.834Z,1684432420.834 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:53:40.834Z,1684432420.834 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:53:42.847Z,1684432422.847 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175342.00,A,3648.16993,N,12147.28419,W,0.097,0.00,180523,,,D*76
2023-05-18T17:53:42.854Z,1684432422.854 [NAL9602](INFO): GPS fix at 20230518T175342: (36.802832, -121.788070)
2023-05-18T17:53:42.897Z,1684432422.897 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:53:42.897Z,1684432422.897 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:53:53.063Z,1684432433.063 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0022.lzma
2023-05-18T17:53:54.068Z,1684432434.068 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0022.lzma.bak
2023-05-18T17:53:54.068Z,1684432434.068 [DataOverHttps](INFO): SBD MOMSN=18327351
2023-05-18T17:54:13.365Z,1684432453.365 [DataOverHttps](INFO): Sending 226 bytes from file Logs/20230518T171335/Express0023.lzma
2023-05-18T17:54:13.609Z,1684432453.609 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-18T17:54:13.689Z,1684432453.689 [NAL9602](ERROR): received: 
+CSQ:0

OK313, 2, 0, 0, 0

OK
2023-05-18T17:54:14.366Z,1684432454.366 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0023.lzma.bak
2023-05-18T17:54:14.366Z,1684432454.366 [DataOverHttps](INFO): SBD MOMSN=18327354
2023-05-18T17:54:15.638Z,1684432455.638 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:54:15.638Z,1684432455.638 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:54:15.639Z,1684432455.639 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:58:45.557Z,1684432725.557 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T17:58:45.557Z,1684432725.557 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000+19.2,0000.0,1489.0,000
2023-05-18T17:58:45.558Z,1684432725.558 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-18T17:59:16.267Z,1684432756.267 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T17:59:16.279Z,1684432756.279 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T17:59:16.279Z,1684432756.279 [Default:CheckIn:C.Wait] Stopped
2023-05-18T17:59:16.279Z,1684432756.279 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T17:59:16.279Z,1684432756.279 [Default:CheckIn:D] Running Loop=1
2023-05-18T17:59:16.667Z,1684432756.667 [Default:CheckIn:D] Stopped
2023-05-18T17:59:16.667Z,1684432756.667 [Default:CheckIn:E] Running Loop=1
2023-05-18T17:59:17.082Z,1684432757.082 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.608533 min 
2023-05-18T17:59:17.082Z,1684432757.082 [Default:CheckIn:E] Stopped
2023-05-18T17:59:17.083Z,1684432757.083 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T17:59:17.083Z,1684432757.083 [Default:CheckIn] Stopped
2023-05-18T17:59:17.083Z,1684432757.083 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T17:59:17.083Z,1684432757.083 [Default:CheckIn](INFO): Running loop #8
2023-05-18T17:59:17.083Z,1684432757.083 [Default:CheckIn] Running Loop=8
2023-05-18T17:59:17.083Z,1684432757.083 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T17:59:17.083Z,1684432757.083 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T17:59:19.087Z,1684432759.087 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175918.00,A,3648.16565,N,12147.28187,W,0.194,7.89,180523,,,D*70
2023-05-18T17:59:19.089Z,1684432759.089 [NAL9602](INFO): GPS fix at 20230518T175918: (36.802761, -121.788031)
2023-05-18T17:59:19.128Z,1684432759.128 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T17:59:19.128Z,1684432759.128 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T17:59:26.847Z,1684432766.847 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0025.lzma
2023-05-18T17:59:27.850Z,1684432767.850 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0025.lzma.bak
2023-05-18T17:59:27.850Z,1684432767.850 [DataOverHttps](INFO): SBD MOMSN=18327362
2023-05-18T17:59:46.292Z,1684432786.292 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20230518T171335/Express0026.lzma
2023-05-18T17:59:47.298Z,1684432787.298 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0026.lzma.bak
2023-05-18T17:59:47.298Z,1684432787.298 [DataOverHttps](INFO): SBD MOMSN=18327365
2023-05-18T17:59:48.652Z,1684432788.652 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T17:59:48.652Z,1684432788.652 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T17:59:48.652Z,1684432788.652 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T17:59:49.826Z,1684432789.826 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2023-05-18T17:59:49.904Z,1684432789.904 [NAL9602](ERROR): received: 
+CSQ:0

OK313, 2, 0, 0, 0

OK
2023-05-18T17:59:54.274Z,1684432794.274 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T17:59:54.274Z,1684432794.274 [DVL_micro](ERROR): Failed to parse:
:BI,-00086,+00054,+0000,I
2023-05-18T18:00:57.316Z,1684432857.316 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T18:00:57.316Z,1684432857.316 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T18:01:23.573Z,1684432883.573 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T18:01:23.574Z,1684432883.574 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T18:03:53.459Z,1684433033.459 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T18:03:53.460Z,1684433033.460 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+0.0,1489.0,000
2023-05-18T18:04:31.027Z,1684433071.027 [NAL9602](INFO): SBD MO Status=2, MOMSN=18313, MT Status=2, MTMSN=0
2023-05-18T18:04:31.027Z,1684433071.027 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T18:04:31.456Z,1684433071.456 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-18T18:04:49.231Z,1684433089.231 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:04:49.231Z,1684433089.231 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:04:49.231Z,1684433089.231 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:04:49.231Z,1684433089.231 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:04:49.619Z,1684433089.619 [Default:CheckIn:D] Stopped
2023-05-18T18:04:49.619Z,1684433089.619 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:04:50.023Z,1684433090.023 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 47.157731 min 
2023-05-18T18:04:50.024Z,1684433090.024 [Default:CheckIn:E] Stopped
2023-05-18T18:04:50.024Z,1684433090.024 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:04:50.024Z,1684433090.024 [Default:CheckIn] Stopped
2023-05-18T18:04:50.024Z,1684433090.024 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:04:50.024Z,1684433090.024 [Default:CheckIn](INFO): Running loop #9
2023-05-18T18:04:50.024Z,1684433090.024 [Default:CheckIn] Running Loop=9
2023-05-18T18:04:50.024Z,1684433090.024 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:04:50.025Z,1684433090.025 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:04:52.038Z,1684433092.038 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180451.00,A,3648.17550,N,12147.28212,W,0.058,211.10,180523,,,D*76
2023-05-18T18:04:52.040Z,1684433092.040 [NAL9602](INFO): GPS fix at 20230518T180451: (36.802925, -121.788035)
2023-05-18T18:04:52.051Z,1684433092.051 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:04:52.051Z,1684433092.051 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:04:59.695Z,1684433099.695 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0028.lzma
2023-05-18T18:05:00.698Z,1684433100.698 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0028.lzma.bak
2023-05-18T18:05:00.698Z,1684433100.698 [DataOverHttps](INFO): SBD MOMSN=18327371
2023-05-18T18:05:16.628Z,1684433116.628 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20230518T171335/Express0029.lzma
2023-05-18T18:05:17.630Z,1684433117.630 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0029.lzma.bak
2023-05-18T18:05:17.630Z,1684433117.630 [DataOverHttps](INFO): SBD MOMSN=18327374
2023-05-18T18:05:18.707Z,1684433118.707 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:05:18.707Z,1684433118.707 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:05:18.707Z,1684433118.707 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:05:24.349Z,1684433124.349 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:05:37.691Z,1684433137.691 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T18:05:37.691Z,1684433137.691 [DVL_micro](ERROR): Failed to parse:
:BI,-01226,+04328,+0010,I
2023-05-18T18:06:33.457Z,1684433193.457 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T18:06:33.458Z,1684433193.458 [DVL_micro](ERROR): Failed to parse:
:BI,-01231,+03199,+0040,I
2023-05-18T18:09:23.611Z,1684433363.611 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T18:09:23.612Z,1684433363.612 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,+0.0,1489.0,000
2023-05-18T18:10:19.433Z,1684433419.433 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:10:19.433Z,1684433419.433 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:10:19.433Z,1684433419.433 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:10:19.434Z,1684433419.434 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:10:19.815Z,1684433419.815 [Default:CheckIn:D] Stopped
2023-05-18T18:10:19.815Z,1684433419.815 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:10:20.225Z,1684433420.225 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.660990 min 
2023-05-18T18:10:20.225Z,1684433420.225 [Default:CheckIn:E] Stopped
2023-05-18T18:10:20.225Z,1684433420.225 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:10:20.225Z,1684433420.225 [Default:CheckIn] Stopped
2023-05-18T18:10:20.226Z,1684433420.226 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:10:20.226Z,1684433420.226 [Default:CheckIn](INFO): Running loop #10
2023-05-18T18:10:20.226Z,1684433420.226 [Default:CheckIn] Running Loop=10
2023-05-18T18:10:20.226Z,1684433420.226 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:10:20.226Z,1684433420.226 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:10:22.232Z,1684433422.232 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181021.00,A,3648.16797,N,12147.28303,W,0.486,185.19,180523,,,D*7D
2023-05-18T18:10:22.234Z,1684433422.234 [NAL9602](INFO): GPS fix at 20230518T181021: (36.802799, -121.788050)
2023-05-18T18:10:22.245Z,1684433422.245 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:10:22.245Z,1684433422.245 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:10:29.923Z,1684433429.923 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0031.lzma
2023-05-18T18:10:30.926Z,1684433430.926 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0031.lzma.bak
2023-05-18T18:10:30.926Z,1684433430.926 [DataOverHttps](INFO): SBD MOMSN=18327379
2023-05-18T18:10:46.948Z,1684433446.948 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230518T171335/Express0032.lzma
2023-05-18T18:10:47.950Z,1684433447.950 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0032.lzma.bak
2023-05-18T18:10:47.950Z,1684433447.950 [DataOverHttps](INFO): SBD MOMSN=18327382
2023-05-18T18:10:49.319Z,1684433449.319 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:10:49.319Z,1684433449.319 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:10:49.320Z,1684433449.320 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:12:05.711Z,1684433525.711 [NAL9602](INFO): SBD MO Status=0, MOMSN=18313, MT Status=0, MTMSN=0
2023-05-18T18:12:05.711Z,1684433525.711 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:12:16.241Z,1684433536.241 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T18:12:16.241Z,1684433536.241 [DVL_micro](ERROR): Failed to parse:
:BI,+00244,-02315,+0000,I
2023-05-18T18:12:36.437Z,1684433556.437 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:15:49.981Z,1684433749.981 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:15:49.981Z,1684433749.981 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:15:49.981Z,1684433749.981 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:15:49.981Z,1684433749.981 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:15:50.379Z,1684433750.379 [Default:CheckIn:D] Stopped
2023-05-18T18:15:50.379Z,1684433750.379 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:15:50.784Z,1684433750.784 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.170394 min 
2023-05-18T18:15:50.784Z,1684433750.784 [Default:CheckIn:E] Stopped
2023-05-18T18:15:50.784Z,1684433750.784 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:15:50.784Z,1684433750.784 [Default:CheckIn] Stopped
2023-05-18T18:15:50.784Z,1684433750.784 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:15:50.784Z,1684433750.784 [Default:CheckIn](INFO): Running loop #11
2023-05-18T18:15:50.784Z,1684433750.784 [Default:CheckIn] Running Loop=11
2023-05-18T18:15:50.785Z,1684433750.785 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:15:50.785Z,1684433750.785 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:15:52.795Z,1684433752.795 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181552.00,A,3648.14689,N,12147.22560,W,0.292,23.54,180523,,,D*4E
2023-05-18T18:15:52.798Z,1684433752.798 [NAL9602](INFO): GPS fix at 20230518T181552: (36.802448, -121.787093)
2023-05-18T18:15:52.837Z,1684433752.837 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:15:52.837Z,1684433752.837 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:16:03.444Z,1684433763.444 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230518T171335/Courier0034.lzma
2023-05-18T18:16:04.446Z,1684433764.446 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0034.lzma.bak
2023-05-18T18:16:04.446Z,1684433764.446 [DataOverHttps](INFO): SBD MOMSN=18327412
2023-05-18T18:16:20.672Z,1684433780.672 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230518T171335/Express0035.lzma
2023-05-18T18:16:21.674Z,1684433781.674 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0035.lzma.bak
2023-05-18T18:16:21.674Z,1684433781.674 [DataOverHttps](INFO): SBD MOMSN=18327415
2023-05-18T18:16:22.783Z,1684433782.783 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:16:22.783Z,1684433782.783 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:16:22.783Z,1684433782.783 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:17:43.175Z,1684433863.175 [NAL9602](INFO): SBD MO Status=0, MOMSN=18314, MT Status=0, MTMSN=0
2023-05-18T18:17:43.175Z,1684433863.175 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:18:05.006Z,1684433885.006 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T18:18:05.006Z,1684433885.006 [DVL_micro](ERROR): Failed to parse:
:BI,+00029,+0659,+00000,I
2023-05-18T18:18:13.881Z,1684433893.881 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:19:46.817Z,1684433986.817 [DVL_micro](ERROR): Failed to parse:
:BD,+0000+00000000.0000.00,990.00
2023-05-18T18:21:23.439Z,1684434083.439 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:21:23.440Z,1684434083.440 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:21:23.440Z,1684434083.440 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:21:23.440Z,1684434083.440 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:21:23.827Z,1684434083.827 [Default:CheckIn:D] Stopped
2023-05-18T18:21:23.827Z,1684434083.827 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:21:24.228Z,1684434084.228 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.727865 min 
2023-05-18T18:21:24.228Z,1684434084.228 [Default:CheckIn:E] Stopped
2023-05-18T18:21:24.229Z,1684434084.229 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:21:24.229Z,1684434084.229 [Default:CheckIn] Stopped
2023-05-18T18:21:24.229Z,1684434084.229 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:21:24.229Z,1684434084.229 [Default:CheckIn](INFO): Running loop #12
2023-05-18T18:21:24.229Z,1684434084.229 [Default:CheckIn] Running Loop=12
2023-05-18T18:21:24.229Z,1684434084.229 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:21:24.229Z,1684434084.229 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:21:26.238Z,1684434086.238 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182125.00,A,3648.14978,N,12147.22110,W,0.156,111.21,180523,,,D*72
2023-05-18T18:21:26.241Z,1684434086.241 [NAL9602](INFO): GPS fix at 20230518T182125: (36.802496, -121.787018)
2023-05-18T18:21:26.276Z,1684434086.276 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:21:26.276Z,1684434086.276 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:21:34.235Z,1684434094.235 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0037.lzma
2023-05-18T18:21:35.238Z,1684434095.238 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0037.lzma.bak
2023-05-18T18:21:35.238Z,1684434095.238 [DataOverHttps](INFO): SBD MOMSN=18327421
2023-05-18T18:21:40.003Z,1684434100.003 [NAL9602](INFO): SBD MO Status=0, MOMSN=18315, MT Status=0, MTMSN=0
2023-05-18T18:21:40.004Z,1684434100.004 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:21:54.608Z,1684434114.608 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230518T171335/Express0038.lzma
2023-05-18T18:21:55.610Z,1684434115.610 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0038.lzma.bak
2023-05-18T18:21:55.610Z,1684434115.610 [DataOverHttps](INFO): SBD MOMSN=18327424
2023-05-18T18:21:56.997Z,1684434116.997 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:21:56.997Z,1684434116.997 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:21:56.997Z,1684434116.997 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:22:10.742Z,1684434130.742 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:22:26.893Z,1684434146.893 [DVL_micro](ERROR): Failed to parse:
55,+01434,+00968,+00000,I
2023-05-18T18:26:57.640Z,1684434417.640 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:26:57.640Z,1684434417.640 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:26:57.640Z,1684434417.640 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:26:57.640Z,1684434417.640 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:26:58.032Z,1684434418.032 [Default:CheckIn:D] Stopped
2023-05-18T18:26:58.032Z,1684434418.032 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.297933 min 
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn:E] Stopped
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn] Stopped
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn](INFO): Running loop #13
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn] Running Loop=13
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:26:58.433Z,1684434418.433 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:27:00.452Z,1684434420.452 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182659.00,A,3648.14900,N,12147.22003,W,0.039,111.21,180523,,,D*7A
2023-05-18T18:27:00.455Z,1684434420.455 [NAL9602](INFO): GPS fix at 20230518T182659: (36.802483, -121.787001)
2023-05-18T18:27:00.465Z,1684434420.465 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:27:00.465Z,1684434420.465 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:27:07.703Z,1684434427.703 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0040.lzma
2023-05-18T18:27:08.706Z,1684434428.706 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0040.lzma.bak
2023-05-18T18:27:08.706Z,1684434428.706 [DataOverHttps](INFO): SBD MOMSN=18327437
2023-05-18T18:27:24.700Z,1684434444.700 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20230518T171335/Express0041.lzma
2023-05-18T18:27:25.702Z,1684434445.702 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0041.lzma.bak
2023-05-18T18:27:25.702Z,1684434445.702 [DataOverHttps](INFO): SBD MOMSN=18327440
2023-05-18T18:27:26.762Z,1684434446.762 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:27:26.762Z,1684434446.762 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:27:26.762Z,1684434446.762 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:27:27.148Z,1684434447.148 [NAL9602](INFO): SBD MO Status=0, MOMSN=18316, MT Status=0, MTMSN=0
2023-05-18T18:27:27.149Z,1684434447.149 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:27:49.377Z,1684434469.377 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T18:27:49.377Z,1684434469.377 [DVL_micro](ERROR): Failed to parse:
:TS,000,+20.6,0000.0,1489.0,000
2023-05-18T18:27:54.627Z,1684434474.627 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T18:27:54.627Z,1684434474.627 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.6,0000.0,148

2023-05-18T18:27:57.852Z,1684434477.852 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:28:56.026Z,1684434536.026 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-18T18:29:01.274Z,1684434541.274 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-18T18:29:01.281Z,1684434541.281 [BPC1](INFO): Calculating totals. Valid battery stick count: 48. Valid reserve battery stick count: 5.
2023-05-18T18:29:01.305Z,1684434541.305 [BPC1](INFO): Received data from all battery sticks.
2023-05-18T18:32:27.421Z,1684434747.421 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:32:27.421Z,1684434747.421 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:32:27.421Z,1684434747.421 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:32:27.421Z,1684434747.421 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:32:27.804Z,1684434747.804 [Default:CheckIn:D] Stopped
2023-05-18T18:32:27.804Z,1684434747.804 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:32:28.229Z,1684434748.229 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 74.794141 min 
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn:E] Stopped
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn] Stopped
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn](INFO): Running loop #14
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn] Running Loop=14
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:32:28.230Z,1684434748.230 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:32:30.213Z,1684434750.213 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183229.00,A,3648.20800,N,12147.14106,W,3.771,16.61,180523,,,D*45
2023-05-18T18:32:30.215Z,1684434750.215 [NAL9602](INFO): GPS fix at 20230518T183229: (36.803467, -121.785684)
2023-05-18T18:32:30.234Z,1684434750.234 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:32:30.234Z,1684434750.234 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:32:38.031Z,1684434758.031 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20230518T171335/Courier0043.lzma
2023-05-18T18:32:39.034Z,1684434759.034 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0043.lzma.bak
2023-05-18T18:32:39.034Z,1684434759.034 [DataOverHttps](INFO): SBD MOMSN=18327459
2023-05-18T18:32:48.860Z,1684434768.860 [NAL9602](INFO): SBD MO Status=0, MOMSN=18317, MT Status=0, MTMSN=0
2023-05-18T18:32:48.860Z,1684434768.860 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:32:54.848Z,1684434774.848 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20230518T171335/Express0044.lzma
2023-05-18T18:32:55.850Z,1684434775.850 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0044.lzma.bak
2023-05-18T18:32:55.850Z,1684434775.850 [DataOverHttps](INFO): SBD MOMSN=18327462
2023-05-18T18:32:56.975Z,1684434776.975 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:32:56.975Z,1684434776.975 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:32:56.975Z,1684434776.975 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:33:19.573Z,1684434799.573 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:33:24.821Z,1684434804.821 [DVL_micro](ERROR): Failed to parse:
:WI,+02402,+01392,+00309,+00000,A
2023-05-18T18:36:12.546Z,1684434972.546 [DVL_micro](ERROR): Failed to parse:
:WI,+0253,+00241,+00000+02538,+01656,+00241,+00000,00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2023-05-18T18:37:57.697Z,1684435077.697 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:37:57.697Z,1684435077.697 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:37:57.697Z,1684435077.697 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:37:57.698Z,1684435077.698 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:37:58.101Z,1684435078.101 [Default:CheckIn:D] Stopped
2023-05-18T18:37:58.101Z,1684435078.101 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:37:58.503Z,1684435078.503 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.299097 min 
2023-05-18T18:37:58.503Z,1684435078.503 [Default:CheckIn:E] Stopped
2023-05-18T18:37:58.503Z,1684435078.503 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:37:58.503Z,1684435078.503 [Default:CheckIn] Stopped
2023-05-18T18:37:58.503Z,1684435078.503 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:37:58.504Z,1684435078.504 [Default:CheckIn](INFO): Running loop #15
2023-05-18T18:37:58.504Z,1684435078.504 [Default:CheckIn] Running Loop=15
2023-05-18T18:37:58.504Z,1684435078.504 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:37:58.504Z,1684435078.504 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:38:00.507Z,1684435080.507 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183759.00,A,3648.45515,N,12147.29877,W,7.873,235.79,180523,,,D*7F
2023-05-18T18:38:00.510Z,1684435080.510 [NAL9602](INFO): GPS fix at 20230518T183759: (36.807586, -121.788313)
2023-05-18T18:38:00.529Z,1684435080.529 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:38:00.529Z,1684435080.529 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:38:10.399Z,1684435090.399 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0046.lzma
2023-05-18T18:38:11.402Z,1684435091.402 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0046.lzma.bak
2023-05-18T18:38:11.402Z,1684435091.402 [DataOverHttps](INFO): SBD MOMSN=18327489
2023-05-18T18:38:22.355Z,1684435102.355 [NAL9602](INFO): SBD MO Status=2, MOMSN=18318, MT Status=2, MTMSN=0
2023-05-18T18:38:22.355Z,1684435102.355 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T18:38:27.308Z,1684435107.308 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20230518T171335/Express0047.lzma
2023-05-18T18:38:28.310Z,1684435108.310 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0047.lzma.bak
2023-05-18T18:38:28.310Z,1684435108.310 [DataOverHttps](INFO): SBD MOMSN=18327493
2023-05-18T18:38:29.647Z,1684435109.647 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:38:29.647Z,1684435109.647 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:38:29.647Z,1684435109.647 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:38:34.885Z,1684435114.885 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T18:38:34.886Z,1684435114.886 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.999
2023-05-18T18:39:20.543Z,1684435160.543 [NAL9602](INFO): SBD MO Status=2, MOMSN=18318, MT Status=2, MTMSN=0
2023-05-18T18:39:20.543Z,1684435160.543 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T18:39:33.471Z,1684435173.471 [DVL_micro](ERROR): only read 0 of 4 data items
2023-05-18T18:39:33.472Z,1684435173.472 [DVL_micro](ERROR): Failed to parse:
:RD9,+9999.99,+9999.99,+9999.99
2023-05-18T18:39:59.771Z,1684435199.771 [NAL9602](INFO): SBD MO Status=0, MOMSN=18318, MT Status=0, MTMSN=0
2023-05-18T18:39:59.771Z,1684435199.771 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:40:30.481Z,1684435230.481 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:43:30.271Z,1684435410.271 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:43:30.271Z,1684435410.271 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:43:30.271Z,1684435410.271 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:43:30.271Z,1684435410.271 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:43:30.675Z,1684435410.675 [Default:CheckIn:D] Stopped
2023-05-18T18:43:30.676Z,1684435410.676 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:43:31.087Z,1684435411.087 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 85.842000 min 
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn:E] Stopped
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn] Stopped
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn](INFO): Running loop #16
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn] Running Loop=16
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:43:31.088Z,1684435411.088 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:43:33.088Z,1684435413.088 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184332.00,A,3648.61121,N,12148.37606,W,13.238,312.53,180523,,,D*40
2023-05-18T18:43:33.090Z,1684435413.090 [NAL9602](INFO): GPS fix at 20230518T184332: (36.810187, -121.806268)
2023-05-18T18:43:33.100Z,1684435413.100 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:43:33.101Z,1684435413.101 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:43:40.039Z,1684435420.039 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230518T171335/Courier0049.lzma
2023-05-18T18:43:41.042Z,1684435421.042 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0049.lzma.bak
2023-05-18T18:43:41.042Z,1684435421.042 [DataOverHttps](INFO): SBD MOMSN=18327509
2023-05-18T18:44:00.060Z,1684435440.060 [DataOverHttps](INFO): Sending 139 bytes from file Logs/20230518T171335/Express0050.lzma
2023-05-18T18:44:01.062Z,1684435441.062 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0050.lzma.bak
2023-05-18T18:44:01.062Z,1684435441.062 [DataOverHttps](INFO): SBD MOMSN=18327513
2023-05-18T18:44:01.423Z,1684435441.423 [NAL9602](INFO): SBD MO Status=0, MOMSN=18319, MT Status=0, MTMSN=0
2023-05-18T18:44:01.423Z,1684435441.423 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:44:02.252Z,1684435442.252 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:44:02.252Z,1684435442.252 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:44:02.252Z,1684435442.252 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:44:32.185Z,1684435472.185 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:49:02.901Z,1684435742.901 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:49:02.902Z,1684435742.902 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:49:02.902Z,1684435742.902 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:49:02.902Z,1684435742.902 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:49:03.321Z,1684435743.321 [Default:CheckIn:D] Stopped
2023-05-18T18:49:03.321Z,1684435743.321 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:49:03.699Z,1684435743.699 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 91.386100 min 
2023-05-18T18:49:03.699Z,1684435743.699 [Default:CheckIn:E] Stopped
2023-05-18T18:49:03.699Z,1684435743.699 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:49:03.699Z,1684435743.699 [Default:CheckIn] Stopped
2023-05-18T18:49:03.699Z,1684435743.699 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:49:03.699Z,1684435743.699 [Default:CheckIn](INFO): Running loop #17
2023-05-18T18:49:03.699Z,1684435743.699 [Default:CheckIn] Running Loop=17
2023-05-18T18:49:03.700Z,1684435743.700 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:49:03.700Z,1684435743.700 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:49:05.734Z,1684435745.734 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184905.00,A,3649.49765,N,12149.46210,W,10.575,313.58,180523,,,D*40
2023-05-18T18:49:05.737Z,1684435745.737 [NAL9602](INFO): GPS fix at 20230518T184905: (36.824961, -121.824368)
2023-05-18T18:49:05.775Z,1684435745.775 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:49:05.775Z,1684435745.775 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:49:13.691Z,1684435753.691 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0052.lzma
2023-05-18T18:49:14.694Z,1684435754.694 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0052.lzma.bak
2023-05-18T18:49:14.694Z,1684435754.694 [DataOverHttps](INFO): SBD MOMSN=18327530
2023-05-18T18:49:32.708Z,1684435772.708 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20230518T171335/Express0053.lzma
2023-05-18T18:49:33.710Z,1684435773.710 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0053.lzma.bak
2023-05-18T18:49:33.710Z,1684435773.710 [DataOverHttps](INFO): SBD MOMSN=18327533
2023-05-18T18:49:34.813Z,1684435774.813 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:49:34.813Z,1684435774.813 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:49:34.813Z,1684435774.813 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:49:44.511Z,1684435784.511 [NAL9602](INFO): SBD MO Status=0, MOMSN=18320, MT Status=0, MTMSN=0
2023-05-18T18:49:44.511Z,1684435784.511 [NAL9602](INFO): No messages in MT queue
2023-05-18T18:50:15.257Z,1684435815.257 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:53:38.728Z,1684436018.728 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T18:53:40.737Z,1684436020.737 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.251312
2023-05-18T18:54:13.876Z,1684436053.876 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T18:54:35.503Z,1684436075.503 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T18:54:35.503Z,1684436075.503 [Default:CheckIn:C.Wait] Stopped
2023-05-18T18:54:35.503Z,1684436075.503 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T18:54:35.504Z,1684436075.504 [Default:CheckIn:D] Running Loop=1
2023-05-18T18:54:35.909Z,1684436075.909 [Default:CheckIn:D] Stopped
2023-05-18T18:54:35.909Z,1684436075.909 [Default:CheckIn:E] Running Loop=1
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 96.929232 min 
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn:E] Stopped
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn] Stopped
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn](INFO): Running loop #18
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn] Running Loop=18
2023-05-18T18:54:36.317Z,1684436076.317 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T18:54:36.318Z,1684436076.318 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T18:54:38.323Z,1684436078.323 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185437.00,A,3650.04376,N,12150.54314,W,9.952,284.11,180523,,,D*77
2023-05-18T18:54:38.325Z,1684436078.325 [NAL9602](INFO): GPS fix at 20230518T185437: (36.834063, -121.842386)
2023-05-18T18:54:38.368Z,1684436078.368 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T18:54:38.368Z,1684436078.368 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T18:54:49.016Z,1684436089.016 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T18:55:05.529Z,1684436105.529 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003233
2023-05-18T18:55:13.027Z,1684436113.027 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20230518T171335/Courier0055.lzma
2023-05-18T18:55:14.035Z,1684436114.035 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0055.lzma.bak
2023-05-18T18:55:14.035Z,1684436114.035 [DataOverHttps](INFO): SBD MOMSN=18327570
2023-05-18T18:55:38.925Z,1684436138.925 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:56:21.055Z,1684436181.055 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T18:56:21.055Z,1684436181.055 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000020.8,0000.0,1489.0,000
2023-05-18T18:56:22.361Z,1684436182.361 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20230518T171335/Express0056.lzma
2023-05-18T18:56:41.432Z,1684436201.432 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2023-05-18T18:56:59.916Z,1684436219.916 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20230518T171335/Express0056.lzma
2023-05-18T18:57:09.956Z,1684436229.956 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.054367
2023-05-18T18:57:39.063Z,1684436259.063 [NAL9602](INFO): SBD MO Status=1, MOMSN=18321, MT Status=0, MTMSN=0
2023-05-18T18:57:39.128Z,1684436259.128 [NAL9602](INFO): Sent 146 bytes from file Logs/20230518T171335/Express0056.lzma
2023-05-18T18:57:39.129Z,1684436259.129 [NAL9602](INFO): Packets left to send: 0
2023-05-18T18:57:41.623Z,1684436261.623 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.013180
2023-05-18T18:57:42.769Z,1684436262.769 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T18:57:42.769Z,1684436262.769 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T18:57:42.769Z,1684436262.769 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T18:57:49.169Z,1684436269.169 [NAL9602](INFO): SBD MO Status=0, MOMSN=18322, MT Status=0, MTMSN=0
2023-05-18T18:58:12.732Z,1684436292.732 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T18:58:19.869Z,1684436299.869 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T18:58:41.849Z,1684436321.849 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239166
2023-05-18T18:59:23.013Z,1684436363.013 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T18:59:58.152Z,1684436398.152 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:01:08.436Z,1684436468.436 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:02:18.732Z,1684436538.732 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:02:43.288Z,1684436563.288 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:02:43.288Z,1684436563.288 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:02:43.288Z,1684436563.288 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:02:43.288Z,1684436563.288 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:02:43.698Z,1684436563.698 [Default:CheckIn:D] Stopped
2023-05-18T19:02:43.698Z,1684436563.698 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:02:44.095Z,1684436564.095 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 105.059041 min 
2023-05-18T19:02:44.095Z,1684436564.095 [Default:CheckIn:E] Stopped
2023-05-18T19:02:44.096Z,1684436564.096 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:02:44.096Z,1684436564.096 [Default:CheckIn] Stopped
2023-05-18T19:02:44.096Z,1684436564.096 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:02:44.097Z,1684436564.097 [Default:CheckIn](INFO): Running loop #19
2023-05-18T19:02:44.097Z,1684436564.097 [Default:CheckIn] Running Loop=19
2023-05-18T19:02:44.097Z,1684436564.097 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:02:44.097Z,1684436564.097 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:02:46.107Z,1684436566.107 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190245.00,A,3650.37149,N,12152.75966,W,10.749,280.74,180523,,,D*4B
2023-05-18T19:02:46.110Z,1684436566.110 [NAL9602](INFO): GPS fix at 20230518T190245: (36.839525, -121.879328)
2023-05-18T19:02:46.170Z,1684436566.170 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:02:46.170Z,1684436566.170 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:02:53.925Z,1684436573.925 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:03:13.620Z,1684436593.620 [DVL_micro](ERROR): Failed to parse:
:R99,+9999.99,+9999.99,+9999.99
2023-05-18T19:03:29.064Z,1684436609.064 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:03:31.397Z,1684436611.397 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2023-05-18T19:03:32.607Z,1684436612.607 [NAL9602](INFO): SBD MO Status=2, MOMSN=18323, MT Status=2, MTMSN=0
2023-05-18T19:03:32.607Z,1684436612.607 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:04:04.204Z,1684436644.204 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:04:13.051Z,1684436653.051 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=18323, MT Status=1, MTMSN=1271
2023-05-18T19:04:13.112Z,1684436653.112 [NAL9602](INFO): Sent 72 bytes from file Logs/20230518T171335/Courier0058.lzma
2023-05-18T19:04:13.112Z,1684436653.112 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:04:13.540Z,1684436653.540 [NAL9602](INFO): Received command: ibit 
2023-05-18T19:04:13.589Z,1684436653.589 [CommandExec](IMPORTANT): got command ibit 
2023-05-18T19:04:13.874Z,1684436653.874 [IBIT](IMPORTANT): Beginning Initiated BIT
2023-05-18T19:04:13.874Z,1684436653.874 [IBIT](IMPORTANT): Beginning control surface checks.
2023-05-18T19:04:13.877Z,1684436653.877 [CBIT](IMPORTANT): Beginning ground fault scan
2023-05-18T19:04:15.068Z,1684436655.068 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190414.00,A,3650.42808,N,12153.11082,W,14.501,276.04,180523,,,D*43
2023-05-18T19:04:15.070Z,1684436655.070 [NAL9602](INFO): GPS fix at 20230518T190414: (36.840468, -121.885180)
2023-05-18T19:04:26.751Z,1684436666.751 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.015774
CHAN A1 (24V): 0.006290
CHAN A2 (12V): -0.009763
CHAN A3 (5V): -0.000698
CHAN B0 (3.3V): -0.003498
CHAN B1 (3.15aV): -0.000932
CHAN B2 (3.15bV): -0.000243
CHAN B3 (GND): -0.009371
OPEN: 0.005818
Full Scale: +/- 1 mA
2023-05-18T19:04:31.964Z,1684436671.964 [NAL9602](INFO): SBD MO Status=2, MOMSN=18324, MT Status=2, MTMSN=0
2023-05-18T19:04:31.965Z,1684436671.965 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:04:33.179Z,1684436673.179 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190432.00,A,3650.43659,N,12153.20984,W,14.890,278.03,180523,,,D*4D
2023-05-18T19:04:33.182Z,1684436673.182 [NAL9602](INFO): GPS fix at 20230518T190432: (36.840610, -121.886831)
2023-05-18T19:04:39.348Z,1684436679.348 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:04:50.988Z,1684436690.988 [NAL9602](INFO): SBD MO Status=1, MOMSN=18324, MT Status=0, MTMSN=0
2023-05-18T19:04:51.044Z,1684436691.044 [NAL9602](INFO): Sent 145 bytes from file Logs/20230518T171335/Express0059.lzma
2023-05-18T19:04:51.044Z,1684436691.044 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:05:00.291Z,1684436700.291 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 3
Latitude: 36.840611 Longitude: -121.886833
2023-05-18T19:05:00.699Z,1684436700.699 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 16.532000
2023-05-18T19:05:00.699Z,1684436700.699 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2023-05-18T19:05:00.699Z,1684436700.699 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2023-05-18T19:05:01.104Z,1684436701.104 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2023-05-18T19:05:01.105Z,1684436701.105 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2023-05-18T19:05:01.105Z,1684436701.105 [IBIT](IMPORTANT): Pressure:9.916799 PSI
2023-05-18T19:05:01.105Z,1684436701.105 [IBIT](IMPORTANT): Humidity:19.686241 %
2023-05-18T19:05:01.520Z,1684436701.520 [IBIT](IMPORTANT): Vehicle Pitch:7.831644 degrees
2023-05-18T19:05:01.520Z,1684436701.520 [IBIT](IMPORTANT): Vehicle  Roll:-6.757924 degrees
2023-05-18T19:05:01.521Z,1684436701.521 [IBIT](IMPORTANT): Vehicle  Heading:281.032684 degrees
2023-05-18T19:05:01.906Z,1684436701.906 [IBIT](IMPORTANT): surfaceThreshold: 1.500000 m
2023-05-18T19:05:01.907Z,1684436701.907 [IBIT](IMPORTANT): buoyancyNeutral: 208.610001 cc
2023-05-18T19:05:01.907Z,1684436701.907 [IBIT](IMPORTANT): massDefault: -1.000000 cm
2023-05-18T19:05:01.907Z,1684436701.907 [IBIT](IMPORTANT): stopDepth: 265.000000 m
2023-05-18T19:05:01.907Z,1684436701.907 [IBIT](IMPORTANT): abortDepth: 300.000000 m
2023-05-18T19:05:01.907Z,1684436701.907 [IBIT](IMPORTANT): IBIT PASSED
2023-05-18T19:05:08.378Z,1684436708.378 [NAL9602](INFO): SBD MO Status=0, MOMSN=18325, MT Status=0, MTMSN=0
2023-05-18T19:05:14.520Z,1684436714.520 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:05:18.515Z,1684436718.515 [NAL9602](INFO): SBD MO Status=1, MOMSN=18326, MT Status=0, MTMSN=0
2023-05-18T19:05:18.577Z,1684436718.577 [NAL9602](INFO): Sent 73 bytes from file Logs/20230518T171335/Courier0061.lzma
2023-05-18T19:05:18.577Z,1684436718.577 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:05:31.086Z,1684436731.086 [NAL9602](INFO): SBD MO Status=1, MOMSN=18327, MT Status=0, MTMSN=0
2023-05-18T19:05:31.152Z,1684436731.152 [NAL9602](INFO): Sent 332 bytes from file Logs/20230518T171335/Express0062.lzma
2023-05-18T19:05:31.153Z,1684436731.153 [NAL9602](INFO): Packets left to send: 2
2023-05-18T19:05:47.275Z,1684436747.275 [NAL9602](INFO): SBD MO Status=1, MOMSN=18328, MT Status=0, MTMSN=0
2023-05-18T19:05:47.337Z,1684436747.337 [NAL9602](INFO): Sent 332 bytes from file Logs/20230518T171335/Express0062.lzma
2023-05-18T19:05:47.337Z,1684436747.337 [NAL9602](INFO): Packets left to send: 1
2023-05-18T19:05:49.684Z,1684436749.684 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:05:54.603Z,1684436754.603 [NAL9602](INFO): SBD MO Status=1, MOMSN=18329, MT Status=0, MTMSN=0
2023-05-18T19:05:54.652Z,1684436754.652 [NAL9602](INFO): Sent 117 bytes from file Logs/20230518T171335/Express0062.lzma
2023-05-18T19:05:54.653Z,1684436754.653 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:06:05.912Z,1684436765.912 [NAL9602](INFO): SBD MO Status=0, MOMSN=18330, MT Status=0, MTMSN=0
2023-05-18T19:06:05.978Z,1684436765.978 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:06:05.978Z,1684436765.978 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:06:05.978Z,1684436765.978 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:06:24.832Z,1684436784.832 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:06:36.615Z,1684436796.615 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:06:59.989Z,1684436819.989 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:07:35.488Z,1684436855.488 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003053
2023-05-18T19:09:21.748Z,1684436961.748 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:09:34.801Z,1684436974.801 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.251297
2023-05-18T19:10:32.056Z,1684437032.056 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:11:06.609Z,1684437066.609 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:11:06.609Z,1684437066.609 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:11:06.609Z,1684437066.609 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:11:06.609Z,1684437066.609 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:11:06.973Z,1684437066.973 [Default:CheckIn:D] Stopped
2023-05-18T19:11:06.973Z,1684437066.973 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 113.446965 min 
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn:E] Stopped
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn] Stopped
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn](INFO): Running loop #20
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn] Running Loop=20
2023-05-18T19:11:07.423Z,1684437067.423 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:11:07.424Z,1684437067.424 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:11:09.379Z,1684437069.379 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191108.00,A,3650.55522,N,12155.18274,W,11.585,255.62,180523,,,D*45
2023-05-18T19:11:09.382Z,1684437069.382 [NAL9602](INFO): GPS fix at 20230518T191108: (36.842587, -121.919712)
2023-05-18T19:11:09.420Z,1684437069.420 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:11:09.420Z,1684437069.420 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:11:23.252Z,1684437083.252 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002778
2023-05-18T19:11:30.759Z,1684437090.759 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230518T171335/Courier0064.lzma
2023-05-18T19:11:31.762Z,1684437091.762 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0064.lzma.bak
2023-05-18T19:11:31.762Z,1684437091.762 [DataOverHttps](INFO): SBD MOMSN=18327625
2023-05-18T19:11:41.337Z,1684437101.337 [NAL9602](INFO): SBD MO Status=1, MOMSN=18331, MT Status=0, MTMSN=0
2023-05-18T19:11:41.392Z,1684437101.392 [NAL9602](INFO): Sent 72 bytes from file Logs/20230518T171335/Courier0064.lzma
2023-05-18T19:11:41.392Z,1684437101.392 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:11:50.920Z,1684437110.920 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20230518T171335/Express0065.lzma
2023-05-18T19:11:51.922Z,1684437111.922 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0065.lzma.bak
2023-05-18T19:11:51.922Z,1684437111.922 [DataOverHttps](INFO): SBD MOMSN=18327628
2023-05-18T19:11:53.136Z,1684437113.136 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:11:53.136Z,1684437113.136 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:11:53.136Z,1684437113.136 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:12:12.100Z,1684437132.100 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:13:34.128Z,1684437214.128 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:13:51.197Z,1684437231.197 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.247948
2023-05-18T19:14:26.640Z,1684437266.640 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T19:14:26.640Z,1684437266.640 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.0,0000.,000
2023-05-18T19:14:44.444Z,1684437284.444 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:15:19.920Z,1684437319.920 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002834
2023-05-18T19:15:55.056Z,1684437355.056 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:16:20.157Z,1684437380.157 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239265
2023-05-18T19:16:53.715Z,1684437413.715 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:16:53.715Z,1684437413.715 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:16:53.715Z,1684437413.715 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:16:53.715Z,1684437413.715 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:16:54.120Z,1684437414.120 [Default:CheckIn:D] Stopped
2023-05-18T19:16:54.121Z,1684437414.121 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:16:54.545Z,1684437414.545 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.232674 min 
2023-05-18T19:16:54.545Z,1684437414.545 [Default:CheckIn:E] Stopped
2023-05-18T19:16:54.546Z,1684437414.546 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:16:54.546Z,1684437414.546 [Default:CheckIn] Stopped
2023-05-18T19:16:54.546Z,1684437414.546 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:16:54.546Z,1684437414.546 [Default:CheckIn](INFO): Running loop #21
2023-05-18T19:16:54.546Z,1684437414.546 [Default:CheckIn] Running Loop=21
2023-05-18T19:16:54.546Z,1684437414.546 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:16:54.546Z,1684437414.546 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:16:56.519Z,1684437416.519 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191655.00,A,3650.45139,N,12156.44532,W,12.790,282.24,180523,,,D*47
2023-05-18T19:16:56.521Z,1684437416.521 [NAL9602](INFO): GPS fix at 20230518T191655: (36.840857, -121.940755)
2023-05-18T19:16:56.531Z,1684437416.531 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:16:56.531Z,1684437416.531 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:16:56.934Z,1684437416.934 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T19:16:56.934Z,1684437416.934 [DVL_micro](ERROR): Failed to parse:
:BI,-0005,+00313,+00000,I
2023-05-18T19:17:05.336Z,1684437425.336 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:17:29.710Z,1684437449.710 [NAL9602](INFO): SBD MO Status=1, MOMSN=18332, MT Status=0, MTMSN=0
2023-05-18T19:17:29.768Z,1684437449.768 [NAL9602](INFO): Sent 73 bytes from file Logs/20230518T171335/Courier0067.lzma
2023-05-18T19:17:29.769Z,1684437449.769 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:17:39.878Z,1684437459.878 [NAL9602](INFO): SBD MO Status=1, MOMSN=18333, MT Status=0, MTMSN=0
2023-05-18T19:17:39.940Z,1684437459.940 [NAL9602](INFO): Sent 141 bytes from file Logs/20230518T171335/Express0068.lzma
2023-05-18T19:17:39.941Z,1684437459.941 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:17:40.476Z,1684437460.476 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:17:45.612Z,1684437465.612 [DVL_micro](ERROR): DVL uart error: serial timeout
2023-05-18T19:17:45.612Z,1684437465.612 [DVL_micro] Communications Fault, FailCount= 1
2023-05-18T19:17:45.612Z,1684437465.612 [DVL_micro](ERROR): Communications Fault
2023-05-18T19:17:45.613Z,1684437465.613 [DVL_micro](ERROR): Failed to parse:
2023-05-18T19:17:45.682Z,1684437465.682 [CBIT](ERROR): Communications Fault in component: DVL_micro
2023-05-18T19:17:46.004Z,1684437466.004 [DVL_micro](INFO): Powering down
2023-05-18T19:17:46.768Z,1684437466.768 [CBIT](INFO): Clearing failed state for component DVL_micro
2023-05-18T19:17:46.768Z,1684437466.768 [DVL_micro] No Fault, FailCount= 1
2023-05-18T19:17:49.574Z,1684437469.574 [NAL9602](INFO): SBD MO Status=0, MOMSN=18334, MT Status=0, MTMSN=0
2023-05-18T19:17:49.658Z,1684437469.658 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:17:49.658Z,1684437469.658 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:17:49.658Z,1684437469.658 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:18:15.616Z,1684437495.616 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:18:20.294Z,1684437500.294 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:19:13.661Z,1684437553.661 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003260
2023-05-18T19:20:02.092Z,1684437602.092 [DVL_micro](ERROR): Failed to parse:
:WI,+00189,+00999,+00495,+00000,A
2023-05-18T19:20:55.637Z,1684437655.637 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.255714
2023-05-18T19:22:00.428Z,1684437720.428 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003137
2023-05-18T19:22:07.331Z,1684437727.331 [DVL_micro](ERROR): Failed to parse:
:WI,+0200,+00284,+00000,A
2023-05-18T19:22:50.201Z,1684437770.201 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:22:50.201Z,1684437770.201 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:22:50.201Z,1684437770.201 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:22:50.201Z,1684437770.201 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:22:50.601Z,1684437770.601 [Default:CheckIn:D] Stopped
2023-05-18T19:22:50.601Z,1684437770.601 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 125.174089 min 
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn:E] Stopped
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn] Stopped
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn](INFO): Running loop #22
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn] Running Loop=22
2023-05-18T19:22:50.993Z,1684437770.993 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:22:50.994Z,1684437770.994 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:22:53.029Z,1684437773.029 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192252.00,A,3650.81579,N,12157.59445,W,8.806,256.87,180523,,,D*78
2023-05-18T19:22:53.031Z,1684437773.031 [NAL9602](INFO): GPS fix at 20230518T192252: (36.846930, -121.959907)
2023-05-18T19:22:53.042Z,1684437773.042 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:22:53.042Z,1684437773.042 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:23:00.663Z,1684437780.663 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230518T171335/Courier0070.lzma
2023-05-18T19:23:01.666Z,1684437781.666 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0070.lzma.bak
2023-05-18T19:23:01.666Z,1684437781.666 [DataOverHttps](INFO): SBD MOMSN=18327643
2023-05-18T19:23:14.015Z,1684437794.015 [NAL9602](INFO): SBD MO Status=0, MOMSN=18335, MT Status=0, MTMSN=0
2023-05-18T19:23:14.015Z,1684437794.015 [NAL9602](INFO): No messages in MT queue
2023-05-18T19:23:21.644Z,1684437801.644 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20230518T171335/Express0071.lzma
2023-05-18T19:23:22.646Z,1684437802.646 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0071.lzma.bak
2023-05-18T19:23:22.646Z,1684437802.646 [DataOverHttps](INFO): SBD MOMSN=18327646
2023-05-18T19:23:23.755Z,1684437803.755 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:23:23.755Z,1684437803.755 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:23:23.755Z,1684437803.755 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:23:44.717Z,1684437824.717 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:23:54.324Z,1684437834.324 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2023-05-18T19:24:23.453Z,1684437863.453 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.807564
2023-05-18T19:25:04.649Z,1684437904.649 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:25:39.788Z,1684437939.788 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:26:14.936Z,1684437974.936 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:26:48.484Z,1684438008.484 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002819
2023-05-18T19:28:01.217Z,1684438081.217 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:28:06.237Z,1684438086.237 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.255634
2023-05-18T19:28:24.301Z,1684438104.301 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:28:24.302Z,1684438104.302 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:28:24.302Z,1684438104.302 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:28:24.302Z,1684438104.302 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:28:24.699Z,1684438104.699 [Default:CheckIn:D] Stopped
2023-05-18T19:28:24.699Z,1684438104.699 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:28:25.137Z,1684438105.137 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 130.742399 min 
2023-05-18T19:28:25.137Z,1684438105.137 [Default:CheckIn:E] Stopped
2023-05-18T19:28:25.137Z,1684438105.137 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:28:25.137Z,1684438105.137 [Default:CheckIn] Stopped
2023-05-18T19:28:25.137Z,1684438105.137 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:28:25.138Z,1684438105.138 [Default:CheckIn](INFO): Running loop #23
2023-05-18T19:28:25.138Z,1684438105.138 [Default:CheckIn] Running Loop=23
2023-05-18T19:28:25.138Z,1684438105.138 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:28:25.138Z,1684438105.138 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:28:27.116Z,1684438107.116 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192826.00,A,3650.01107,N,12158.25775,W,10.205,237.74,180523,,,D*4B
2023-05-18T19:28:27.118Z,1684438107.118 [NAL9602](INFO): GPS fix at 20230518T192826: (36.833518, -121.970962)
2023-05-18T19:28:27.129Z,1684438107.129 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:28:27.129Z,1684438107.129 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:28:32.774Z,1684438112.774 [DVL_micro](ERROR): Failed to parse:170,-00058,+00544,+00000,I
2023-05-18T19:28:42.936Z,1684438122.936 [NAL9602](INFO): SBD MO Status=1, MOMSN=18336, MT Status=0, MTMSN=0
2023-05-18T19:28:42.990Z,1684438122.990 [NAL9602](INFO): Sent 73 bytes from file Logs/20230518T171335/Courier0073.lzma
2023-05-18T19:28:42.991Z,1684438122.991 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:28:56.703Z,1684438136.703 [NAL9602](INFO): SBD MO Status=1, MOMSN=18337, MT Status=0, MTMSN=0
2023-05-18T19:28:56.760Z,1684438136.760 [NAL9602](INFO): Sent 145 bytes from file Logs/20230518T171335/Express0074.lzma
2023-05-18T19:28:56.761Z,1684438136.761 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:29:10.032Z,1684438150.032 [NAL9602](INFO): SBD MO Status=0, MOMSN=18338, MT Status=0, MTMSN=0
2023-05-18T19:29:10.106Z,1684438150.106 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:29:10.106Z,1684438150.106 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:29:10.106Z,1684438150.106 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:29:11.516Z,1684438151.516 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:29:40.737Z,1684438180.737 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:29:46.664Z,1684438186.664 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:30:21.836Z,1684438221.836 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:30:56.977Z,1684438256.977 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:31:32.116Z,1684438292.116 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:32:07.256Z,1684438327.256 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:32:42.396Z,1684438362.396 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:33:03.880Z,1684438383.880 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002728
2023-05-18T19:34:10.624Z,1684438450.624 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:34:10.624Z,1684438450.624 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:34:10.624Z,1684438450.624 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:34:10.624Z,1684438450.624 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:34:11.035Z,1684438451.035 [Default:CheckIn:D] Stopped
2023-05-18T19:34:11.035Z,1684438451.035 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:34:11.429Z,1684438451.429 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 136.514665 min 
2023-05-18T19:34:11.429Z,1684438451.429 [Default:CheckIn:E] Stopped
2023-05-18T19:34:11.429Z,1684438451.429 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:34:11.429Z,1684438451.429 [Default:CheckIn] Stopped
2023-05-18T19:34:11.429Z,1684438451.429 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:34:11.430Z,1684438451.430 [Default:CheckIn](INFO): Running loop #24
2023-05-18T19:34:11.430Z,1684438451.430 [Default:CheckIn] Running Loop=24
2023-05-18T19:34:11.430Z,1684438451.430 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:34:11.430Z,1684438451.430 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:34:13.457Z,1684438453.457 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193412.00,A,3649.20222,N,12158.99231,W,18.641,196.25,180523,,,D*4C
2023-05-18T19:34:13.459Z,1684438453.459 [NAL9602](INFO): GPS fix at 20230518T193412: (36.820037, -121.983205)
2023-05-18T19:34:13.473Z,1684438453.473 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:34:13.474Z,1684438453.474 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:34:22.327Z,1684438462.327 [NAL9602](INFO): SBD MO Status=0, MOMSN=18339, MT Status=0, MTMSN=0
2023-05-18T19:34:22.327Z,1684438462.327 [NAL9602](INFO): No messages in MT queue
2023-05-18T19:34:34.779Z,1684438474.779 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=64.361732
2023-05-18T19:34:38.079Z,1684438478.079 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T19:34:38.079Z,1684438478.079 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+0.0,14
2023-05-18T19:34:48.364Z,1684438488.364 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002674
2023-05-18T19:35:01.659Z,1684438501.659 [NAL9602](INFO): SBD MO Status=2, MOMSN=18340, MT Status=2, MTMSN=0
2023-05-18T19:35:01.659Z,1684438501.659 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:35:03.187Z,1684438503.187 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20230518T171335/Courier0076.lzma
2023-05-18T19:35:04.190Z,1684438504.190 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Courier0076.lzma.bak
2023-05-18T19:35:04.190Z,1684438504.190 [DataOverHttps](INFO): SBD MOMSN=18327658
2023-05-18T19:35:21.015Z,1684438521.015 [DataOverHttps](INFO): Sending 147 bytes from file Logs/20230518T171335/Express0077.lzma
2023-05-18T19:35:23.022Z,1684438523.022 [DataOverHttps](INFO): Moved sent file to Logs/20230518T171335/Express0077.lzma.bak
2023-05-18T19:35:23.022Z,1684438523.022 [DataOverHttps](INFO): SBD MOMSN=18327661
2023-05-18T19:35:24.288Z,1684438524.288 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:35:24.288Z,1684438524.288 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:35:24.288Z,1684438524.288 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:35:32.358Z,1684438532.358 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:36:23.261Z,1684438583.261 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239666
2023-05-18T19:36:37.845Z,1684438597.845 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T19:36:37.845Z,1684438597.845 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+99999.99,+9999.99
2023-05-18T19:36:40.626Z,1684438600.626 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-18T19:36:40.634Z,1684438600.634 [BPC1](INFO): Calculating totals. Valid battery stick count: 48. Valid reserve battery stick count: 5.
2023-05-18T19:36:40.658Z,1684438600.658 [BPC1](INFO): Received data from all battery sticks.
2023-05-18T19:37:04.448Z,1684438624.448 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:37:39.617Z,1684438659.617 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:37:42.046Z,1684438662.046 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T19:37:42.046Z,1684438662.046 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999..99
2023-05-18T19:38:14.752Z,1684438694.752 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:38:40.630Z,1684438720.630 [DVL_micro](ERROR): Failed to parse:
:SA,+09.16,-06.34,194.5
2023-05-18T19:38:49.892Z,1684438729.892 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:38:55.984Z,1684438735.984 [DVL_micro](ERROR): only read 3 of 4 data items
2023-05-18T19:38:55.984Z,1684438735.984 [DVL_micro](ERROR): Failed to parse:
:BI,+0140,+00108,+00000,I
2023-05-18T19:39:25.044Z,1684438765.044 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:40:00.204Z,1684438800.204 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:40:24.859Z,1684438824.859 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:40:24.859Z,1684438824.859 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:40:24.859Z,1684438824.859 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:40:24.860Z,1684438824.860 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:40:25.278Z,1684438825.278 [Default:CheckIn:D] Stopped
2023-05-18T19:40:25.278Z,1684438825.278 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:40:25.673Z,1684438825.673 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 142.752051 min 
2023-05-18T19:40:25.673Z,1684438825.673 [Default:CheckIn:E] Stopped
2023-05-18T19:40:25.673Z,1684438825.673 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:40:25.673Z,1684438825.673 [Default:CheckIn] Stopped
2023-05-18T19:40:25.673Z,1684438825.673 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:40:25.673Z,1684438825.673 [Default:CheckIn](INFO): Running loop #25
2023-05-18T19:40:25.674Z,1684438825.674 [Default:CheckIn] Running Loop=25
2023-05-18T19:40:25.674Z,1684438825.674 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:40:25.674Z,1684438825.674 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:40:27.684Z,1684438827.684 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194027.00,A,3647.60476,N,12159.88084,W,16.076,208.96,180523,,,A*4C
2023-05-18T19:40:27.686Z,1684438827.686 [NAL9602](INFO): GPS fix at 20230518T194027: (36.793413, -121.998014)
2023-05-18T19:40:27.725Z,1684438827.725 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:40:27.725Z,1684438827.725 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:40:35.345Z,1684438835.345 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:40:40.611Z,1684438840.611 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T19:40:40.611Z,1684438840.611 [DVL_micro](ERROR): Failed to parse:
:TS,000000005.0,+19.2,489.0,0000066,-00363,+00209,+00000,A
2023-05-18T19:41:10.489Z,1684438870.489 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:41:37.631Z,1684438897.631 [NAL9602](INFO): SBD MO Status=2, MOMSN=18340, MT Status=2, MTMSN=0
2023-05-18T19:41:37.632Z,1684438897.632 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:41:39.660Z,1684438899.660 [DVL_micro](ERROR): Failed to parse:
9.99,+9999.99,+9999.99,+9999.99
2023-05-18T19:41:45.628Z,1684438905.628 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:42:03.551Z,1684438923.551 [NAL9602](INFO): SBD MO Status=2, MOMSN=18340, MT Status=2, MTMSN=0
2023-05-18T19:42:03.551Z,1684438923.551 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:42:20.768Z,1684438940.768 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:42:30.280Z,1684438950.280 [NAL9602](INFO): SBD MO Status=1, MOMSN=18340, MT Status=0, MTMSN=0
2023-05-18T19:42:30.336Z,1684438950.336 [NAL9602](INFO): Sent 85 bytes from file Logs/20230518T171335/Courier0079.lzma
2023-05-18T19:42:30.337Z,1684438950.337 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:42:40.843Z,1684438960.843 [NAL9602](INFO): SBD MO Status=1, MOMSN=18341, MT Status=0, MTMSN=0
2023-05-18T19:42:40.896Z,1684438960.896 [NAL9602](INFO): Sent 146 bytes from file Logs/20230518T171335/Express0080.lzma
2023-05-18T19:42:40.896Z,1684438960.896 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:42:55.908Z,1684438975.908 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:43:05.887Z,1684438985.887 [NAL9602](INFO): SBD MO Status=0, MOMSN=18342, MT Status=0, MTMSN=0
2023-05-18T19:43:05.966Z,1684438985.966 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:43:05.966Z,1684438985.966 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:43:05.966Z,1684438985.966 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:43:31.056Z,1684439011.056 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:43:36.589Z,1684439016.589 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:43:50.748Z,1684439030.748 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002741
2023-05-18T19:44:51.325Z,1684439091.325 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.579117
2023-05-18T19:45:52.568Z,1684439152.568 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:46:27.720Z,1684439187.720 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:46:46.133Z,1684439206.133 [DVL_micro](ERROR): Failed to parse:
:SA,+01.92,-05.57,224.8
2023-05-18T19:47:02.865Z,1684439222.865 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:47:38.040Z,1684439258.040 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:48:06.532Z,1684439286.532 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:48:06.532Z,1684439286.532 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:48:06.532Z,1684439286.532 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:48:06.532Z,1684439286.532 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:48:06.942Z,1684439286.942 [Default:CheckIn:D] Stopped
2023-05-18T19:48:06.942Z,1684439286.942 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 150.446452 min 
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn:E] Stopped
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn] Stopped
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn](INFO): Running loop #26
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn] Running Loop=26
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:48:07.341Z,1684439287.341 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:48:09.346Z,1684439289.346 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194808.00,A,3646.27973,N,12200.91382,W,10.225,200.91,180523,,,D*49
2023-05-18T19:48:09.349Z,1684439289.349 [NAL9602](INFO): GPS fix at 20230518T194808: (36.771329, -122.015230)
2023-05-18T19:48:09.359Z,1684439289.359 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:48:09.359Z,1684439289.359 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:48:13.180Z,1684439293.180 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:48:47.795Z,1684439327.795 [NAL9602](INFO): SBD MO Status=2, MOMSN=18343, MT Status=2, MTMSN=0
2023-05-18T19:48:47.795Z,1684439327.795 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:48:48.320Z,1684439328.320 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:49:03.586Z,1684439343.586 [NAL9602](INFO): SBD MO Status=1, MOMSN=18343, MT Status=0, MTMSN=0
2023-05-18T19:49:03.644Z,1684439343.644 [NAL9602](INFO): Sent 72 bytes from file Logs/20230518T171335/Courier0082.lzma
2023-05-18T19:49:03.644Z,1684439343.644 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:49:21.840Z,1684439361.840 [NAL9602](INFO): SBD MO Status=2, MOMSN=18344, MT Status=2, MTMSN=0
2023-05-18T19:49:21.840Z,1684439361.840 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:49:23.460Z,1684439363.460 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:49:58.608Z,1684439398.608 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:50:33.740Z,1684439433.740 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:50:40.272Z,1684439440.272 [NAL9602](INFO): SBD MO Status=1, MOMSN=18344, MT Status=0, MTMSN=0
2023-05-18T19:50:40.329Z,1684439440.329 [NAL9602](INFO): Sent 145 bytes from file Logs/20230518T171335/Express0083.lzma
2023-05-18T19:50:40.329Z,1684439440.329 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:50:49.160Z,1684439449.160 [NAL9602](INFO): SBD MO Status=0, MOMSN=18345, MT Status=0, MTMSN=0
2023-05-18T19:50:49.238Z,1684439449.238 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:50:49.238Z,1684439449.238 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:50:49.239Z,1684439449.239 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:51:08.880Z,1684439468.880 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:51:19.862Z,1684439479.862 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:51:44.020Z,1684439504.020 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:52:19.160Z,1684439539.160 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:52:48.749Z,1684439568.749 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T19:52:48.750Z,1684439568.750 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489.0,000
2023-05-18T19:52:54.300Z,1684439574.300 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:53:29.440Z,1684439609.440 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:54:04.580Z,1684439644.580 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:54:39.736Z,1684439679.736 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:55:14.884Z,1684439714.884 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:55:49.743Z,1684439749.743 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T19:55:49.743Z,1684439749.743 [Default:CheckIn:C.Wait] Stopped
2023-05-18T19:55:49.743Z,1684439749.743 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T19:55:49.743Z,1684439749.743 [Default:CheckIn:D] Running Loop=1
2023-05-18T19:55:50.032Z,1684439750.032 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:55:50.157Z,1684439750.157 [Default:CheckIn:D] Stopped
2023-05-18T19:55:50.157Z,1684439750.157 [Default:CheckIn:E] Running Loop=1
2023-05-18T19:55:50.565Z,1684439750.565 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 158.166699 min 
2023-05-18T19:55:50.565Z,1684439750.565 [Default:CheckIn:E] Stopped
2023-05-18T19:55:50.565Z,1684439750.565 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T19:55:50.565Z,1684439750.565 [Default:CheckIn] Stopped
2023-05-18T19:55:50.565Z,1684439750.565 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T19:55:50.566Z,1684439750.566 [Default:CheckIn](INFO): Running loop #27
2023-05-18T19:55:50.566Z,1684439750.566 [Default:CheckIn] Running Loop=27
2023-05-18T19:55:50.566Z,1684439750.566 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T19:55:50.566Z,1684439750.566 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T19:55:52.574Z,1684439752.574 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195551.00,A,3645.19195,N,12201.54930,W,8.844,235.57,180523,,,D*74
2023-05-18T19:55:52.577Z,1684439752.577 [NAL9602](INFO): GPS fix at 20230518T195551: (36.753199, -122.025822)
2023-05-18T19:55:52.612Z,1684439752.612 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T19:55:52.613Z,1684439752.613 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T19:56:16.870Z,1684439776.870 [NAL9602](INFO): SBD MO Status=2, MOMSN=18346, MT Status=2, MTMSN=0
2023-05-18T19:56:16.870Z,1684439776.870 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:56:25.180Z,1684439785.180 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:56:34.286Z,1684439794.286 [NAL9602](INFO): SBD MO Status=2, MOMSN=18346, MT Status=2, MTMSN=0
2023-05-18T19:56:34.286Z,1684439794.286 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:57:00.195Z,1684439820.195 [NAL9602](INFO): SBD MO Status=2, MOMSN=18346, MT Status=2, MTMSN=0
2023-05-18T19:57:00.195Z,1684439820.195 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:57:00.322Z,1684439820.322 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:57:26.091Z,1684439846.091 [NAL9602](INFO): SBD MO Status=2, MOMSN=18346, MT Status=2, MTMSN=0
2023-05-18T19:57:26.091Z,1684439846.091 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:57:35.460Z,1684439855.460 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:58:10.608Z,1684439890.608 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:58:13.827Z,1684439893.827 [NAL9602](INFO): SBD MO Status=2, MOMSN=18346, MT Status=2, MTMSN=0
2023-05-18T19:58:13.827Z,1684439893.827 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T19:58:42.575Z,1684439922.575 [NAL9602](INFO): SBD MO Status=1, MOMSN=18346, MT Status=0, MTMSN=0
2023-05-18T19:58:42.628Z,1684439922.628 [NAL9602](INFO): Sent 73 bytes from file Logs/20230518T171335/Courier0085.lzma
2023-05-18T19:58:42.629Z,1684439922.629 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:58:45.748Z,1684439925.748 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:58:52.310Z,1684439932.310 [NAL9602](INFO): SBD MO Status=1, MOMSN=18347, MT Status=0, MTMSN=0
2023-05-18T19:58:52.364Z,1684439932.364 [NAL9602](INFO): Sent 144 bytes from file Logs/20230518T171335/Express0086.lzma
2023-05-18T19:58:52.365Z,1684439932.365 [NAL9602](INFO): Packets left to send: 0
2023-05-18T19:59:02.819Z,1684439942.819 [NAL9602](INFO): SBD MO Status=0, MOMSN=18348, MT Status=0, MTMSN=0
2023-05-18T19:59:02.909Z,1684439942.909 [Default:CheckIn:Read_Iridium] Stopped
2023-05-18T19:59:02.909Z,1684439942.909 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-18T19:59:02.909Z,1684439942.909 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-18T19:59:20.888Z,1684439960.888 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T19:59:33.521Z,1684439973.521 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-18T19:59:56.028Z,1684439996.028 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:00:31.180Z,1684440031.180 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:00:41.049Z,1684440041.049 [DVL_micro](ERROR): Failed to parse:265,+01737,+00189,+00000,I
2023-05-18T20:01:06.320Z,1684440066.320 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:01:41.484Z,1684440101.484 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:02:16.632Z,1684440136.632 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:02:51.772Z,1684440171.772 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:03:26.920Z,1684440206.920 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:04:02.060Z,1684440242.060 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:04:03.409Z,1684440243.409 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2023-05-18T20:04:03.409Z,1684440243.409 [Default:CheckIn:C.Wait] Stopped
2023-05-18T20:04:03.409Z,1684440243.409 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-18T20:04:03.409Z,1684440243.409 [Default:CheckIn:D] Running Loop=1
2023-05-18T20:04:03.814Z,1684440243.814 [Default:CheckIn:D] Stopped
2023-05-18T20:04:03.814Z,1684440243.814 [Default:CheckIn:E] Running Loop=1
2023-05-18T20:04:04.229Z,1684440244.229 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 166.394320 min 
2023-05-18T20:04:04.229Z,1684440244.229 [Default:CheckIn:E] Stopped
2023-05-18T20:04:04.229Z,1684440244.229 [Default:CheckIn](INFO): Completed Default:CheckIn
2023-05-18T20:04:04.229Z,1684440244.229 [Default:CheckIn] Stopped
2023-05-18T20:04:04.230Z,1684440244.230 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-18T20:04:04.230Z,1684440244.230 [Default:CheckIn](INFO): Running loop #28
2023-05-18T20:04:04.230Z,1684440244.230 [Default:CheckIn] Running Loop=28
2023-05-18T20:04:04.230Z,1684440244.230 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-18T20:04:04.230Z,1684440244.230 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-18T20:04:06.222Z,1684440246.222 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200405.00,A,3645.01125,N,12201.46536,W,0.816,166.39,180523,,,A*77
2023-05-18T20:04:06.225Z,1684440246.225 [NAL9602](INFO): GPS fix at 20230518T200405: (36.750188, -122.024423)
2023-05-18T20:04:06.235Z,1684440246.235 [Default:CheckIn:Read_GPS] Stopped
2023-05-18T20:04:06.235Z,1684440246.235 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-18T20:04:29.707Z,1684440269.707 [NAL9602](INFO): SBD MO Status=2, MOMSN=18349, MT Status=2, MTMSN=0
2023-05-18T20:04:29.707Z,1684440269.707 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T20:04:37.216Z,1684440277.216 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:04:55.617Z,1684440295.617 [NAL9602](INFO): SBD MO Status=2, MOMSN=18349, MT Status=2, MTMSN=0
2023-05-18T20:04:55.617Z,1684440295.617 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T20:05:12.372Z,1684440312.372 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:05:13.445Z,1684440313.445 [NAL9602](INFO): SBD MO Status=2, MOMSN=18349, MT Status=2, MTMSN=0
2023-05-18T20:05:13.445Z,1684440313.445 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T20:05:29.287Z,1684440329.287 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2023-05-18T20:05:29.287Z,1684440329.287 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+1.0,1489.0,000
2023-05-18T20:05:38.535Z,1684440338.535 [NAL9602](INFO): SBD MO Status=2, MOMSN=18349, MT Status=2, MTMSN=0
2023-05-18T20:05:38.535Z,1684440338.535 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T20:05:47.512Z,1684440347.512 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:06:04.427Z,1684440364.427 [NAL9602](INFO): SBD MO Status=2, MOMSN=18349, MT Status=2, MTMSN=0
2023-05-18T20:06:04.427Z,1684440364.427 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T20:06:21.844Z,1684440381.844 [NAL9602](INFO): SBD MO Status=2, MOMSN=18349, MT Status=2, MTMSN=0
2023-05-18T20:06:21.844Z,1684440381.844 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2023-05-18T20:06:22.652Z,1684440382.652 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2023-05-18T20:06:42.150Z,1684440402.150 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=18349, MT Status=1, MTMSN=1272
2023-05-18T20:06:42.200Z,1684440402.200 [NAL9602](INFO): Sent 73 bytes from file Logs/20230518T171335/Courier0088.lzma
2023-05-18T20:06:42.201Z,1684440402.201 [NAL9602](INFO): Packets left to send: 0
2023-05-18T20:06:42.601Z,1684440402.601 [NAL9602](INFO): Received command: restart logs