2021-12-10T16:24:24.949Z,1639153464.949 [Supervisor](DEBUG): Initializing supervisor.
2021-12-10T16:24:24.953Z,1639153464.953 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-12-10T16:24:24.954Z,1639153464.954 [SyncHandler](INFO): Protected caller Thread ID is 334
2021-12-10T16:24:24.954Z,1639153464.954 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-12-10T16:24:24.955Z,1639153464.955 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-12-10T16:24:24.955Z,1639153464.955 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 335
2021-12-10T16:24:24.960Z,1639153464.960 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-12-10T16:24:24.978Z,1639153464.978 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2021-12-10T16:24:24.979Z,1639153464.979 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-12-10T16:24:24.979Z,1639153464.979 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 336
2021-12-10T16:24:24.983Z,1639153464.983 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-12-10T16:24:24.984Z,1639153464.984 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-12-10T16:24:24.985Z,1639153464.985 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 337
2021-12-10T16:24:24.987Z,1639153464.987 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-12-10T16:24:24.988Z,1639153464.988 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2021-12-10T16:24:24.988Z,1639153464.988 [logger ThreadHandler](INFO): Protected caller Thread ID is 338
2021-12-10T16:24:24.992Z,1639153464.992 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-12-10T16:24:24.993Z,1639153464.993 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-12-10T16:24:24.994Z,1639153464.994 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-12-10T16:24:25.088Z,1639153465.088 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-12-10T16:24:25.089Z,1639153465.089 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-12-10T16:24:25.681Z,1639153465.681 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-12-10T16:24:25.681Z,1639153465.681 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-12-10T16:24:25.891Z,1639153465.891 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-12-10T16:24:25.892Z,1639153465.892 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-12-10T16:24:25.968Z,1639153465.968 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-12-10T16:24:26.088Z,1639153466.088 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-12-10T16:24:26.089Z,1639153466.089 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-12-10T16:24:26.168Z,1639153466.168 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-12-10T16:24:26.272Z,1639153466.272 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-12-10T16:24:26.273Z,1639153466.273 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-12-10T16:24:26.625Z,1639153466.625 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-12-10T16:24:26.626Z,1639153466.626 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-12-10T16:24:27.228Z,1639153467.228 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-12-10T16:24:27.229Z,1639153467.229 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-12-10T16:24:27.379Z,1639153467.379 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-12-10T16:24:27.379Z,1639153467.379 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-12-10T16:24:27.560Z,1639153467.560 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-12-10T16:24:27.561Z,1639153467.561 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-12-10T16:24:28.008Z,1639153468.008 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-12-10T16:24:28.009Z,1639153468.009 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-12-10T16:24:28.240Z,1639153468.240 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-12-10T16:24:28.241Z,1639153468.241 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-12-10T16:24:28.439Z,1639153468.439 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-12-10T16:24:28.439Z,1639153468.439 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-12-10T16:24:28.787Z,1639153468.787 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-12-10T16:24:28.787Z,1639153468.787 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-12-10T16:24:29.119Z,1639153469.119 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-12-10T16:24:29.121Z,1639153469.121 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2021-12-10T16:24:29.122Z,1639153469.122 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2021-12-10T16:24:29.203Z,1639153469.203 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2021-12-10T16:24:29.353Z,1639153469.353 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2021-12-10T16:24:29.459Z,1639153469.459 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2021-12-10T16:24:29.542Z,1639153469.542 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2021-12-10T16:24:29.634Z,1639153469.634 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2021-12-10T16:24:29.976Z,1639153469.976 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2021-12-10T16:24:30.380Z,1639153470.380 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-12-10T16:24:30.380Z,1639153470.380 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2021-12-10T16:24:30.549Z,1639153470.549 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2021-12-10T16:24:30.645Z,1639153470.645 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2021-12-10T16:24:30.780Z,1639153470.780 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2021-12-10T16:24:30.877Z,1639153470.877 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/root/
2021-12-10T16:24:30.877Z,1639153470.877 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-12-10T16:24:30.888Z,1639153470.888 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-12-10T16:24:30.985Z,1639153470.985 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-12-10T16:24:30.986Z,1639153470.986 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-12-10T16:24:31.040Z,1639153471.040 [VerticalControl](DEBUG): Construct VerticalControl.
2021-12-10T16:24:31.102Z,1639153471.102 [VerticalControl] Loaded
2021-12-10T16:24:31.102Z,1639153471.102 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-12-10T16:24:31.105Z,1639153471.105 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-12-10T16:24:31.143Z,1639153471.143 [HorizontalControl] Loaded
2021-12-10T16:24:31.143Z,1639153471.143 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-12-10T16:24:31.146Z,1639153471.146 [SpeedControl](DEBUG): Construct SpeedControl.
2021-12-10T16:24:31.149Z,1639153471.149 [SpeedControl] Loaded
2021-12-10T16:24:31.149Z,1639153471.149 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-12-10T16:24:31.151Z,1639153471.151 [LoopControl](DEBUG): Construct LoopControl.
2021-12-10T16:24:31.152Z,1639153471.152 [LoopControl] Loaded
2021-12-10T16:24:31.152Z,1639153471.152 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-12-10T16:24:31.153Z,1639153471.153 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-12-10T16:24:31.153Z,1639153471.153 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-12-10T16:24:31.196Z,1639153471.196 [DepthRateCalculator] Loaded
2021-12-10T16:24:31.196Z,1639153471.196 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-12-10T16:24:31.201Z,1639153471.201 [PitchRateCalculator] Loaded
2021-12-10T16:24:31.201Z,1639153471.201 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-12-10T16:24:31.211Z,1639153471.211 [SpeedCalculator] Loaded
2021-12-10T16:24:31.212Z,1639153471.212 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-12-10T16:24:31.225Z,1639153471.225 [TempGradientCalculator] Loaded
2021-12-10T16:24:31.225Z,1639153471.225 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-12-10T16:24:31.229Z,1639153471.229 [YawRateCalculator] Loaded
2021-12-10T16:24:31.230Z,1639153471.230 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-12-10T16:24:31.247Z,1639153471.247 [ElevatorOffsetCalculator] Loaded
2021-12-10T16:24:31.247Z,1639153471.247 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-12-10T16:24:31.248Z,1639153471.248 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-12-10T16:24:31.248Z,1639153471.248 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-12-10T16:24:31.277Z,1639153471.277 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-12-10T16:24:31.278Z,1639153471.278 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-12-10T16:24:31.336Z,1639153471.336 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-12-10T16:24:31.336Z,1639153471.336 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-12-10T16:24:31.662Z,1639153471.662 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-12-10T16:24:31.663Z,1639153471.663 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-12-10T16:24:31.767Z,1639153471.767 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-12-10T16:24:31.768Z,1639153471.768 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-12-10T16:24:32.154Z,1639153472.154 [AHRS_M2] Loaded
2021-12-10T16:24:32.155Z,1639153472.155 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-12-10T16:24:32.184Z,1639153472.184 [BackseatComponent] Loaded
2021-12-10T16:24:32.184Z,1639153472.184 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2021-12-10T16:24:32.186Z,1639153472.186 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 409474E0
2021-12-10T16:24:32.186Z,1639153472.186 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 424
2021-12-10T16:24:32.189Z,1639153472.189 [LcmUniversalReporter] Loaded
2021-12-10T16:24:32.189Z,1639153472.189 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2021-12-10T16:24:32.973Z,1639153472.973 [BPC1] Loaded
2021-12-10T16:24:32.974Z,1639153472.974 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-12-10T16:24:33.044Z,1639153473.044 [DataOverHttps] Loaded
2021-12-10T16:24:33.044Z,1639153473.044 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-12-10T16:24:33.045Z,1639153473.045 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409774E0
2021-12-10T16:24:33.046Z,1639153473.046 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 425
2021-12-10T16:24:33.065Z,1639153473.065 [Depth_Keller] Loaded
2021-12-10T16:24:33.066Z,1639153473.066 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-12-10T16:24:33.070Z,1639153473.070 [DropWeight] Loaded
2021-12-10T16:24:33.071Z,1639153473.071 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-12-10T16:24:33.130Z,1639153473.130 [NAL9602] Loaded
2021-12-10T16:24:33.130Z,1639153473.130 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-12-10T16:24:33.159Z,1639153473.159 [Onboard] Loaded
2021-12-10T16:24:33.160Z,1639153473.160 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-12-10T16:24:33.161Z,1639153473.161 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409A74E0
2021-12-10T16:24:33.161Z,1639153473.161 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 426
2021-12-10T16:24:33.174Z,1639153473.174 [Power24vConverter] Loaded
2021-12-10T16:24:33.174Z,1639153473.174 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-12-10T16:24:33.187Z,1639153473.187 [Radio_Surface] Loaded
2021-12-10T16:24:33.187Z,1639153473.187 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-12-10T16:24:33.188Z,1639153473.188 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409D74E0
2021-12-10T16:24:33.188Z,1639153473.188 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 427
2021-12-10T16:24:33.231Z,1639153473.231 [RDI_Pathfinder] Loaded
2021-12-10T16:24:33.232Z,1639153473.232 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2021-12-10T16:24:33.313Z,1639153473.313 [DAT] Loaded
2021-12-10T16:24:33.313Z,1639153473.313 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-12-10T16:24:33.314Z,1639153473.314 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-12-10T16:24:33.314Z,1639153473.314 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-12-10T16:24:33.394Z,1639153473.394 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-12-10T16:24:33.394Z,1639153473.394 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-12-10T16:24:33.407Z,1639153473.407 [NavChart] Loaded
2021-12-10T16:24:33.408Z,1639153473.408 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-12-10T16:24:33.413Z,1639153473.413 [UniversalFixResidualReporter] Loaded
2021-12-10T16:24:33.414Z,1639153473.414 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-12-10T16:24:33.414Z,1639153473.414 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-12-10T16:24:33.415Z,1639153473.415 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-12-10T16:24:33.559Z,1639153473.559 [SBIT](DEBUG): Construct Startup Built In Test.
2021-12-10T16:24:33.569Z,1639153473.569 [SBIT] Loaded
2021-12-10T16:24:33.569Z,1639153473.569 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-12-10T16:24:33.572Z,1639153473.572 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-12-10T16:24:33.585Z,1639153473.585 [IBIT] Loaded
2021-12-10T16:24:33.585Z,1639153473.585 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-12-10T16:24:33.591Z,1639153473.591 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-12-10T16:24:33.692Z,1639153473.692 [CBIT] Loaded
2021-12-10T16:24:33.692Z,1639153473.692 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-12-10T16:24:33.693Z,1639153473.693 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-12-10T16:24:33.693Z,1639153473.693 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-12-10T16:24:33.824Z,1639153473.824 [BuoyancyServo] Loaded
2021-12-10T16:24:33.824Z,1639153473.824 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-12-10T16:24:33.844Z,1639153473.844 [ElevatorServo] Loaded
2021-12-10T16:24:33.844Z,1639153473.844 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-12-10T16:24:33.864Z,1639153473.864 [MassServo] Loaded
2021-12-10T16:24:33.864Z,1639153473.864 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-12-10T16:24:33.882Z,1639153473.882 [RudderServo] Loaded
2021-12-10T16:24:33.883Z,1639153473.883 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-12-10T16:24:33.901Z,1639153473.901 [ThrusterServo] Loaded
2021-12-10T16:24:33.902Z,1639153473.902 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-12-10T16:24:33.902Z,1639153473.902 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-12-10T16:24:33.903Z,1639153473.903 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-12-10T16:24:33.913Z,1639153473.913 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-12-10T16:24:33.914Z,1639153473.914 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-12-10T16:24:34.087Z,1639153474.087 [CTD_Seabird] Loaded
2021-12-10T16:24:34.088Z,1639153474.088 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-12-10T16:24:34.089Z,1639153474.089 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B104E0
2021-12-10T16:24:34.089Z,1639153474.089 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 428
2021-12-10T16:24:34.109Z,1639153474.109 [PAR_Licor] Loaded
2021-12-10T16:24:34.109Z,1639153474.109 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-12-10T16:24:34.142Z,1639153474.142 [WetLabsBB2FL] Loaded
2021-12-10T16:24:34.142Z,1639153474.142 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-12-10T16:24:34.143Z,1639153474.143 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B404E0
2021-12-10T16:24:34.143Z,1639153474.143 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 429
2021-12-10T16:24:34.164Z,1639153474.164 [WetLabsUBAT] Loaded
2021-12-10T16:24:34.164Z,1639153474.164 [ComponentRegistry](DEBUG): Component "WetLabsUBAT" handled in its own thread.
2021-12-10T16:24:34.165Z,1639153474.165 [WetLabsUBAT ThreadHandler](DEBUG): Created PCaller Thread at 40B704E0
2021-12-10T16:24:34.165Z,1639153474.165 [WetLabsUBAT ThreadHandler](INFO): Protected caller Thread ID is 430
2021-12-10T16:24:34.166Z,1639153474.166 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-12-10T16:24:34.172Z,1639153474.172 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-12-10T16:24:34.175Z,1639153474.175 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-12-10T16:24:34.186Z,1639153474.186 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-12-10T16:24:34.187Z,1639153474.187 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BA04E0
2021-12-10T16:24:34.187Z,1639153474.187 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 431
2021-12-10T16:24:34.192Z,1639153474.192 [Supervisor](INFO): Main Thread ID is 333
2021-12-10T16:24:34.192Z,1639153474.192 [Supervisor](DEBUG): Running supervisor.
2021-12-10T16:24:34.193Z,1639153474.193 [CommandExec ThreadHandler](INFO): Handler Thread ID is 432
2021-12-10T16:24:34.193Z,1639153474.193 [CommandExec](INFO): Initializing the command executive.
2021-12-10T16:24:34.195Z,1639153474.195 [CommandLine ThreadHandler](INFO): Handler Thread ID is 433
2021-12-10T16:24:34.197Z,1639153474.197 [controlThread ThreadHandler](INFO): Handler Thread ID is 434
2021-12-10T16:24:34.197Z,1639153474.197 [controlThread](DEBUG): Initializing ControlThread
2021-12-10T16:24:34.198Z,1639153474.198 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-12-10T16:24:34.200Z,1639153474.200 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-12-10T16:24:34.201Z,1639153474.201 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-12-10T16:24:34.202Z,1639153474.202 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-12-10T16:24:34.202Z,1639153474.202 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-12-10T16:24:34.203Z,1639153474.203 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-12-10T16:24:34.203Z,1639153474.203 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-12-10T16:24:34.203Z,1639153474.203 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-12-10T16:24:34.204Z,1639153474.204 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-12-10T16:24:34.204Z,1639153474.204 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-12-10T16:24:34.209Z,1639153474.209 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-12-10T16:24:34.210Z,1639153474.210 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-12-10T16:24:34.210Z,1639153474.210 [SBIT](INFO): Initialize SBIT Component.
2021-12-10T16:24:34.211Z,1639153474.211 [SBIT](IMPORTANT): git: 2021-11-29
2021-12-10T16:24:34.211Z,1639153474.211 [SBIT](INFO): git hash: f462e1af5d4560b0531ff1e41adede0f51e7b106
2021-12-10T16:24:34.211Z,1639153474.211 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-12-10T16:24:34.212Z,1639153474.212 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2021-12-10T16:24:34.214Z,1639153474.214 [SBIT](INFO): Beginning SBIT in 52.000000 seconds.
2021-12-10T16:24:34.214Z,1639153474.214 [IBIT](INFO): Initialize IBIT Component.
2021-12-10T16:24:34.215Z,1639153474.215 [CBIT](DEBUG): Initialize CBIT Component.
2021-12-10T16:24:34.216Z,1639153474.216 [logger ThreadHandler](INFO): Handler Thread ID is 435
2021-12-10T16:24:34.227Z,1639153474.227 [CBIT](DEBUG): Initialized mux pins.
2021-12-10T16:24:34.227Z,1639153474.227 [CBIT](DEBUG): Initializing the watchdog timer.
2021-12-10T16:24:34.235Z,1639153474.235 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 436
2021-12-10T16:24:34.248Z,1639153474.248 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 437
2021-12-10T16:24:34.249Z,1639153474.249 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-12-10T16:24:34.251Z,1639153474.251 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-12-10T16:24:34.251Z,1639153474.251 [CBIT](DEBUG): Initializing heartbeat.
2021-12-10T16:24:34.259Z,1639153474.259 [Onboard ThreadHandler](INFO): Handler Thread ID is 438
2021-12-10T16:24:34.289Z,1639153474.289 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 439
2021-12-10T16:24:34.299Z,1639153474.299 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 440
2021-12-10T16:24:34.300Z,1639153474.300 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-12-10T16:24:34.304Z,1639153474.304 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 442
2021-12-10T16:24:34.307Z,1639153474.307 [WetLabsBB2FL](INFO): Powering up
2021-12-10T16:24:34.308Z,1639153474.308 [WetLabsUBAT ThreadHandler](INFO): Handler Thread ID is 444
2021-12-10T16:24:34.311Z,1639153474.311 [WetLabsUBAT](INFO): Powering up
2021-12-10T16:24:34.312Z,1639153474.312 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 446
2021-12-10T16:24:34.316Z,1639153474.316 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-12-10T16:24:34.316Z,1639153474.316 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-12-10T16:24:34.316Z,1639153474.316 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-12-10T16:24:34.317Z,1639153474.317 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-12-10T16:24:34.317Z,1639153474.317 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-12-10T16:24:34.317Z,1639153474.317 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-12-10T16:24:34.317Z,1639153474.317 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-12-10T16:24:34.317Z,1639153474.317 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-12-10T16:24:34.317Z,1639153474.317 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-12-10T16:24:34.318Z,1639153474.318 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-12-10T16:24:34.318Z,1639153474.318 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-12-10T16:24:34.318Z,1639153474.318 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-12-10T16:24:34.318Z,1639153474.318 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-12-10T16:24:34.318Z,1639153474.318 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-12-10T16:24:34.319Z,1639153474.319 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-12-10T16:24:34.319Z,1639153474.319 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-12-10T16:24:34.323Z,1639153474.323 [CBIT](DEBUG): Deactivating GF circuits.
2021-12-10T16:24:34.323Z,1639153474.323 [CBIT](DEBUG): Deactivating emergency mode.
2021-12-10T16:24:34.359Z,1639153474.359 [CBIT](DEBUG): Backplane powered.
2021-12-10T16:24:34.364Z,1639153474.364 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-12-10T16:24:34.393Z,1639153474.393 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-12-10T16:24:34.438Z,1639153474.438 [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>


2021-12-10T16:24:34.439Z,1639153474.439 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-12-10T16:24:34.531Z,1639153474.531 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-12-10T16:24:34.533Z,1639153474.533 [Default:A.Wait](DEBUG): Construct Wait.
2021-12-10T16:24:34.543Z,1639153474.543 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-12-10T16:24:34.582Z,1639153474.582 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-12-10T16:24:34.585Z,1639153474.585 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-12-10T16:24:34.616Z,1639153474.616 [Default:E.Execute](DEBUG): Construct Execute.
2021-12-10T16:24:34.636Z,1639153474.636 [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="P2H">
                <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>


2021-12-10T16:24:34.640Z,1639153474.640 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,RDI_Pathfinder,DAT,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2021-12-10T16:24:34.661Z,1639153474.661 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-12-10T16:24:34.691Z,1639153474.691 [Radio_Surface](INFO): Powering up
2021-12-10T16:24:34.725Z,1639153474.725 [Power24vConverter](INFO): Powering up.
2021-12-10T16:24:34.736Z,1639153474.736 [DAT](INFO): Powering up
2021-12-10T16:24:34.736Z,1639153474.736 [DAT](DEBUG): Initializing DAT.
2021-12-10T16:24:34.807Z,1639153474.807 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-12-10T16:24:34.819Z,1639153474.819 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-12-10T16:24:34.821Z,1639153474.821 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-12-10T16:24:34.827Z,1639153474.827 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-12-10T16:24:34.828Z,1639153474.828 [MassServo](DEBUG): Initializing EZServoServo.
2021-12-10T16:24:34.835Z,1639153474.835 [MassServo](DEBUG): Initializing MassServo.
2021-12-10T16:24:34.836Z,1639153474.836 [RudderServo](DEBUG): Initializing EZServoServo.
2021-12-10T16:24:34.847Z,1639153474.847 [RudderServo](DEBUG): Initializing RudderServo.
2021-12-10T16:24:34.848Z,1639153474.848 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-12-10T16:24:34.855Z,1639153474.855 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-12-10T16:24:35.072Z,1639153475.072 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2021-12-10T16:24:35.072Z,1639153475.072 [DropWeight] Hardware Fault, FailCount= 1
2021-12-10T16:24:35.072Z,1639153475.072 [DropWeight](ERROR): Hardware Fault
2021-12-10T16:24:35.153Z,1639153475.153 [CommandExec](FAULT): Scheduling is paused
2021-12-10T16:24:35.153Z,1639153475.153 [CBIT](INFO): Critical error at 20211210T162435
2021-12-10T16:24:35.153Z,1639153475.153 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2021-12-10T16:24:35.168Z,1639153475.168 [CBIT](ERROR): Hardware Fault in component: DropWeight
2021-12-10T16:24:35.168Z,1639153475.168 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2021-12-10T16:24:35.803Z,1639153475.803 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-12-10T16:24:35.803Z,1639153475.803 [RudderServo](FAULT): Rudder failed to initialize
2021-12-10T16:24:35.803Z,1639153475.803 [RudderServo] Communications Fault, FailCount= 1
2021-12-10T16:24:35.803Z,1639153475.803 [RudderServo](ERROR): Communications Fault
2021-12-10T16:24:35.901Z,1639153475.901 [CBIT](INFO): Critical error at 20211210T162435
2021-12-10T16:24:35.904Z,1639153475.904 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-12-10T16:24:36.084Z,1639153476.084 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-12-10T16:24:36.084Z,1639153476.084 [RudderServo](INFO): Powering down
2021-12-10T16:24:36.768Z,1639153476.768 [RudderServo](DEBUG): Initializing EZServoServo.
2021-12-10T16:24:36.888Z,1639153476.888 [RudderServo](DEBUG): Initializing RudderServo.
2021-12-10T16:24:36.893Z,1639153476.893 [CBIT](INFO): Clearing failed state for component RudderServo
2021-12-10T16:24:36.893Z,1639153476.893 [RudderServo] No Fault, FailCount= 1
2021-12-10T16:24:36.919Z,1639153476.919 [WetLabsBB2FL](INFO): Powering down
2021-12-10T16:24:41.348Z,1639153481.348 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2021-12-10T16:24:43.579Z,1639153483.579 [WetLabsUBAT](INFO): Powering down
2021-12-10T16:24:48.349Z,1639153488.349 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004620
2021-12-10T16:24:48.847Z,1639153488.847 [DAT](INFO): commRate: 800
2021-12-10T16:24:50.865Z,1639153490.865 [DAT](INFO): entering command mode
2021-12-10T16:24:51.281Z,1639153491.281 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:51.673Z,1639153491.673 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:52.077Z,1639153492.077 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:52.539Z,1639153492.539 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:52.885Z,1639153492.885 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:53.289Z,1639153493.289 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:53.693Z,1639153493.693 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:54.097Z,1639153494.097 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:54.530Z,1639153494.530 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:54.905Z,1639153494.905 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:55.309Z,1639153495.309 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:55.713Z,1639153495.713 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:56.117Z,1639153496.117 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:56.600Z,1639153496.600 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:56.925Z,1639153496.925 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:57.333Z,1639153497.333 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:57.733Z,1639153497.733 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:58.137Z,1639153498.137 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:58.562Z,1639153498.562 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:58.945Z,1639153498.945 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:59.348Z,1639153499.348 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:24:59.773Z,1639153499.773 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:00.157Z,1639153500.157 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:00.603Z,1639153500.603 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:00.969Z,1639153500.969 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:01.373Z,1639153501.373 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:01.774Z,1639153501.774 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:02.178Z,1639153502.178 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:02.632Z,1639153502.632 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:02.986Z,1639153502.986 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:03.389Z,1639153503.389 [NAL9602](INFO): Powering up NAL9602
2021-12-10T16:25:03.391Z,1639153503.391 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:03.794Z,1639153503.794 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:04.198Z,1639153504.198 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:04.627Z,1639153504.627 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:05.013Z,1639153505.013 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:05.410Z,1639153505.410 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:05.813Z,1639153505.813 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:06.218Z,1639153506.218 [DAT](DEBUG): checking for command mode acknowledgment
2021-12-10T16:25:06.218Z,1639153506.218 [DAT](FAULT): failed to enter command mode
2021-12-10T16:25:06.683Z,1639153506.683 [DAT](INFO): entering command mode
2021-12-10T16:25:07.035Z,1639153507.035 [DAT](INFO): setting verbose to 3
2021-12-10T16:25:07.431Z,1639153507.431 [DAT](INFO): set verbose to 3
2021-12-10T16:25:07.432Z,1639153507.432 [DAT](INFO): setting DatVerbose to 27440
2021-12-10T16:25:07.835Z,1639153507.835 [DAT](INFO): set DatVerbose to 27440
2021-12-10T16:25:07.835Z,1639153507.835 [DAT](INFO): setting transmit power to 8
2021-12-10T16:25:08.242Z,1639153508.242 [DAT](INFO): set transmit power to 8
2021-12-10T16:25:08.243Z,1639153508.243 [DAT](INFO): setting local address to 9
2021-12-10T16:25:08.696Z,1639153508.696 [DAT](INFO): set local address to 9
2021-12-10T16:25:14.340Z,1639153514.340 [NAL9602](INFO): NAL9602 initialized
2021-12-10T16:25:26.856Z,1639153526.856 [SBIT](IMPORTANT): Beginning Startup BIT
2021-12-10T16:25:26.865Z,1639153526.865 [CBIT](IMPORTANT): Beginning ground fault scan
2021-12-10T16:25:37.818Z,1639153537.818 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.009621
CHAN A1 (24V): 0.000683
CHAN A2 (12V): -0.007235
CHAN A3 (5V): -0.002737
CHAN B0 (3.3V): -0.000093
CHAN B1 (3.15aV): -0.000142
CHAN B2 (3.15bV): 0.000102
CHAN B3 (GND): 0.002133
OPEN: 0.004921
Full Scale: +/- 1 mA
2021-12-10T16:26:20.627Z,1639153580.627 [SBIT](IMPORTANT): SBIT PASSED
2021-12-10T16:26:20.627Z,1639153580.627 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-12-10T16:26:20.628Z,1639153580.628 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;

2021-12-10T16:26:20.628Z,1639153580.628 [SBIT](IMPORTANT): CBIT.gf24Offset=143 microampere;

2021-12-10T16:26:20.631Z,1639153580.631 [SBIT](IMPORTANT): DAT.baud=115200 bit_per_second;

2021-12-10T16:26:20.631Z,1639153580.631 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2021-12-10T16:26:20.631Z,1639153580.631 [SBIT](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 0.300000 liter_per_second;

2021-12-10T16:26:20.631Z,1639153580.631 [SBIT](IMPORTANT): IBIT.batteryCapacityThreshold=24 ampere_hour;

2021-12-10T16:26:20.631Z,1639153580.631 [SBIT](IMPORTANT): IBIT.batteryVoltageThreshold=13 volt;

2021-12-10T16:26:20.631Z,1639153580.631 [SBIT](IMPORTANT): Power24vConverter.simulateHardware=0 bool;

2021-12-10T16:26:20.632Z,1639153580.632 [SBIT](IMPORTANT): RDI_Pathfinder.loadAtStartup=1 bool;

2021-12-10T16:26:20.632Z,1639153580.632 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=228.666848 cubic_centimeter;

2021-12-10T16:26:20.632Z,1639153580.632 [SBIT](IMPORTANT): VerticalControl.massDefault=8.215154 millimeter;

2021-12-10T16:26:20.990Z,1639153580.990 [MissionManager](IMPORTANT): Started mission Startup
2021-12-10T16:26:20.990Z,1639153580.990 [Startup] Running Loop=1
2021-12-10T16:26:20.990Z,1639153580.990 [Startup](DEBUG): Aggregate::initialize Startup
2021-12-10T16:26:20.990Z,1639153580.990 [Startup:A.GoToSurface] Running Loop=1
2021-12-10T16:26:20.991Z,1639153580.991 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-12-10T16:26:20.991Z,1639153580.991 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-12-10T16:26:20.992Z,1639153580.992 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-12-10T16:26:20.992Z,1639153580.992 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-12-10T16:26:20.992Z,1639153580.992 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-12-10T16:26:20.993Z,1639153580.993 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-12-10T16:26:20.995Z,1639153580.995 [Startup:StartupSatComms] Running Loop=1
2021-12-10T16:26:20.995Z,1639153580.995 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-12-10T16:26:20.996Z,1639153580.996 [Startup:StartupSatComms:A] Running Loop=1
2021-12-10T16:26:21.374Z,1639153581.374 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-12-10T16:26:52.451Z,1639153612.451 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.242767
2021-12-10T16:27:21.166Z,1639153641.166 [Startup:StartupSatComms:A](INFO): Timed out from 2021-12-10T16:26:20.0Z
2021-12-10T16:27:21.166Z,1639153641.166 [Startup:StartupSatComms:A] Stopped
2021-12-10T16:27:21.166Z,1639153641.166 [Startup:StartupSatComms:B] Running Loop=1
2021-12-10T16:27:21.575Z,1639153641.575 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-12-10T16:27:25.583Z,1639153645.583 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:27:34.521Z,1639153654.521 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-12-10T16:27:34.521Z,1639153654.521 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:27:34.549Z,1639153654.549 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:27:34.919Z,1639153654.919 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:27:34.920Z,1639153654.920 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-12-10T16:28:00.723Z,1639153680.723 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:28:21.358Z,1639153701.358 [Startup:StartupSatComms:B](INFO): Timed out from 2021-12-10T16:27:21.2Z
2021-12-10T16:28:21.358Z,1639153701.358 [Startup:StartupSatComms:B] Stopped
2021-12-10T16:28:21.358Z,1639153701.358 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-12-10T16:28:21.358Z,1639153701.358 [Startup:StartupSatComms] Stopped
2021-12-10T16:28:21.358Z,1639153701.358 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-12-10T16:28:21.359Z,1639153701.359 [Startup](INFO): Completed Startup
2021-12-10T16:28:21.359Z,1639153701.359 [MissionManager](INFO): Startup is completed.
2021-12-10T16:28:21.360Z,1639153701.360 [MissionManager](INFO): Uninitializing Mission Startup
2021-12-10T16:28:21.360Z,1639153701.360 [Startup] Stopped
2021-12-10T16:28:21.360Z,1639153701.360 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-12-10T16:28:21.360Z,1639153701.360 [Startup:A.GoToSurface] Stopped
2021-12-10T16:28:21.360Z,1639153701.360 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-12-10T16:28:21.769Z,1639153701.769 [MissionManager](IMPORTANT): Started mission Default
2021-12-10T16:28:21.770Z,1639153701.770 [Default] Running Loop=1
2021-12-10T16:28:21.770Z,1639153701.770 [Default](DEBUG): Aggregate::initialize Default
2021-12-10T16:28:21.770Z,1639153701.770 [Default:B.GoToSurface] Running Loop=1
2021-12-10T16:28:21.770Z,1639153701.770 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-12-10T16:28:21.770Z,1639153701.770 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-12-10T16:28:21.771Z,1639153701.771 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-12-10T16:28:21.771Z,1639153701.771 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-12-10T16:28:21.771Z,1639153701.771 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-12-10T16:28:21.772Z,1639153701.772 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-12-10T16:28:21.772Z,1639153701.772 [Default:A.Wait] Running Loop=1
2021-12-10T16:28:21.772Z,1639153701.772 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-12-10T16:28:35.118Z,1639153715.118 [Default:A.Wait](INFO): Done Waiting.
2021-12-10T16:28:35.118Z,1639153715.118 [Default:A.Wait] Stopped
2021-12-10T16:28:35.118Z,1639153715.118 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T16:28:35.518Z,1639153715.518 [Default:CheckIn] Running Loop=1
2021-12-10T16:28:35.518Z,1639153715.518 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T16:28:35.518Z,1639153715.518 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T16:28:35.863Z,1639153715.863 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:28:35.945Z,1639153715.945 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-12-10T16:29:11.007Z,1639153751.007 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:29:31.264Z,1639153771.264 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2021-12-10T16:29:46.151Z,1639153786.151 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:30:17.296Z,1639153817.296 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T16:30:21.299Z,1639153821.299 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:30:35.500Z,1639153835.500 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-12-10T16:30:35.500Z,1639153835.500 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:30:35.511Z,1639153835.511 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:30:35.923Z,1639153835.923 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:30:35.923Z,1639153835.923 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-12-10T16:30:56.475Z,1639153856.475 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:31:31.627Z,1639153891.627 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:32:05.572Z,1639153925.572 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-12-10T16:32:05.577Z,1639153925.577 [BPC1](INFO): Received data from all battery sticks.
2021-12-10T16:32:06.775Z,1639153926.775 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:32:41.915Z,1639153961.915 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:33:17.055Z,1639153997.055 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:33:35.673Z,1639154015.673 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-12-10T16:28:35.5Z
2021-12-10T16:33:35.674Z,1639154015.674 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T16:33:35.674Z,1639154015.674 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T16:33:36.078Z,1639154016.078 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-12-10T16:33:36.506Z,1639154016.506 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-12-10T16:33:36.506Z,1639154016.506 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:33:36.546Z,1639154016.546 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:33:36.903Z,1639154016.903 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:33:36.903Z,1639154016.903 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-12-10T16:33:52.195Z,1639154032.195 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:34:05.557Z,1639154045.557 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. 
2021-12-10T16:34:05.631Z,1639154045.631 [NAL9602](ERROR): received: 
+CSQ:0

OK
2021-12-10T16:34:27.335Z,1639154067.335 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:35:02.475Z,1639154102.475 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:35:15.015Z,1639154115.015 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003216
2021-12-10T16:35:17.476Z,1639154117.476 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-12-10T16:35:17.476Z,1639154117.476 [NAL9602] Data Fault, FailCount= 1
2021-12-10T16:35:17.476Z,1639154117.476 [NAL9602](ERROR): Data Fault
2021-12-10T16:35:17.497Z,1639154117.497 [CBIT](ERROR): Data Fault in component: NAL9602
2021-12-10T16:35:17.872Z,1639154117.872 [NAL9602](INFO): Powering down
2021-12-10T16:35:18.764Z,1639154118.764 [CBIT](INFO): Clearing failed state for component NAL9602
2021-12-10T16:35:18.764Z,1639154118.764 [NAL9602] No Fault, FailCount= 1
2021-12-10T16:35:22.471Z,1639154122.471 [DataOverHttps](INFO): Sending 144 bytes from file Logs/20211207T183600/Courier0051.lzma
2021-12-10T16:35:23.473Z,1639154123.473 [DataOverHttps](INFO): Moved sent file to Logs/20211207T183600/Courier0051.lzma.bak
2021-12-10T16:35:23.473Z,1639154123.473 [DataOverHttps](INFO): SBD MOMSN=16341049
2021-12-10T16:35:32.379Z,1639154132.379 [CommandExec](IMPORTANT): got command failComponent
2021-12-10T16:35:32.380Z,1639154132.380 [CommandExec](IMPORTANT): Failed components:
2021-12-10T16:35:32.380Z,1639154132.380 [CommandExec](IMPORTANT): DropWeight: Hardware Fault
2021-12-10T16:35:39.195Z,1639154139.195 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20211210T162424/Courier0000.lzma
2021-12-10T16:35:40.196Z,1639154140.196 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0000.lzma.bak
2021-12-10T16:35:40.197Z,1639154140.197 [DataOverHttps](INFO): SBD MOMSN=16341053
2021-12-10T16:35:48.176Z,1639154148.176 [NAL9602](INFO): Powering up NAL9602
2021-12-10T16:35:56.248Z,1639154156.248 [DataOverHttps](INFO): Sending 169 bytes from file Logs/20211210T162424/Courier0004.lzma
2021-12-10T16:35:57.248Z,1639154157.248 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0004.lzma.bak
2021-12-10T16:35:57.249Z,1639154157.249 [DataOverHttps](INFO): SBD MOMSN=16341059
2021-12-10T16:35:59.087Z,1639154159.087 [NAL9602](INFO): NAL9602 initialized
2021-12-10T16:36:37.479Z,1639154197.479 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-12-10T16:36:37.479Z,1639154197.479 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:36:37.490Z,1639154197.490 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:36:37.908Z,1639154197.908 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:36:37.908Z,1639154197.908 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-12-10T16:37:06.015Z,1639154226.015 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.247402
2021-12-10T16:37:37.155Z,1639154257.155 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:38:12.296Z,1639154292.296 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:38:47.447Z,1639154327.447 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:39:22.607Z,1639154362.607 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:39:35.243Z,1639154375.243 [CBIT](INFO): Clearing failed state for component DropWeight
2021-12-10T16:39:35.243Z,1639154375.243 [DropWeight] No Fault, FailCount= 1
2021-12-10T16:39:38.497Z,1639154378.497 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-12-10T16:39:38.498Z,1639154378.498 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:39:38.509Z,1639154378.509 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:39:38.916Z,1639154378.916 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:39:38.916Z,1639154378.916 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-12-10T16:39:57.751Z,1639154397.751 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:40:32.891Z,1639154432.891 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:41:08.043Z,1639154468.043 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:41:43.183Z,1639154503.183 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:42:05.170Z,1639154525.170 [NAL9602](INFO): SBD MO Status=2, MOMSN=17872, MT Status=2, MTMSN=0
2021-12-10T16:42:05.170Z,1639154525.170 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T16:42:18.343Z,1639154538.343 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:42:39.517Z,1639154559.517 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-12-10T16:42:39.517Z,1639154559.517 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:42:39.548Z,1639154559.548 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:42:39.965Z,1639154559.965 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:42:39.965Z,1639154559.965 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-12-10T16:42:53.499Z,1639154573.499 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:43:08.294Z,1639154588.294 [NAL9602](INFO): SBD MO Status=2, MOMSN=17872, MT Status=2, MTMSN=0
2021-12-10T16:43:08.294Z,1639154588.294 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T16:43:28.639Z,1639154608.639 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:43:31.770Z,1639154611.770 [NAL9602](INFO): SBD MO Status=1, MOMSN=17872, MT Status=0, MTMSN=0
2021-12-10T16:43:31.818Z,1639154611.818 [NAL9602](INFO): Sent 132 bytes from file Logs/20211207T183600/Express0052.lzma
2021-12-10T16:43:31.818Z,1639154611.818 [NAL9602](INFO): Packets left to send: 0
2021-12-10T16:43:44.378Z,1639154624.378 [NAL9602](INFO): SBD MO Status=2, MOMSN=17873, MT Status=2, MTMSN=0
2021-12-10T16:43:44.378Z,1639154624.378 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T16:44:03.779Z,1639154643.779 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:44:08.325Z,1639154648.325 [NAL9602](INFO): SBD MO Status=2, MOMSN=17873, MT Status=2, MTMSN=0
2021-12-10T16:44:08.325Z,1639154648.325 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T16:44:38.919Z,1639154678.919 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:44:41.522Z,1639154681.522 [NAL9602](INFO): SBD MO Status=1, MOMSN=17873, MT Status=0, MTMSN=0
2021-12-10T16:44:41.571Z,1639154681.571 [NAL9602](INFO): Sent 332 bytes from file Logs/20211210T162424/Express0001.lzma
2021-12-10T16:44:41.571Z,1639154681.571 [NAL9602](INFO): Packets left to send: 2
2021-12-10T16:44:56.134Z,1639154696.134 [NAL9602](INFO): SBD MO Status=2, MOMSN=17874, MT Status=2, MTMSN=0
2021-12-10T16:44:56.134Z,1639154696.134 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T16:45:14.059Z,1639154714.059 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:45:19.250Z,1639154719.250 [NAL9602](INFO): SBD MO Status=2, MOMSN=17874, MT Status=2, MTMSN=0
2021-12-10T16:45:19.250Z,1639154719.250 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T16:45:40.666Z,1639154740.666 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-12-10T16:45:40.666Z,1639154740.666 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:45:40.677Z,1639154740.677 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:45:41.094Z,1639154741.094 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:45:41.094Z,1639154741.094 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-12-10T16:45:49.199Z,1639154749.199 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:46:19.146Z,1639154779.146 [NAL9602](INFO): SBD MO Status=2, MOMSN=17874, MT Status=2, MTMSN=0
2021-12-10T16:46:19.146Z,1639154779.146 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T16:46:19.957Z,1639154779.957 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-12-10T16:46:19.957Z,1639154779.957 [NAL9602] Data Fault, FailCount= 2
2021-12-10T16:46:19.957Z,1639154779.957 [NAL9602](ERROR): Data Fault
2021-12-10T16:46:20.026Z,1639154780.026 [CBIT](ERROR): Data Fault in component: NAL9602
2021-12-10T16:46:20.380Z,1639154780.380 [NAL9602](INFO): Powering down
2021-12-10T16:46:21.183Z,1639154781.183 [CBIT](INFO): Clearing failed state for component NAL9602
2021-12-10T16:46:21.183Z,1639154781.183 [NAL9602] No Fault, FailCount= 2
2021-12-10T16:46:24.339Z,1639154784.339 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:46:50.653Z,1639154810.653 [NAL9602](INFO): Powering up NAL9602
2021-12-10T16:46:59.507Z,1639154819.507 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:47:01.561Z,1639154821.561 [NAL9602](INFO): NAL9602 initialized
2021-12-10T16:47:34.655Z,1639154854.655 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T16:48:07.347Z,1639154887.347 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.007947
2021-12-10T16:48:14.969Z,1639154894.969 [DataOverHttps](INFO): Sending 983 bytes from file Logs/20211210T162424/Express0001.lzma
2021-12-10T16:48:15.969Z,1639154895.969 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0001.lzma.bak
2021-12-10T16:48:15.969Z,1639154895.969 [DataOverHttps](INFO): SBD MOMSN=16341076
2021-12-10T16:48:35.375Z,1639154915.375 [DataOverHttps](INFO): Sending 188 bytes from file Logs/20211210T162424/Express0005.lzma
2021-12-10T16:48:36.376Z,1639154916.376 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0005.lzma.bak
2021-12-10T16:48:36.377Z,1639154916.377 [DataOverHttps](INFO): SBD MOMSN=16341101
2021-12-10T16:48:37.851Z,1639154917.851 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T16:48:37.851Z,1639154917.851 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T16:48:37.851Z,1639154917.851 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T16:48:41.884Z,1639154921.884 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2021-12-10T16:48:41.884Z,1639154921.884 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:48:41.908Z,1639154921.908 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:48:42.333Z,1639154922.333 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:48:42.333Z,1639154922.333 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2021-12-10T16:49:56.472Z,1639154996.472 [DataOverHttps](IMPORTANT): SBD MTMSN=20211210T164955
2021-12-10T16:50:04.119Z,1639155004.119 [DataOverHttps](INFO): Received command: failc
2021-12-10T16:50:04.141Z,1639155004.141 [CommandExec](IMPORTANT): got command failComponent
2021-12-10T16:50:04.141Z,1639155004.141 [CommandExec](IMPORTANT): Failed components:
2021-12-10T16:50:04.141Z,1639155004.141 [CommandExec](IMPORTANT): No failed Components.
2021-12-10T16:51:42.819Z,1639155102.819 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2021-12-10T16:51:42.819Z,1639155102.819 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:51:42.831Z,1639155102.831 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:51:43.282Z,1639155103.282 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:51:43.282Z,1639155103.282 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2021-12-10T16:53:38.440Z,1639155218.440 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T16:53:38.440Z,1639155218.440 [Default:CheckIn:C.Wait] Stopped
2021-12-10T16:53:38.440Z,1639155218.440 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T16:53:38.440Z,1639155218.440 [Default:CheckIn:D] Running Loop=1
2021-12-10T16:53:38.859Z,1639155218.859 [Default:CheckIn:D] Stopped
2021-12-10T16:53:38.859Z,1639155218.859 [Default:CheckIn:E] Running Loop=1
2021-12-10T16:53:39.239Z,1639155219.239 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 25.284821 min 
2021-12-10T16:53:39.239Z,1639155219.239 [Default:CheckIn:E] Stopped
2021-12-10T16:53:39.239Z,1639155219.239 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T16:53:39.239Z,1639155219.239 [Default:CheckIn] Stopped
2021-12-10T16:53:39.239Z,1639155219.239 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T16:53:39.239Z,1639155219.239 [Default:CheckIn](INFO): Running loop #2
2021-12-10T16:53:39.239Z,1639155219.239 [Default:CheckIn] Running Loop=2
2021-12-10T16:53:39.240Z,1639155219.240 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T16:53:39.240Z,1639155219.240 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T16:54:43.936Z,1639155283.936 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2021-12-10T16:54:43.936Z,1639155283.936 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:54:43.948Z,1639155283.948 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:54:44.319Z,1639155284.319 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:54:44.319Z,1639155284.319 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2021-12-10T16:57:01.267Z,1639155421.267 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2021-12-10T16:57:04.464Z,1639155424.464 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-12-10T16:57:04.464Z,1639155424.464 [NAL9602] Data Fault, FailCount= 3
2021-12-10T16:57:04.464Z,1639155424.464 [NAL9602](ERROR): Data Fault
2021-12-10T16:57:04.520Z,1639155424.520 [CBIT](ERROR): Data Fault in component: NAL9602
2021-12-10T16:57:04.878Z,1639155424.878 [NAL9602](INFO): Powering down
2021-12-10T16:57:05.700Z,1639155425.700 [CBIT](INFO): Clearing failed state for component NAL9602
2021-12-10T16:57:05.700Z,1639155425.700 [NAL9602] No Fault, FailCount= 3
2021-12-10T16:57:35.179Z,1639155455.179 [NAL9602](INFO): Powering up NAL9602
2021-12-10T16:57:44.869Z,1639155464.869 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2021-12-10T16:57:44.869Z,1639155464.869 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T16:57:44.921Z,1639155464.921 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T16:57:45.371Z,1639155465.371 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T16:57:45.371Z,1639155465.371 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2021-12-10T16:57:46.080Z,1639155466.080 [NAL9602](INFO): NAL9602 initialized
2021-12-10T16:58:39.500Z,1639155519.500 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-12-10T16:53:39.2Z
2021-12-10T16:58:39.500Z,1639155519.500 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T16:58:39.500Z,1639155519.500 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T16:58:46.778Z,1639155526.778 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211210T162424/Courier0007.lzma
2021-12-10T16:58:47.781Z,1639155527.781 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0007.lzma.bak
2021-12-10T16:58:47.781Z,1639155527.781 [DataOverHttps](INFO): SBD MOMSN=16341137
2021-12-10T16:59:04.024Z,1639155544.024 [DataOverHttps](INFO): Sending 326 bytes from file Logs/20211210T162424/Express0008.lzma
2021-12-10T16:59:05.025Z,1639155545.025 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0008.lzma.bak
2021-12-10T16:59:05.025Z,1639155545.025 [DataOverHttps](INFO): SBD MOMSN=16341139
2021-12-10T16:59:21.238Z,1639155561.238 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211210T162424/Express0011.lzma
2021-12-10T16:59:22.240Z,1639155562.240 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0011.lzma.bak
2021-12-10T16:59:22.241Z,1639155562.241 [DataOverHttps](INFO): SBD MOMSN=16341156
2021-12-10T16:59:23.513Z,1639155563.513 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T16:59:23.514Z,1639155563.514 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T16:59:23.514Z,1639155563.514 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:00:45.937Z,1639155645.937 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2021-12-10T17:00:45.938Z,1639155645.938 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T17:00:45.949Z,1639155645.949 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T17:00:46.360Z,1639155646.360 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T17:00:46.360Z,1639155646.360 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2021-12-10T17:03:46.941Z,1639155826.941 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2021-12-10T17:03:46.941Z,1639155826.941 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T17:03:46.976Z,1639155826.976 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T17:03:47.393Z,1639155827.393 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T17:03:47.393Z,1639155827.393 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2021-12-10T17:04:24.090Z,1639155864.090 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:04:24.090Z,1639155864.090 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:04:24.090Z,1639155864.090 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:04:24.090Z,1639155864.090 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:04:24.517Z,1639155864.517 [Default:CheckIn:D] Stopped
2021-12-10T17:04:24.517Z,1639155864.517 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 36.045793 min 
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn:E] Stopped
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn] Stopped
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn](INFO): Running loop #3
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn] Running Loop=3
2021-12-10T17:04:24.940Z,1639155864.940 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:04:24.941Z,1639155864.941 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:06:47.941Z,1639156007.941 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14
2021-12-10T17:06:47.941Z,1639156007.941 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T17:06:47.972Z,1639156007.972 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T17:06:48.343Z,1639156008.343 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T17:06:48.343Z,1639156008.343 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14
2021-12-10T17:07:46.888Z,1639156066.888 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-12-10T17:07:46.888Z,1639156066.888 [NAL9602] Data Fault, FailCount= 4
2021-12-10T17:07:46.888Z,1639156066.888 [NAL9602](ERROR): Data Fault
2021-12-10T17:07:46.991Z,1639156066.991 [CBIT](ERROR): Data Fault in component: NAL9602
2021-12-10T17:07:47.292Z,1639156067.292 [NAL9602](INFO): Powering down
2021-12-10T17:07:48.136Z,1639156068.136 [CBIT](INFO): Clearing failed state for component NAL9602
2021-12-10T17:07:48.136Z,1639156068.136 [NAL9602] No Fault, FailCount= 4
2021-12-10T17:08:17.596Z,1639156097.596 [NAL9602](INFO): Powering up NAL9602
2021-12-10T17:08:28.556Z,1639156108.556 [NAL9602](INFO): NAL9602 initialized
2021-12-10T17:09:25.183Z,1639156165.183 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-12-10T17:04:24.9Z
2021-12-10T17:09:25.183Z,1639156165.183 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:09:25.183Z,1639156165.183 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:09:32.314Z,1639156172.314 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211210T162424/Courier0013.lzma
2021-12-10T17:09:33.317Z,1639156173.317 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0013.lzma.bak
2021-12-10T17:09:33.317Z,1639156173.317 [DataOverHttps](INFO): SBD MOMSN=16341159
2021-12-10T17:09:48.985Z,1639156188.985 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15
2021-12-10T17:09:48.985Z,1639156188.985 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T17:09:48.996Z,1639156188.996 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T17:09:49.389Z,1639156189.389 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T17:09:49.389Z,1639156189.389 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15
2021-12-10T17:09:49.535Z,1639156189.535 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20211210T162424/Express0014.lzma
2021-12-10T17:09:50.536Z,1639156190.536 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0014.lzma.bak
2021-12-10T17:09:50.537Z,1639156190.537 [DataOverHttps](INFO): SBD MOMSN=16341164
2021-12-10T17:09:51.842Z,1639156191.842 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:09:51.842Z,1639156191.842 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:09:51.842Z,1639156191.842 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:12:50.005Z,1639156370.005 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16
2021-12-10T17:12:50.005Z,1639156370.005 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T17:12:50.021Z,1639156370.021 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T17:12:50.415Z,1639156370.415 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T17:12:50.415Z,1639156370.415 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16
2021-12-10T17:14:52.404Z,1639156492.404 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:14:52.404Z,1639156492.404 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:14:52.404Z,1639156492.404 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:14:52.404Z,1639156492.404 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:14:52.821Z,1639156492.821 [Default:CheckIn:D] Stopped
2021-12-10T17:14:52.821Z,1639156492.821 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:14:53.226Z,1639156493.226 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.517513 min 
2021-12-10T17:14:53.226Z,1639156493.226 [Default:CheckIn:E] Stopped
2021-12-10T17:14:53.226Z,1639156493.226 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:14:53.226Z,1639156493.226 [Default:CheckIn] Stopped
2021-12-10T17:14:53.226Z,1639156493.226 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:14:53.243Z,1639156493.243 [Default:CheckIn](INFO): Running loop #4
2021-12-10T17:14:53.243Z,1639156493.243 [Default:CheckIn] Running Loop=4
2021-12-10T17:14:53.243Z,1639156493.243 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:14:53.243Z,1639156493.243 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:15:50.964Z,1639156550.964 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17
2021-12-10T17:15:50.965Z,1639156550.965 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-12-10T17:15:51.021Z,1639156551.021 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-12-10T17:15:51.381Z,1639156551.381 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-12-10T17:15:51.381Z,1639156551.381 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17
2021-12-10T17:16:13.979Z,1639156573.978 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171613.00,A,3648.17728,N,12147.28104,W,0.311,0.00,101221,,,A*71
2021-12-10T17:16:13.982Z,1639156573.982 [NAL9602](INFO): GPS fix at 20211210T171613: (36.802955, -121.788017)
2021-12-10T17:16:13.994Z,1639156573.994 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:16:13.994Z,1639156573.994 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:16:28.163Z,1639156588.163 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20211210T162424/Courier0016.lzma
2021-12-10T17:16:29.165Z,1639156589.165 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0016.lzma.bak
2021-12-10T17:16:29.165Z,1639156589.165 [DataOverHttps](INFO): SBD MOMSN=16341184
2021-12-10T17:16:46.384Z,1639156606.384 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T17:16:47.655Z,1639156607.655 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20211210T162424/Express0017.lzma
2021-12-10T17:16:48.656Z,1639156608.656 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0017.lzma.bak
2021-12-10T17:16:48.657Z,1639156608.657 [DataOverHttps](INFO): SBD MOMSN=16341189
2021-12-10T17:16:50.048Z,1639156610.048 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:16:50.048Z,1639156610.048 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:16:50.048Z,1639156610.048 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:21:50.621Z,1639156910.621 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:21:50.621Z,1639156910.621 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:21:50.621Z,1639156910.621 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:21:50.621Z,1639156910.621 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:21:51.047Z,1639156911.047 [Default:CheckIn:D] Stopped
2021-12-10T17:21:51.047Z,1639156911.047 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:21:51.428Z,1639156911.428 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.487960 min 
2021-12-10T17:21:51.428Z,1639156911.428 [Default:CheckIn:E] Stopped
2021-12-10T17:21:51.428Z,1639156911.428 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:21:51.428Z,1639156911.428 [Default:CheckIn] Stopped
2021-12-10T17:21:51.428Z,1639156911.428 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:21:51.428Z,1639156911.428 [Default:CheckIn](INFO): Running loop #5
2021-12-10T17:21:51.428Z,1639156911.428 [Default:CheckIn] Running Loop=5
2021-12-10T17:21:51.429Z,1639156911.429 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:21:51.429Z,1639156911.429 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:21:53.442Z,1639156913.442 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172152.00,A,3648.15717,N,12147.27680,W,0.875,0.00,101221,,,A*73
2021-12-10T17:21:53.444Z,1639156913.444 [NAL9602](INFO): GPS fix at 20211210T172152: (36.802619, -121.787947)
2021-12-10T17:21:53.464Z,1639156913.464 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:21:53.464Z,1639156913.464 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:22:01.658Z,1639156921.658 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20211210T162424/Courier0019.lzma
2021-12-10T17:22:02.661Z,1639156922.661 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0019.lzma.bak
2021-12-10T17:22:02.661Z,1639156922.661 [DataOverHttps](INFO): SBD MOMSN=16341221
2021-12-10T17:22:20.647Z,1639156940.647 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20211210T162424/Express0020.lzma
2021-12-10T17:22:21.649Z,1639156941.649 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0020.lzma.bak
2021-12-10T17:22:21.649Z,1639156941.649 [DataOverHttps](INFO): SBD MOMSN=16341228
2021-12-10T17:22:22.949Z,1639156942.949 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:22:22.949Z,1639156942.949 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:22:22.949Z,1639156942.949 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:26:55.259Z,1639157215.259 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T17:27:23.561Z,1639157243.561 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:27:23.561Z,1639157243.561 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:27:23.561Z,1639157243.561 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:27:23.561Z,1639157243.561 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:27:23.991Z,1639157243.991 [Default:CheckIn:D] Stopped
2021-12-10T17:27:23.991Z,1639157243.991 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.036975 min 
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn:E] Stopped
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn] Stopped
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn](INFO): Running loop #6
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn] Running Loop=6
2021-12-10T17:27:24.352Z,1639157244.352 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:27:24.353Z,1639157244.353 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:27:26.364Z,1639157246.364 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172725.00,A,3648.16603,N,12147.28384,W,0.175,224.40,101221,,,A*75
2021-12-10T17:27:26.367Z,1639157246.367 [NAL9602](INFO): GPS fix at 20211210T172725: (36.802767, -121.788064)
2021-12-10T17:27:26.379Z,1639157246.379 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:27:26.379Z,1639157246.379 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:27:33.862Z,1639157253.862 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0022.lzma
2021-12-10T17:27:34.864Z,1639157254.864 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0022.lzma.bak
2021-12-10T17:27:34.865Z,1639157254.865 [DataOverHttps](INFO): SBD MOMSN=16341234
2021-12-10T17:27:51.539Z,1639157271.539 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20211210T162424/Express0023.lzma
2021-12-10T17:27:52.541Z,1639157272.541 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0023.lzma.bak
2021-12-10T17:27:52.541Z,1639157272.541 [DataOverHttps](INFO): SBD MOMSN=16341237
2021-12-10T17:27:53.853Z,1639157273.853 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:27:53.853Z,1639157273.853 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:27:53.853Z,1639157273.853 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:27:58.284Z,1639157278.284 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T17:32:54.481Z,1639157574.481 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:32:54.481Z,1639157574.481 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:32:54.482Z,1639157574.482 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:32:54.482Z,1639157574.482 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:32:54.889Z,1639157574.889 [Default:CheckIn:D] Stopped
2021-12-10T17:32:54.889Z,1639157574.889 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:32:55.268Z,1639157575.268 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 64.551990 min 
2021-12-10T17:32:55.268Z,1639157575.268 [Default:CheckIn:E] Stopped
2021-12-10T17:32:55.269Z,1639157575.269 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:32:55.269Z,1639157575.269 [Default:CheckIn] Stopped
2021-12-10T17:32:55.269Z,1639157575.269 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:32:55.269Z,1639157575.269 [Default:CheckIn](INFO): Running loop #7
2021-12-10T17:32:55.269Z,1639157575.269 [Default:CheckIn] Running Loop=7
2021-12-10T17:32:55.269Z,1639157575.269 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:32:55.269Z,1639157575.269 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:32:57.275Z,1639157577.275 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173256.00,A,3648.14808,N,12147.28330,W,0.389,322.65,101221,,,A*7C
2021-12-10T17:32:57.277Z,1639157577.277 [NAL9602](INFO): GPS fix at 20211210T173256: (36.802468, -121.788055)
2021-12-10T17:32:57.295Z,1639157577.295 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:32:57.295Z,1639157577.295 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:33:05.026Z,1639157585.026 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20211210T162424/Courier0025.lzma
2021-12-10T17:33:06.028Z,1639157586.028 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0025.lzma.bak
2021-12-10T17:33:06.029Z,1639157586.029 [DataOverHttps](INFO): SBD MOMSN=16341253
2021-12-10T17:33:22.865Z,1639157602.865 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20211210T162424/Express0026.lzma
2021-12-10T17:33:23.865Z,1639157603.865 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0026.lzma.bak
2021-12-10T17:33:23.865Z,1639157603.865 [DataOverHttps](INFO): SBD MOMSN=16341257
2021-12-10T17:33:25.195Z,1639157605.195 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:33:25.195Z,1639157605.195 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:33:25.195Z,1639157605.195 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:33:28.028Z,1639157608.028 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-12-10T17:33:28.111Z,1639157608.111 [NAL9602](ERROR): received: 
+CSQ:0

OK874, 2, 0, 0, 0

OK
2021-12-10T17:37:59.512Z,1639157879.512 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T17:38:25.809Z,1639157905.809 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:38:25.809Z,1639157905.809 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:38:25.809Z,1639157905.809 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:38:25.809Z,1639157905.809 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:38:26.204Z,1639157906.204 [Default:CheckIn:D] Stopped
2021-12-10T17:38:26.204Z,1639157906.204 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:38:26.633Z,1639157906.633 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.073910 min 
2021-12-10T17:38:26.633Z,1639157906.633 [Default:CheckIn:E] Stopped
2021-12-10T17:38:26.633Z,1639157906.633 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:38:26.633Z,1639157906.633 [Default:CheckIn] Stopped
2021-12-10T17:38:26.634Z,1639157906.634 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:38:26.634Z,1639157906.634 [Default:CheckIn](INFO): Running loop #8
2021-12-10T17:38:26.634Z,1639157906.634 [Default:CheckIn] Running Loop=8
2021-12-10T17:38:26.634Z,1639157906.634 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:38:26.634Z,1639157906.634 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:38:28.602Z,1639157908.602 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173827.00,A,3648.15082,N,12147.26670,W,6.356,137.59,101221,,,A*79
2021-12-10T17:38:28.604Z,1639157908.604 [NAL9602](INFO): GPS fix at 20211210T173827: (36.802514, -121.787778)
2021-12-10T17:38:28.660Z,1639157908.660 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:38:28.660Z,1639157908.660 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:38:36.746Z,1639157916.746 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0028.lzma
2021-12-10T17:38:37.749Z,1639157917.749 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0028.lzma.bak
2021-12-10T17:38:37.749Z,1639157917.749 [DataOverHttps](INFO): SBD MOMSN=16341288
2021-12-10T17:38:54.503Z,1639157934.503 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20211210T162424/Express0029.lzma
2021-12-10T17:38:55.505Z,1639157935.505 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0029.lzma.bak
2021-12-10T17:38:55.505Z,1639157935.505 [DataOverHttps](INFO): SBD MOMSN=16341293
2021-12-10T17:38:56.569Z,1639157936.569 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:38:56.569Z,1639157936.569 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:38:56.569Z,1639157936.569 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:39:01.596Z,1639157941.596 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T17:39:35.299Z,1639157975.299 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-12-10T17:39:35.303Z,1639157975.303 [BPC1](INFO): Received data from all battery sticks.
2021-12-10T17:43:57.091Z,1639158237.091 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:43:57.092Z,1639158237.092 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:43:57.092Z,1639158237.092 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:43:57.092Z,1639158237.092 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:43:57.536Z,1639158237.536 [Default:CheckIn:D] Stopped
2021-12-10T17:43:57.536Z,1639158237.536 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:43:57.901Z,1639158237.901 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.596102 min 
2021-12-10T17:43:57.901Z,1639158237.901 [Default:CheckIn:E] Stopped
2021-12-10T17:43:57.901Z,1639158237.901 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:43:57.901Z,1639158237.901 [Default:CheckIn] Stopped
2021-12-10T17:43:57.901Z,1639158237.901 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:43:57.901Z,1639158237.901 [Default:CheckIn](INFO): Running loop #9
2021-12-10T17:43:57.901Z,1639158237.901 [Default:CheckIn] Running Loop=9
2021-12-10T17:43:57.902Z,1639158237.902 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:43:57.902Z,1639158237.902 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:43:59.914Z,1639158239.914 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174359.00,A,3648.16705,N,12147.28910,W,0.855,176.99,101221,,,A*77
2021-12-10T17:43:59.917Z,1639158239.917 [NAL9602](INFO): GPS fix at 20211210T174359: (36.802784, -121.788152)
2021-12-10T17:43:59.957Z,1639158239.957 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:43:59.957Z,1639158239.957 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:44:08.307Z,1639158248.307 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20211210T162424/Courier0031.lzma
2021-12-10T17:44:09.308Z,1639158249.308 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0031.lzma.bak
2021-12-10T17:44:09.309Z,1639158249.309 [DataOverHttps](INFO): SBD MOMSN=16341356
2021-12-10T17:44:29.579Z,1639158269.579 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20211210T162424/Express0032.lzma
2021-12-10T17:44:30.581Z,1639158270.581 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0032.lzma.bak
2021-12-10T17:44:30.581Z,1639158270.581 [DataOverHttps](INFO): SBD MOMSN=16341361
2021-12-10T17:44:30.681Z,1639158270.681 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-12-10T17:44:30.755Z,1639158270.755 [NAL9602](ERROR): received: 
+CSQ:0

OK874, 2, 0, 0, 0

OK
2021-12-10T17:44:31.933Z,1639158271.933 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:44:31.934Z,1639158271.934 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:44:31.934Z,1639158271.934 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:49:02.640Z,1639158542.640 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T17:49:32.582Z,1639158572.582 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:49:32.582Z,1639158572.582 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:49:32.583Z,1639158572.583 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:49:32.583Z,1639158572.583 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:49:32.957Z,1639158572.957 [Default:CheckIn:D] Stopped
2021-12-10T17:49:32.957Z,1639158572.957 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:49:33.352Z,1639158573.352 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T17:49:33.424Z,1639158573.424 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.186450 min 
2021-12-10T17:49:33.424Z,1639158573.424 [Default:CheckIn:E] Stopped
2021-12-10T17:49:33.424Z,1639158573.424 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:49:33.424Z,1639158573.424 [Default:CheckIn] Stopped
2021-12-10T17:49:33.424Z,1639158573.424 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:49:33.424Z,1639158573.424 [Default:CheckIn](INFO): Running loop #10
2021-12-10T17:49:33.424Z,1639158573.424 [Default:CheckIn] Running Loop=10
2021-12-10T17:49:33.425Z,1639158573.425 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:49:33.425Z,1639158573.425 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:49:35.368Z,1639158575.368 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174934.00,A,3648.16201,N,12147.28182,W,0.389,176.99,101221,,,A*7E
2021-12-10T17:49:35.371Z,1639158575.371 [NAL9602](INFO): GPS fix at 20211210T174934: (36.802700, -121.788030)
2021-12-10T17:49:35.403Z,1639158575.403 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:49:35.404Z,1639158575.404 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:49:43.086Z,1639158583.086 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0034.lzma
2021-12-10T17:49:44.089Z,1639158584.089 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0034.lzma.bak
2021-12-10T17:49:44.089Z,1639158584.089 [DataOverHttps](INFO): SBD MOMSN=16341435
2021-12-10T17:49:51.943Z,1639158591.943 [NAL9602](INFO): SBD MO Status=0, MOMSN=17874, MT Status=0, MTMSN=0
2021-12-10T17:49:51.943Z,1639158591.943 [NAL9602](INFO): No messages in MT queue
2021-12-10T17:50:00.887Z,1639158600.887 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20211210T162424/Express0035.lzma
2021-12-10T17:50:01.889Z,1639158601.889 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0035.lzma.bak
2021-12-10T17:50:01.889Z,1639158601.889 [DataOverHttps](INFO): SBD MOMSN=16341472
2021-12-10T17:50:03.257Z,1639158603.257 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:50:03.257Z,1639158603.257 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:50:03.257Z,1639158603.257 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:50:22.632Z,1639158622.632 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T17:53:12.735Z,1639158792.735 [RDI_Pathfinder](ERROR): only read -1 of 1 data item for water mass range.
2021-12-10T17:55:03.871Z,1639158903.871 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T17:55:03.871Z,1639158903.871 [Default:CheckIn:C.Wait] Stopped
2021-12-10T17:55:03.871Z,1639158903.871 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T17:55:03.871Z,1639158903.871 [Default:CheckIn:D] Running Loop=1
2021-12-10T17:55:04.262Z,1639158904.262 [Default:CheckIn:D] Stopped
2021-12-10T17:55:04.262Z,1639158904.262 [Default:CheckIn:E] Running Loop=1
2021-12-10T17:55:04.640Z,1639158904.640 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.708203 min 
2021-12-10T17:55:04.640Z,1639158904.640 [Default:CheckIn:E] Stopped
2021-12-10T17:55:04.640Z,1639158904.640 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T17:55:04.640Z,1639158904.640 [Default:CheckIn] Stopped
2021-12-10T17:55:04.640Z,1639158904.640 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T17:55:04.641Z,1639158904.641 [Default:CheckIn](INFO): Running loop #11
2021-12-10T17:55:04.641Z,1639158904.641 [Default:CheckIn] Running Loop=11
2021-12-10T17:55:04.641Z,1639158904.641 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T17:55:04.641Z,1639158904.641 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T17:55:06.650Z,1639158906.650 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175505.00,A,3648.16148,N,12147.28346,W,0.525,0.00,101221,,,A*75
2021-12-10T17:55:06.661Z,1639158906.661 [NAL9602](INFO): GPS fix at 20211210T175505: (36.802691, -121.788058)
2021-12-10T17:55:06.674Z,1639158906.674 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T17:55:06.674Z,1639158906.674 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T17:55:14.374Z,1639158914.374 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0037.lzma
2021-12-10T17:55:15.376Z,1639158915.376 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0037.lzma.bak
2021-12-10T17:55:15.377Z,1639158915.377 [DataOverHttps](INFO): SBD MOMSN=16341619
2021-12-10T17:55:32.167Z,1639158932.167 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20211210T162424/Express0038.lzma
2021-12-10T17:55:33.169Z,1639158933.169 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0038.lzma.bak
2021-12-10T17:55:33.169Z,1639158933.169 [DataOverHttps](INFO): SBD MOMSN=16341625
2021-12-10T17:55:34.548Z,1639158934.548 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T17:55:34.548Z,1639158934.548 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T17:55:34.548Z,1639158934.548 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T17:58:04.220Z,1639159084.220 [DataOverHttps](IMPORTANT): SBD MTMSN=20211210T175803
2021-12-10T17:58:12.134Z,1639159092.134 [DataOverHttps](INFO): Received command: stop
2021-12-10T17:58:12.136Z,1639159092.136 [CommandExec](IMPORTANT): got command stop
2021-12-10T17:58:12.136Z,1639159092.136 [CommandExec](IMPORTANT): Scheduling is paused
2021-12-10T17:58:50.869Z,1639159130.869 [NAL9602](INFO): SBD MO Status=2, MOMSN=17875, MT Status=2, MTMSN=0
2021-12-10T17:58:50.869Z,1639159130.869 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:00:24.607Z,1639159224.607 [NAL9602](INFO): SBD MO Status=2, MOMSN=17875, MT Status=2, MTMSN=0
2021-12-10T18:00:24.607Z,1639159224.607 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:00:25.020Z,1639159225.020 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T18:00:35.167Z,1639159235.167 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T18:00:35.167Z,1639159235.167 [Default:CheckIn:C.Wait] Stopped
2021-12-10T18:00:35.167Z,1639159235.167 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T18:00:35.167Z,1639159235.167 [Default:CheckIn:D] Running Loop=1
2021-12-10T18:00:35.532Z,1639159235.532 [Default:CheckIn:D] Stopped
2021-12-10T18:00:35.532Z,1639159235.532 [Default:CheckIn:E] Running Loop=1
2021-12-10T18:00:35.947Z,1639159235.947 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.229362 min 
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn:E] Stopped
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn] Stopped
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn](INFO): Running loop #12
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn] Running Loop=12
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T18:00:35.948Z,1639159235.948 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T18:00:37.938Z,1639159237.938 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180037.00,A,3648.16348,N,12147.28180,W,0.369,0.00,101221,,,A*7F
2021-12-10T18:00:37.940Z,1639159237.940 [NAL9602](INFO): GPS fix at 20211210T180037: (36.802725, -121.788030)
2021-12-10T18:00:37.957Z,1639159237.957 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T18:00:37.957Z,1639159237.957 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T18:00:46.114Z,1639159246.114 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0040.lzma
2021-12-10T18:00:47.117Z,1639159247.117 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0040.lzma.bak
2021-12-10T18:00:47.117Z,1639159247.117 [DataOverHttps](INFO): SBD MOMSN=16341678
2021-12-10T18:01:03.850Z,1639159263.850 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211210T162424/Courier0043.lzma
2021-12-10T18:01:04.852Z,1639159264.852 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0043.lzma.bak
2021-12-10T18:01:04.853Z,1639159264.853 [DataOverHttps](INFO): SBD MOMSN=16341683
2021-12-10T18:01:10.256Z,1639159270.256 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T18:01:21.531Z,1639159281.531 [DataOverHttps](INFO): Sending 274 bytes from file Logs/20211210T162424/Express0041.lzma
2021-12-10T18:01:22.534Z,1639159282.534 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0041.lzma.bak
2021-12-10T18:01:22.534Z,1639159282.534 [DataOverHttps](IMPORTANT): SBD MOMSN=16341687, MTMSN=20211210T180121
2021-12-10T18:01:30.591Z,1639159290.591 [DataOverHttps](INFO): Received command: load Maintenance/tank_ballast_and_trim.xml;set ballast_and_trim.MissionTimeout 20 min;run
2021-12-10T18:01:30.662Z,1639159290.662 [CommandExec](IMPORTANT): got command load ./Missions/Maintenance/tank_ballast_and_trim.xml
2021-12-10T18:01:30.663Z,1639159290.663 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tank_ballast_and_trim.xml
2021-12-10T18:01:30.753Z,1639159290.753 [MissionManager](INFO): DefineArg ballast_and_trim.MissionTimeout = 120.000000 min
2021-12-10T18:01:30.756Z,1639159290.756 [MissionManager](INFO): DefineArg ballast_and_trim.SkipComms = 0 bool
2021-12-10T18:01:30.759Z,1639159290.759 [MissionManager](INFO): DefineArg ballast_and_trim.Depth1 = 7.000000 m
2021-12-10T18:01:30.763Z,1639159290.763 [MissionManager](INFO): DefineArg ballast_and_trim.Depth2 = nan m
2021-12-10T18:01:30.766Z,1639159290.766 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 0.100000 m
2021-12-10T18:01:30.769Z,1639159290.769 [MissionManager](INFO): DefineArg ballast_and_trim.SurfaceThreshold = 2.500000 m
2021-12-10T18:01:30.774Z,1639159290.774 [MissionManager](INFO): DefineArg ballast_and_trim.MaxWaitOnSurface = 20.000000 min
2021-12-10T18:01:30.778Z,1639159290.778 [MissionManager](INFO): DefineArg ballast_and_trim.SettleTime = 10.000000 min
2021-12-10T18:01:30.801Z,1639159290.801 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationTimeout = 45.000000 min
2021-12-10T18:01:30.805Z,1639159290.805 [MissionManager](INFO): DefineArg ballast_and_trim.MinEstimationTime = 10.000000 min
2021-12-10T18:01:30.820Z,1639159290.820 [MissionManager](INFO): DefineArg ballast_and_trim.MassEstimationErrorBound = 0.250000 mm
2021-12-10T18:01:30.829Z,1639159290.829 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyEstimationErrorBound = 15.000000 cc
2021-12-10T18:01:30.837Z,1639159290.837 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationConfidence = 99.900000 %
2021-12-10T18:01:30.876Z,1639159290.876 [MissionManager](INFO): DefineArg ballast_and_trim.WaitToFloat = 5.000000 min
2021-12-10T18:01:30.877Z,1639159290.877 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2021-12-10T18:01:31.461Z,1639159291.461 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectChlActive = 0 bool
2021-12-10T18:01:31.464Z,1639159291.464 [MissionManager](INFO): DefineArg ballast_and_trim:Science.TimeWindowPeakReport = nan min
2021-12-10T18:01:31.466Z,1639159291.466 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestChlPeakReportActive = 0 bool
2021-12-10T18:01:31.469Z,1639159291.469 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestSaltPeakReportActive = 0 bool
2021-12-10T18:01:31.472Z,1639159291.472 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestOilPeakReportActive = 0 bool
2021-12-10T18:01:31.474Z,1639159291.474 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PatchTracking = 0 bool
2021-12-10T18:01:31.477Z,1639159291.477 [MissionManager](INFO): DefineArg ballast_and_trim:Science.DetectTrough = 0 bool
2021-12-10T18:01:31.480Z,1639159291.480 [MissionManager](INFO): DefineArg ballast_and_trim:Science.FilterWidthHorizontal = 3.000000 count
2021-12-10T18:01:31.483Z,1639159291.483 [MissionManager](INFO): DefineArg ballast_and_trim:Science.NumProfilesSlidingwindow = 100.000000 count
2021-12-10T18:01:31.527Z,1639159291.527 [MissionManager](INFO): DefineArg ballast_and_trim:Science.OffPeakFractionHorizontal = 80.000000 %
2021-12-10T18:01:31.530Z,1639159291.530 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectNO3Active = 0 bool
2021-12-10T18:01:31.533Z,1639159291.533 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectOilActive = 0 bool
2021-12-10T18:01:31.551Z,1639159291.551 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectFDOMActive = 0 bool
2021-12-10T18:01:31.555Z,1639159291.555 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectSalinityActive = 0 bool
2021-12-10T18:01:31.558Z,1639159291.558 [MissionManager](INFO): DefineArg ballast_and_trim:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2021-12-10T18:01:31.562Z,1639159291.562 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledAanderaaO2 = 0.000000 bool
2021-12-10T18:01:31.565Z,1639159291.565 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledNeilBrown = 0.000000 bool
2021-12-10T18:01:31.569Z,1639159291.569 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledSeabird = 1.000000 bool
2021-12-10T18:01:31.640Z,1639159291.640 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsBB2FL = 1.000000 bool
2021-12-10T18:01:31.644Z,1639159291.644 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool
2021-12-10T18:01:31.703Z,1639159291.703 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsUBAT = 1.000000 bool
2021-12-10T18:01:31.708Z,1639159291.708 [MissionManager](INFO): DefineArg ballast_and_trim:Science.LowPassWindowLength = 20.000000 count
2021-12-10T18:01:31.723Z,1639159291.723 [MissionManager](INFO): DefineArg ballast_and_trim:Science.MedianFilterLen = 5.000000 count
2021-12-10T18:01:31.727Z,1639159291.727 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakShallowBound = nan m
2021-12-10T18:01:31.730Z,1639159291.730 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDeepBound = nan m
2021-12-10T18:01:31.745Z,1639159291.745 [MissionManager](INFO): DefineArg ballast_and_trim:Science.DepChangeThreshForAttitudeFlip = 2.000000 m
2021-12-10T18:01:31.761Z,1639159291.761 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChl = 0.000000 ug/l
2021-12-10T18:01:31.775Z,1639159291.775 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlDepth = 0.000000 m
2021-12-10T18:01:31.795Z,1639159291.795 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlTemperature = 0.000000 degC
2021-12-10T18:01:31.798Z,1639159291.798 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLatitude = nan arcdeg
2021-12-10T18:01:31.839Z,1639159291.839 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLongitude = nan arcdeg
2021-12-10T18:01:31.842Z,1639159291.842 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3 = 0.000000 umol/l
2021-12-10T18:01:31.862Z,1639159291.862 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Depth = 0.000000 m
2021-12-10T18:01:31.901Z,1639159291.901 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Latitude = nan arcdeg
2021-12-10T18:01:31.921Z,1639159291.921 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Longitude = nan arcdeg
2021-12-10T18:01:31.941Z,1639159291.941 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOil = 0.000000 kg/m3
2021-12-10T18:01:31.948Z,1639159291.948 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilDepth = 0.000000 m
2021-12-10T18:01:31.964Z,1639159291.964 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLatitude = nan arcdeg
2021-12-10T18:01:31.973Z,1639159291.973 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLongitude = nan arcdeg
2021-12-10T18:01:32.012Z,1639159292.012 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOM = 0.000000 ppb
2021-12-10T18:01:32.024Z,1639159292.024 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMDepth = 0.000000 m
2021-12-10T18:01:32.043Z,1639159292.043 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMTemperature = nan degC
2021-12-10T18:01:32.053Z,1639159292.053 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLatitude = nan arcdeg
2021-12-10T18:01:32.084Z,1639159292.084 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLongitude = nan arcdeg
2021-12-10T18:01:32.104Z,1639159292.104 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchFDOMDistance = nan m
2021-12-10T18:01:32.123Z,1639159292.123 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSalt = 0.000000 psu
2021-12-10T18:01:32.145Z,1639159292.145 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltDepth = 0.000000 m
2021-12-10T18:01:32.183Z,1639159292.183 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltTemperature = 0.000000 degC
2021-12-10T18:01:32.198Z,1639159292.198 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltLatitude = nan arcdeg
2021-12-10T18:01:32.202Z,1639159292.202 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltLongitude = nan arcdeg
2021-12-10T18:01:32.213Z,1639159292.213 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChl = 0.000000 ug/l
2021-12-10T18:01:32.240Z,1639159292.240 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDepth = 0.000000 m
2021-12-10T18:01:32.256Z,1639159292.256 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLatitude = nan arcdeg
2021-12-10T18:01:32.264Z,1639159292.264 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLongitude = nan arcdeg
2021-12-10T18:01:32.289Z,1639159292.289 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDistance = nan m
2021-12-10T18:01:32.301Z,1639159292.301 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSalt = 0.000000 psu
2021-12-10T18:01:32.313Z,1639159292.313 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltDepth = 0.000000 m
2021-12-10T18:01:32.316Z,1639159292.316 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltLatitude = nan arcdeg
2021-12-10T18:01:32.343Z,1639159292.343 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltLongitude = nan arcdeg
2021-12-10T18:01:32.346Z,1639159292.346 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltDistance = nan m
2021-12-10T18:01:32.349Z,1639159292.349 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOil = 0.000000 psu
2021-12-10T18:01:32.378Z,1639159292.378 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilDepth = 0.000000 m
2021-12-10T18:01:32.381Z,1639159292.381 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilLatitude = nan arcdeg
2021-12-10T18:01:32.385Z,1639159292.385 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilLongitude = nan arcdeg
2021-12-10T18:01:32.405Z,1639159292.405 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilDistance = nan m
2021-12-10T18:01:32.503Z,1639159292.503 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2021-12-10T18:01:32.543Z,1639159292.543 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2021-12-10T18:01:32.580Z,1639159292.580 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2021-12-10T18:01:32.607Z,1639159292.607 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2021-12-10T18:01:32.630Z,1639159292.630 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2021-12-10T18:01:32.659Z,1639159292.659 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2021-12-10T18:01:32.694Z,1639159292.694 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2021-12-10T18:01:32.706Z,1639159292.706 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2021-12-10T18:01:32.729Z,1639159292.729 [MissionManager](INFO): Inserting Stack: Missions/Insert/BallastAndTrim.xml
2021-12-10T18:01:33.049Z,1639159293.049 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepth = 25.000000 m
2021-12-10T18:01:33.063Z,1639159293.063 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSpeed = 0.000000 m/s
2021-12-10T18:01:33.066Z,1639159293.066 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthRate = 0.400000 m/s
2021-12-10T18:01:33.076Z,1639159293.076 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachPitchLimit = 20.000000 arcdeg
2021-12-10T18:01:33.086Z,1639159293.086 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSettleTimePreDive = 0.000000 min
2021-12-10T18:01:33.102Z,1639159293.102 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = 20.000000 min
2021-12-10T18:01:33.105Z,1639159293.105 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = 10.000000 min
2021-12-10T18:01:33.109Z,1639159293.109 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = 45.000000 min
2021-12-10T18:01:33.120Z,1639159293.120 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = 10.000000 min
2021-12-10T18:01:33.127Z,1639159293.127 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = 0.250000 mm
2021-12-10T18:01:33.135Z,1639159293.135 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = 15.000000 cc
2021-12-10T18:01:33.138Z,1639159293.138 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = 99.900000 %
2021-12-10T18:01:33.146Z,1639159293.146 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = 1.000000 m
2021-12-10T18:01:33.153Z,1639159293.153 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertMassDeadband = 0.250000 mm
2021-12-10T18:01:33.212Z,1639159293.212 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Construct.
2021-12-10T18:01:33.236Z,1639159293.236 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Construct Buoyancy.
2021-12-10T18:01:33.244Z,1639159293.244 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Construct.
2021-12-10T18:01:33.266Z,1639159293.266 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait](DEBUG): Construct Wait.
2021-12-10T18:01:33.306Z,1639159293.306 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Construct.
2021-12-10T18:01:33.317Z,1639159293.317 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Construct.
2021-12-10T18:01:33.346Z,1639159293.346 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2021-12-10T18:01:33.358Z,1639159293.358 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Construct.
2021-12-10T18:01:33.365Z,1639159293.365 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch](DEBUG): Construct.
2021-12-10T18:01:33.385Z,1639159293.385 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Construct Wait.
2021-12-10T18:01:33.397Z,1639159293.397 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](DEBUG): Construct BallastAndTrim.
2021-12-10T18:01:33.440Z,1639159293.440 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = reader:ballast_and_trim.DepthDeadband
2021-12-10T18:01:33.442Z,1639159293.442 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = reader:ballast_and_trim.MaxWaitOnSurface
2021-12-10T18:01:33.448Z,1639159293.448 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = reader:ballast_and_trim.SettleTime
2021-12-10T18:01:33.450Z,1639159293.450 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = reader:ballast_and_trim.EstimationTimeout
2021-12-10T18:01:33.456Z,1639159293.456 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = reader:ballast_and_trim.MinEstimationTime
2021-12-10T18:01:33.458Z,1639159293.458 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = reader:ballast_and_trim.MassEstimationErrorBound
2021-12-10T18:01:33.464Z,1639159293.464 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = reader:ballast_and_trim.BuoyEstimationErrorBound
2021-12-10T18:01:33.466Z,1639159293.466 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = reader:ballast_and_trim.EstimationConfidence
2021-12-10T18:01:33.511Z,1639159293.511 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Construct Buoyancy.
2021-12-10T18:01:33.537Z,1639159293.537 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Construct Wait.
2021-12-10T18:01:33.643Z,1639159293.643 [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="ballast_and_trim">

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:minute/><Value>120</Value></DefineArg>

    <DefineArg Name="SkipComms"><Description>
        Skip communications at start of mission.
    </Description><False/></DefineArg>

    <DefineArg Name="Depth1"><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="Depth2"><Units:meter/><Value>NaN</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Description>
        How much vertical drift from the specified depth is allowed durnig the
        mission.
    </Description><Units:meter/><Value>0.1</Value></DefineArg>

    <DefineArg Name="SurfaceThreshold"><Description>
        Surface threshold depth.
    </Description><Units:meter/><Value>2.5</Value></DefineArg>

    <DefineArg Name="MaxWaitOnSurface"><Description>
        Maximum wait time for the vehicle to go under the surface (i.e., reach
        the surface threshold depth).
    </Description><Units:minute/><Value>20</Value></DefineArg>

    <DefineArg Name="SettleTime"><Description>
        How long to wait after reaching target depth before starting ballast and
        trim.
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="EstimationTimeout"><Description>
        Timeout for ballast and trim estimation.
    </Description><Units:minute/><Value>45</Value></DefineArg>

    <DefineArg Name="MinEstimationTime"><Description>
        Minimum time to run ballast and trim estimation before determining
        convergence (must be shorter than timeout).
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="MassEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:millimeter/><Value>0.25</Value></DefineArg>

    <DefineArg Name="BuoyEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:cubic_centimeter/><Value>15</Value></DefineArg>

    <DefineArg Name="EstimationConfidence"><Description>
        Confidence level that the estimator has reached the desired error range
        (larger values take longer to converge).
    </Description><Units:percent/><Value>99.9</Value></DefineArg>

    <DefineArg Name="WaitToFloat"><Units:minute/><Value>5</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Insert Filename="Insert/Science.xml"/>

    <Aggregate Id="RunBallastAndTrim">

        <Sequence/>

        <Insert Filename="Insert/BallastAndTrim.xml">
            <RedefineArg Name="InsertDepthDeadband"><Arg Name="DepthDeadband"/></RedefineArg>
            <RedefineArg Name="InsertApproachDepthTimeout"><Arg Name="MaxWaitOnSurface"/></RedefineArg>
            <RedefineArg Name="InsertSettleTime"><Arg Name="SettleTime"/></RedefineArg>
            <RedefineArg Name="EstTimeout"><Arg Name="EstimationTimeout"/></RedefineArg>
            <RedefineArg Name="MinEstTime"><Arg Name="MinEstimationTime"/></RedefineArg>
            <RedefineArg Name="MassEstErrorBound"><Arg Name="MassEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="BuoyEstErrorBound"><Arg Name="BuoyEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="EstConfidence"><Arg Name="EstimationConfidence"/></RedefineArg>
        </Insert>

        <Aggregate Id="Depth1">

            <Sequence/>

            <Break>
                <IsNaN><Arg Name="Depth1"/>
                </IsNaN>
            </Break>

            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>

            <Call RefId="BallastAndTrim"/>

        </Aggregate>

        <Aggregate Id="Depth2">

            <Sequence/>

            <Break>
                <IsNaN><Arg Name="Depth2"/>
                </IsNaN>
            </Break>

            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>

            <Call RefId="BallastAndTrim"/>

        </Aggregate>

    </Aggregate>

    <Aggregate Id="Float_Up">

        <Description>
            Float to surface instead of driving.
        </Description>

        <Sequence/>

        <Break>
            <Universal:depth/>
            <Lt><Control:VerticalControl.surfaceThreshold/></Lt>
        </Break>

        <Guidance:Buoyancy>
            <Parallel/>
            <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyDefault/></Setting>
        </Guidance:Buoyancy>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="WaitToFloat"/></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2021-12-10T18:01:33.643Z,1639159293.643 [CommandExec](IMPORTANT): Loaded ./Missions/Maintenance/tank_ballast_and_trim.xml
2021-12-10T18:01:40.661Z,1639159300.661 [CommandExec](IMPORTANT): got command set ballast_and_trim.MissionTimeout 20.000000 minute
2021-12-10T18:01:40.661Z,1639159300.661 [CommandExec](IMPORTANT): got command run
2021-12-10T18:01:40.669Z,1639159300.669 [CommandExec](IMPORTANT): Running 
2021-12-10T18:01:40.982Z,1639159300.982 [Default] Stopped
2021-12-10T18:01:41.007Z,1639159301.007 [Default](DEBUG): Aggregate::uninitialize Default
2021-12-10T18:01:41.007Z,1639159301.007 [Default:B.GoToSurface] Stopped
2021-12-10T18:01:41.007Z,1639159301.007 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-12-10T18:01:41.008Z,1639159301.008 [Default:CheckIn] Stopped
2021-12-10T18:01:41.008Z,1639159301.008 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T18:01:41.008Z,1639159301.008 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T18:01:41.008Z,1639159301.008 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2021-12-10T18:01:41.009Z,1639159301.009 [ballast_and_trim] Running Loop=1
2021-12-10T18:01:41.010Z,1639159301.010 [ballast_and_trim](DEBUG): Aggregate::initialize ballast_and_trim
2021-12-10T18:01:41.010Z,1639159301.010 [ballast_and_trim:Science] Running Loop=1
2021-12-10T18:01:41.015Z,1639159301.015 [ballast_and_trim:Science](DEBUG): Aggregate::initialize ballast_and_trim:Science
2021-12-10T18:01:41.015Z,1639159301.015 [ballast_and_trim:Science:A] Running Loop=1
2021-12-10T18:01:41.015Z,1639159301.015 [ballast_and_trim:Science:B] Running Loop=1
2021-12-10T18:01:41.015Z,1639159301.015 [ballast_and_trim:Science:C] Running Loop=1
2021-12-10T18:01:41.016Z,1639159301.016 [ballast_and_trim:Science:D] Running Loop=1
2021-12-10T18:01:41.016Z,1639159301.016 [ballast_and_trim:Science:E] Running Loop=1
2021-12-10T18:01:41.016Z,1639159301.016 [ballast_and_trim:Science:F] Running Loop=1
2021-12-10T18:01:41.016Z,1639159301.016 [ballast_and_trim:Science:Read_Oil] Running Loop=1
2021-12-10T18:01:41.016Z,1639159301.016 [ballast_and_trim:Science:PeakDetectChl] Running Loop=1
2021-12-10T18:01:41.017Z,1639159301.017 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectChl
2021-12-10T18:01:41.017Z,1639159301.017 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2021-12-10T18:01:41.018Z,1639159301.018 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2021-12-10T18:01:41.041Z,1639159301.041 [ballast_and_trim:Science:HighestChlPeakReport] Running Loop=1
2021-12-10T18:01:41.042Z,1639159301.042 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestChlPeakReport
2021-12-10T18:01:41.042Z,1639159301.042 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2021-12-10T18:01:41.042Z,1639159301.042 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2021-12-10T18:01:41.052Z,1639159301.052 [ballast_and_trim:Science:PeakDetectNO3] Running Loop=1
2021-12-10T18:01:41.052Z,1639159301.052 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectNO3
2021-12-10T18:01:41.053Z,1639159301.053 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2021-12-10T18:01:41.053Z,1639159301.053 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2021-12-10T18:01:41.064Z,1639159301.064 [ballast_and_trim:Science:PeakDetectOil] Running Loop=1
2021-12-10T18:01:41.064Z,1639159301.064 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectOil
2021-12-10T18:01:41.064Z,1639159301.064 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2021-12-10T18:01:41.065Z,1639159301.065 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2021-12-10T18:01:41.075Z,1639159301.075 [ballast_and_trim:Science:HighestOilPeakReport] Running Loop=1
2021-12-10T18:01:41.075Z,1639159301.075 [ballast_and_trim:Science:HighestOilPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestOilPeakReport
2021-12-10T18:01:41.075Z,1639159301.075 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal] Running Loop=1
2021-12-10T18:01:41.075Z,1639159301.075 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2021-12-10T18:01:41.076Z,1639159301.076 [ballast_and_trim:Science:PeakDetectFDOM] Running Loop=1
2021-12-10T18:01:41.076Z,1639159301.076 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectFDOM
2021-12-10T18:01:41.076Z,1639159301.076 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2021-12-10T18:01:41.076Z,1639159301.076 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2021-12-10T18:01:41.078Z,1639159301.078 [ballast_and_trim:Science:PeakDetectSalinity] Running Loop=1
2021-12-10T18:01:41.078Z,1639159301.078 [ballast_and_trim:Science:PeakDetectSalinity](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectSalinity
2021-12-10T18:01:41.087Z,1639159301.087 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth] Running Loop=1
2021-12-10T18:01:41.087Z,1639159301.087 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth](DEBUG): Initialize.
2021-12-10T18:01:41.088Z,1639159301.088 [ballast_and_trim:Science:HighestSaltPeakReport] Running Loop=1
2021-12-10T18:01:41.089Z,1639159301.089 [ballast_and_trim:Science:HighestSaltPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestSaltPeakReport
2021-12-10T18:01:41.089Z,1639159301.089 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal] Running Loop=1
2021-12-10T18:01:41.089Z,1639159301.089 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2021-12-10T18:01:41.089Z,1639159301.089 [ballast_and_trim:Science:OceanCurrent] Running Loop=1
2021-12-10T18:01:41.090Z,1639159301.090 [ballast_and_trim:Science:OceanCurrent](DEBUG): Aggregate::initialize ballast_and_trim:Science:OceanCurrent
2021-12-10T18:01:41.090Z,1639159301.090 [ballast_and_trim:Science:OceanCurrent:A.] Running Loop=1
2021-12-10T18:01:41.090Z,1639159301.090 [ballast_and_trim:Science:OceanCurrent:A.](INFO): Initializing CurrentEstimator.
2021-12-10T18:01:41.090Z,1639159301.090 [ballast_and_trim:RunBallastAndTrim] Running Loop=1
2021-12-10T18:01:41.090Z,1639159301.090 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim
2021-12-10T18:01:41.090Z,1639159301.090 [ballast_and_trim:RunBallastAndTrim:Depth1] Running Loop=1
2021-12-10T18:01:41.099Z,1639159301.099 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1
2021-12-10T18:01:41.101Z,1639159301.101 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Running Loop=1
2021-12-10T18:01:41.103Z,1639159301.103 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Stopped
2021-12-10T18:01:41.104Z,1639159301.104 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Running Loop=1
2021-12-10T18:01:41.104Z,1639159301.104 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2021-12-10T18:01:41.104Z,1639159301.104 [ballast_and_trim:Science] Running Loop=1
2021-12-10T18:01:41.105Z,1639159301.105 [ballast_and_trim:Science:HighestSaltPeakReport] Stopped
2021-12-10T18:01:41.105Z,1639159301.105 [ballast_and_trim:Science:HighestSaltPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestSaltPeakReport
2021-12-10T18:01:41.105Z,1639159301.105 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal] Stopped
2021-12-10T18:01:41.105Z,1639159301.105 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2021-12-10T18:01:41.105Z,1639159301.105 [ballast_and_trim:Science:PeakDetectSalinity] Stopped
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:PeakDetectSalinity](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectSalinity
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth] Stopped
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:PeakDetectFDOM] Stopped
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectFDOM
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:HighestOilPeakReport] Stopped
2021-12-10T18:01:41.106Z,1639159301.106 [ballast_and_trim:Science:HighestOilPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestOilPeakReport
2021-12-10T18:01:41.115Z,1639159301.115 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal] Stopped
2021-12-10T18:01:41.115Z,1639159301.115 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2021-12-10T18:01:41.115Z,1639159301.115 [ballast_and_trim:Science:PeakDetectOil] Stopped
2021-12-10T18:01:41.116Z,1639159301.116 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectOil
2021-12-10T18:01:41.116Z,1639159301.116 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2021-12-10T18:01:41.117Z,1639159301.117 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2021-12-10T18:01:41.117Z,1639159301.117 [ballast_and_trim:Science:PeakDetectNO3] Stopped
2021-12-10T18:01:41.118Z,1639159301.118 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectNO3
2021-12-10T18:01:41.118Z,1639159301.118 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2021-12-10T18:01:41.118Z,1639159301.118 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2021-12-10T18:01:41.118Z,1639159301.118 [ballast_and_trim:Science:HighestChlPeakReport] Stopped
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestChlPeakReport
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:PeakDetectChl] Stopped
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectChl
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2021-12-10T18:01:41.127Z,1639159301.127 [ballast_and_trim:Science:OceanCurrent:A.] Running Loop=1
2021-12-10T18:01:41.129Z,1639159301.129 [ballast_and_trim:Science:Read_Oil] Stopped
2021-12-10T18:01:41.129Z,1639159301.129 [ballast_and_trim:Science:F] Running Loop=1
2021-12-10T18:01:41.130Z,1639159301.130 [ballast_and_trim:Science:F](DEBUG): Initialize ReadDataComponent to sense WetLabsUBAT.average_bioluminescence
2021-12-10T18:01:41.130Z,1639159301.130 [ballast_and_trim:Science:E] Running Loop=1
2021-12-10T18:01:41.147Z,1639159301.147 [ballast_and_trim:Science:E](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2021-12-10T18:01:41.148Z,1639159301.148 [ballast_and_trim:Science:D] Stopped
2021-12-10T18:01:41.148Z,1639159301.148 [ballast_and_trim:Science:C] Running Loop=1
2021-12-10T18:01:41.148Z,1639159301.148 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_temperature
2021-12-10T18:01:41.149Z,1639159301.149 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_salinity
2021-12-10T18:01:41.149Z,1639159301.149 [ballast_and_trim:Science:B] Running Loop=1
2021-12-10T18:01:41.150Z,1639159301.150 [ballast_and_trim:Science:B](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2021-12-10T18:01:41.151Z,1639159301.151 [ballast_and_trim:Science:B](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2021-12-10T18:01:41.151Z,1639159301.151 [ballast_and_trim:Science:A] Stopped
2021-12-10T18:01:41.373Z,1639159301.373 [WetLabsBB2FL](INFO): Powering up
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Running Loop=1
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2021-12-10T18:01:41.512Z,1639159301.512 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Running Loop=1
2021-12-10T18:01:41.523Z,1639159301.523 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F](INFO): Going to target depth. Speed set to 0.000000 m/s 
2021-12-10T18:01:41.523Z,1639159301.523 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Stopped
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Running Loop=1
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Running Loop=1
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Running Loop=1
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Initialize.
2021-12-10T18:01:41.524Z,1639159301.524 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Running Loop=1
2021-12-10T18:01:41.525Z,1639159301.525 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2021-12-10T18:01:41.525Z,1639159301.525 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Running Loop=1
2021-12-10T18:01:41.525Z,1639159301.525 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Initialize.
2021-12-10T18:01:41.525Z,1639159301.525 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Running Loop=1
2021-12-10T18:01:41.525Z,1639159301.525 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2021-12-10T18:01:41.525Z,1639159301.525 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Running Loop=1
2021-12-10T18:01:41.525Z,1639159301.525 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2021-12-10T18:01:41.526Z,1639159301.526 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2021-12-10T18:01:41.535Z,1639159301.535 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2021-12-10T18:01:41.535Z,1639159301.535 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2021-12-10T18:01:41.535Z,1639159301.535 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2021-12-10T18:01:41.596Z,1639159301.596 [WetLabsUBAT](INFO): Powering up
2021-12-10T18:01:41.797Z,1639159301.797 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Stopped
2021-12-10T18:01:41.797Z,1639159301.797 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2021-12-10T18:01:41.797Z,1639159301.797 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Stopped
2021-12-10T18:01:41.797Z,1639159301.797 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Running Loop=1
2021-12-10T18:01:41.798Z,1639159301.798 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2021-12-10T18:01:41.798Z,1639159301.798 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2021-12-10T18:01:41.798Z,1639159301.798 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Initialize.
2021-12-10T18:01:41.798Z,1639159301.798 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Running Loop=1
2021-12-10T18:01:41.798Z,1639159301.798 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Stopped
2021-12-10T18:01:41.806Z,1639159301.806 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2021-12-10T18:01:41.807Z,1639159301.807 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Stopped
2021-12-10T18:01:41.807Z,1639159301.807 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Stopped
2021-12-10T18:01:41.807Z,1639159301.807 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2021-12-10T18:01:41.807Z,1639159301.807 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Stopped
2021-12-10T18:01:41.807Z,1639159301.807 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2021-12-10T18:01:42.237Z,1639159302.237 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2021-12-10T18:01:42.238Z,1639159302.238 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2021-12-10T18:01:42.238Z,1639159302.238 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Stopped
2021-12-10T18:01:42.238Z,1639159302.238 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Running Loop=1
2021-12-10T18:01:42.238Z,1639159302.238 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Initialize.
2021-12-10T18:01:43.514Z,1639159303.514 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20211210T162424/Express0044.lzma
2021-12-10T18:01:44.517Z,1639159304.517 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0044.lzma.bak
2021-12-10T18:01:44.517Z,1639159304.517 [DataOverHttps](INFO): SBD MOMSN=16341695
2021-12-10T18:01:45.044Z,1639159305.044 [CTD_Seabird](ERROR): Failed to parse device response: <!--startlogging-->
2021-12-10T18:01:47.054Z,1639159307.054 [CTD_Seabird](ERROR): Salinity reading out of range: 13.937148 psu
2021-12-10T18:01:51.769Z,1639159311.769 [WetLabsUBAT](FAULT): UBAT flow rate is below the specified threshold of 0.05 l/s.
2021-12-10T18:03:36.080Z,1639159416.080 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.923653
2021-12-10T18:04:37.331Z,1639159477.331 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:05:12.479Z,1639159512.479 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:05:23.672Z,1639159523.672 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2021-12-10T18:05:24.715Z,1639159524.715 [Radio_Surface](INFO): Powering down
2021-12-10T18:05:47.640Z,1639159547.640 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:05:48.643Z,1639159548.643 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2021-12-10T18:06:48.574Z,1639159608.574 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Stopped
2021-12-10T18:06:48.581Z,1639159608.581 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2021-12-10T18:06:48.582Z,1639159608.582 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Stopped
2021-12-10T18:06:48.582Z,1639159608.582 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2021-12-10T18:06:48.587Z,1639159608.587 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Stopped
2021-12-10T18:06:48.587Z,1639159608.587 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Uninitialize.
2021-12-10T18:06:48.588Z,1639159608.588 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2021-12-10T18:06:48.589Z,1639159608.589 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Stopped
2021-12-10T18:06:48.589Z,1639159608.589 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2021-12-10T18:06:48.589Z,1639159608.589 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Stopped
2021-12-10T18:06:48.590Z,1639159608.590 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth] Running Loop=1
2021-12-10T18:06:48.590Z,1639159608.590 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2021-12-10T18:06:48.595Z,1639159608.595 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Running Loop=1
2021-12-10T18:06:48.595Z,1639159608.595 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Initialize.
2021-12-10T18:06:48.595Z,1639159608.595 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Running Loop=1
2021-12-10T18:06:48.595Z,1639159608.595 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch](DEBUG): Initialize.
2021-12-10T18:06:48.595Z,1639159608.595 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C] Running Loop=1
2021-12-10T18:06:48.972Z,1639159608.972 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C](INFO): Waiting for the vehicle to settle. Depth = 7.030683 m 
2021-12-10T18:06:48.972Z,1639159608.972 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C] Stopped
2021-12-10T18:06:48.972Z,1639159608.972 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait] Running Loop=1
2021-12-10T18:06:48.972Z,1639159608.972 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Initialize Wait Component.
2021-12-10T18:06:48.972Z,1639159608.972 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Running Loop=1
2021-12-10T18:06:48.973Z,1639159608.973 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Running Loop=1
2021-12-10T18:10:14.252Z,1639159814.252 [CTD_Seabird](ERROR): Failed to parse device response: 4110.20
2021-12-10T18:12:04.892Z,1639159924.892 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2021-12-10T18:12:05.207Z,1639159925.207 [WetLabsUBAT](ERROR): Failed to parse incomplete device message.
2021-12-10T18:13:15.179Z,1639159995.179 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2021-12-10T18:13:15.179Z,1639159995.179 [RDI_Pathfinder] Communications Fault, FailCount= 1
2021-12-10T18:13:15.179Z,1639159995.179 [RDI_Pathfinder](ERROR): Communications Fault
2021-12-10T18:13:15.273Z,1639159995.273 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2021-12-10T18:13:15.639Z,1639159995.639 [RDI_Pathfinder](INFO): Powering down
2021-12-10T18:13:16.386Z,1639159996.386 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2021-12-10T18:13:16.386Z,1639159996.386 [RDI_Pathfinder] No Fault, FailCount= 1
2021-12-10T18:14:46.939Z,1639160086.939 [WetLabsUBAT](ERROR): Failed to parse incomplete device message.
2021-12-10T18:15:40.226Z,1639160140.226 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for water mass range.
2021-12-10T18:16:49.688Z,1639160209.688 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](INFO): Done Waiting.
2021-12-10T18:16:49.688Z,1639160209.688 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait] Stopped
2021-12-10T18:16:49.688Z,1639160209.688 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T18:16:49.688Z,1639160209.688 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E] Running Loop=1
2021-12-10T18:16:50.138Z,1639160210.138 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E](INFO): Running ballast and trim. Depth = 7.188168 m 
2021-12-10T18:16:50.141Z,1639160210.141 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E] Stopped
2021-12-10T18:16:50.141Z,1639160210.141 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.] Running Loop=1
2021-12-10T18:16:50.142Z,1639160210.142 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](INFO): Initializing BallastAndTrim.
2021-12-10T18:19:15.549Z,1639160355.549 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2021-12-10T18:20:30.324Z,1639160430.324 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2021-12-10T18:21:24.567Z,1639160484.567 [WetLabsUBAT](ERROR): Failed to parse incomplete device message.
2021-12-10T18:21:40.586Z,1639160500.586 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2021-12-10T18:21:41.425Z,1639160501.425 [ballast_and_trim](INFO): Timed out from 2021-12-10T18:01:41.0Z
2021-12-10T18:21:41.425Z,1639160501.425 [MissionManager](INFO): ballast_and_trim is completed.
2021-12-10T18:21:41.425Z,1639160501.425 [MissionManager](INFO): Uninitializing Mission ballast_and_trim
2021-12-10T18:21:41.425Z,1639160501.425 [ballast_and_trim] Stopped
2021-12-10T18:21:41.425Z,1639160501.425 [ballast_and_trim](DEBUG): Aggregate::uninitialize ballast_and_trim
2021-12-10T18:21:41.425Z,1639160501.425 [ballast_and_trim:Science] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science](DEBUG): Aggregate::uninitialize ballast_and_trim:Science
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science:B] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science:C] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science:E] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science:F] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science:OceanCurrent] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science:OceanCurrent](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:OceanCurrent
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:Science:OceanCurrent:A.] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:RunBallastAndTrim] Stopped
2021-12-10T18:21:41.426Z,1639160501.426 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim
2021-12-10T18:21:41.431Z,1639160501.431 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Stopped
2021-12-10T18:21:41.431Z,1639160501.431 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2021-12-10T18:21:41.431Z,1639160501.431 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Stopped
2021-12-10T18:21:41.431Z,1639160501.431 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Stopped
2021-12-10T18:21:41.431Z,1639160501.431 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Stopped
2021-12-10T18:21:41.431Z,1639160501.431 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Stopped
2021-12-10T18:21:41.431Z,1639160501.431 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Stopped
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth] Stopped
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Stopped
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Uninitialize.
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Stopped
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.] Stopped
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](INFO): Uninitializing BallastAndTrim.
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:Depth1] Stopped
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1
2021-12-10T18:21:41.432Z,1639160501.432 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Stopped
2021-12-10T18:21:41.433Z,1639160501.433 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2021-12-10T18:21:41.667Z,1639160501.667 [WetLabsBB2FL](INFO): Powering down
2021-12-10T18:21:41.801Z,1639160501.801 [MissionManager](IMPORTANT): Started mission Default
2021-12-10T18:21:41.801Z,1639160501.801 [Default] Running Loop=1
2021-12-10T18:21:41.802Z,1639160501.802 [Default](DEBUG): Aggregate::initialize Default
2021-12-10T18:21:41.802Z,1639160501.802 [Default:B.GoToSurface] Running Loop=1
2021-12-10T18:21:41.802Z,1639160501.802 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-12-10T18:21:41.802Z,1639160501.802 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-12-10T18:21:41.803Z,1639160501.803 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-12-10T18:21:41.803Z,1639160501.803 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-12-10T18:21:41.803Z,1639160501.803 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-12-10T18:21:41.804Z,1639160501.804 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-12-10T18:21:41.804Z,1639160501.804 [Default:A.Wait] Running Loop=1
2021-12-10T18:21:41.804Z,1639160501.804 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-12-10T18:21:41.948Z,1639160501.948 [WetLabsUBAT](INFO): Powering down
2021-12-10T18:21:42.201Z,1639160502.201 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -20.00 mm (1 active estimators).
2021-12-10T18:21:42.459Z,1639160502.459 [Radio_Surface](INFO): Powering up
2021-12-10T18:21:48.627Z,1639160508.627 [DataOverHttps](INFO): Radio surface powered ON.
2021-12-10T18:21:55.140Z,1639160515.140 [Default:A.Wait](INFO): Done Waiting.
2021-12-10T18:21:55.140Z,1639160515.140 [Default:A.Wait] Stopped
2021-12-10T18:21:55.141Z,1639160515.141 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T18:22:18.755Z,1639160538.755 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:22:53.907Z,1639160573.907 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:23:14.773Z,1639160594.773 [Default:CheckIn] Running Loop=1
2021-12-10T18:23:14.773Z,1639160594.773 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T18:23:14.774Z,1639160594.774 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T18:23:29.047Z,1639160609.047 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:24:04.195Z,1639160644.195 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:24:39.351Z,1639160679.351 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-12-10T18:25:13.515Z,1639160713.515 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002865
2021-12-10T18:27:27.607Z,1639160847.607 [NAL9602](INFO): SBD MO Status=2, MOMSN=17875, MT Status=2, MTMSN=0
2021-12-10T18:27:27.607Z,1639160847.607 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:28:14.909Z,1639160894.909 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-12-10T18:23:14.8Z
2021-12-10T18:28:14.909Z,1639160894.909 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T18:28:14.909Z,1639160894.909 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T18:28:19.356Z,1639160899.356 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T18:28:26.278Z,1639160906.278 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211210T162424/Courier0046.lzma
2021-12-10T18:28:27.281Z,1639160907.281 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0046.lzma.bak
2021-12-10T18:28:27.281Z,1639160907.281 [DataOverHttps](INFO): SBD MOMSN=16342151
2021-12-10T18:28:44.754Z,1639160924.754 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211210T162424/Courier0049.lzma
2021-12-10T18:28:45.756Z,1639160925.756 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0049.lzma.bak
2021-12-10T18:28:45.757Z,1639160925.757 [DataOverHttps](INFO): SBD MOMSN=16342156
2021-12-10T18:28:50.105Z,1639160930.105 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T18:29:02.391Z,1639160942.391 [DataOverHttps](INFO): Sending 174 bytes from file Logs/20211210T162424/Express0047.lzma
2021-12-10T18:29:03.393Z,1639160943.393 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0047.lzma.bak
2021-12-10T18:29:03.393Z,1639160943.393 [DataOverHttps](INFO): SBD MOMSN=16342159
2021-12-10T18:29:20.127Z,1639160960.127 [DataOverHttps](INFO): Sending 735 bytes from file Logs/20211210T162424/Express0050.lzma
2021-12-10T18:29:21.121Z,1639160961.121 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0050.lzma.bak
2021-12-10T18:29:21.121Z,1639160961.121 [DataOverHttps](INFO): SBD MOMSN=16342164
2021-12-10T18:29:22.470Z,1639160962.470 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T18:29:22.475Z,1639160962.475 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T18:29:22.475Z,1639160962.475 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T18:34:23.065Z,1639161263.065 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T18:34:23.066Z,1639161263.066 [Default:CheckIn:C.Wait] Stopped
2021-12-10T18:34:23.066Z,1639161263.066 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T18:34:23.066Z,1639161263.066 [Default:CheckIn:D] Running Loop=1
2021-12-10T18:34:23.492Z,1639161263.492 [Default:CheckIn:D] Stopped
2021-12-10T18:34:23.492Z,1639161263.492 [Default:CheckIn:E] Running Loop=1
2021-12-10T18:34:23.920Z,1639161263.920 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.694833 min 
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn:E] Stopped
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn] Stopped
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn](INFO): Running loop #2
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn] Running Loop=2
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T18:34:23.921Z,1639161263.921 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T18:34:25.468Z,1639161265.468 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-12-10T18:34:25.468Z,1639161265.468 [NAL9602] Data Fault, FailCount= 1
2021-12-10T18:34:25.468Z,1639161265.468 [NAL9602](ERROR): Data Fault
2021-12-10T18:34:25.559Z,1639161265.559 [CBIT](ERROR): Data Fault in component: NAL9602
2021-12-10T18:34:25.876Z,1639161265.876 [NAL9602](INFO): Powering down
2021-12-10T18:34:26.768Z,1639161266.768 [CBIT](INFO): Clearing failed state for component NAL9602
2021-12-10T18:34:26.768Z,1639161266.768 [NAL9602] No Fault, FailCount= 1
2021-12-10T18:34:56.176Z,1639161296.176 [NAL9602](INFO): Powering up NAL9602
2021-12-10T18:35:07.084Z,1639161307.084 [NAL9602](INFO): NAL9602 initialized
2021-12-10T18:36:58.585Z,1639161418.585 [NAL9602](INFO): SBD MO Status=0, MOMSN=17875, MT Status=0, MTMSN=0
2021-12-10T18:36:58.586Z,1639161418.586 [NAL9602](INFO): No messages in MT queue
2021-12-10T18:37:38.994Z,1639161458.994 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183737.00,A,3648.17003,N,12147.28535,W,0.603,105.88,101221,,,A*71
2021-12-10T18:37:38.996Z,1639161458.996 [NAL9602](INFO): GPS fix at 20211210T183737: (36.802834, -121.788089)
2021-12-10T18:37:39.040Z,1639161459.040 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T18:37:39.041Z,1639161459.041 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T18:37:47.126Z,1639161467.126 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0052.lzma
2021-12-10T18:37:48.129Z,1639161468.129 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0052.lzma.bak
2021-12-10T18:37:48.129Z,1639161468.129 [DataOverHttps](INFO): SBD MOMSN=16342284
2021-12-10T18:38:04.919Z,1639161484.919 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20211210T162424/Express0053.lzma
2021-12-10T18:38:05.920Z,1639161485.920 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0053.lzma.bak
2021-12-10T18:38:05.921Z,1639161485.921 [DataOverHttps](INFO): SBD MOMSN=16342287
2021-12-10T18:38:07.303Z,1639161487.303 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T18:38:07.303Z,1639161487.303 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T18:38:07.303Z,1639161487.303 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T18:38:11.308Z,1639161491.308 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T18:43:07.925Z,1639161787.925 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T18:43:07.925Z,1639161787.925 [Default:CheckIn:C.Wait] Stopped
2021-12-10T18:43:07.925Z,1639161787.925 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T18:43:07.925Z,1639161787.925 [Default:CheckIn:D] Running Loop=1
2021-12-10T18:43:08.379Z,1639161788.379 [Default:CheckIn:D] Stopped
2021-12-10T18:43:08.379Z,1639161788.379 [Default:CheckIn:E] Running Loop=1
2021-12-10T18:43:08.735Z,1639161788.735 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.442961 min 
2021-12-10T18:43:08.735Z,1639161788.735 [Default:CheckIn:E] Stopped
2021-12-10T18:43:08.735Z,1639161788.735 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T18:43:08.735Z,1639161788.735 [Default:CheckIn] Stopped
2021-12-10T18:43:08.735Z,1639161788.735 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T18:43:08.735Z,1639161788.735 [Default:CheckIn](INFO): Running loop #3
2021-12-10T18:43:08.736Z,1639161788.736 [Default:CheckIn] Running Loop=3
2021-12-10T18:43:08.736Z,1639161788.736 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T18:43:08.736Z,1639161788.736 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T18:43:10.762Z,1639161790.762 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184310.00,A,3648.14426,N,12147.24386,W,2.099,99.31,101221,,,A*44
2021-12-10T18:43:10.764Z,1639161790.764 [NAL9602](INFO): GPS fix at 20211210T184310: (36.802404, -121.787398)
2021-12-10T18:43:10.819Z,1639161790.819 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T18:43:10.819Z,1639161790.819 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T18:43:19.266Z,1639161799.266 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0055.lzma
2021-12-10T18:43:20.269Z,1639161800.269 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0055.lzma.bak
2021-12-10T18:43:20.269Z,1639161800.269 [DataOverHttps](INFO): SBD MOMSN=16342355
2021-12-10T18:43:37.151Z,1639161817.151 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20211210T162424/Express0056.lzma
2021-12-10T18:43:38.153Z,1639161818.153 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0056.lzma.bak
2021-12-10T18:43:38.153Z,1639161818.153 [DataOverHttps](INFO): SBD MOMSN=16342362
2021-12-10T18:43:39.460Z,1639161819.460 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T18:43:39.460Z,1639161819.460 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T18:43:39.460Z,1639161819.460 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T18:44:21.490Z,1639161861.490 [NAL9602](INFO): SBD MO Status=2, MOMSN=17876, MT Status=2, MTMSN=0
2021-12-10T18:44:21.563Z,1639161861.563 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:44:46.556Z,1639161886.556 [NAL9602](INFO): SBD MO Status=2, MOMSN=17876, MT Status=2, MTMSN=0
2021-12-10T18:44:46.556Z,1639161886.556 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:46:43.714Z,1639162003.714 [NAL9602](INFO): SBD MO Status=2, MOMSN=17876, MT Status=2, MTMSN=0
2021-12-10T18:46:43.714Z,1639162003.714 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:47:01.494Z,1639162021.494 [BPC1](INFO): Calculating totals. Valid battery stick count: 54. Valid reserve battery stick count: 6.
2021-12-10T18:47:01.497Z,1639162021.497 [BPC1](INFO): Received data from all battery sticks.
2021-12-10T18:47:04.317Z,1639162024.317 [NAL9602](INFO): SBD MO Status=0, MOMSN=17876, MT Status=0, MTMSN=0
2021-12-10T18:47:04.317Z,1639162024.317 [NAL9602](INFO): No messages in MT queue
2021-12-10T18:47:35.024Z,1639162055.024 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T18:48:40.099Z,1639162120.099 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T18:48:40.100Z,1639162120.100 [Default:CheckIn:C.Wait] Stopped
2021-12-10T18:48:40.100Z,1639162120.100 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T18:48:40.100Z,1639162120.100 [Default:CheckIn:D] Running Loop=1
2021-12-10T18:48:40.532Z,1639162120.532 [Default:CheckIn:D] Stopped
2021-12-10T18:48:40.532Z,1639162120.532 [Default:CheckIn:E] Running Loop=1
2021-12-10T18:48:40.928Z,1639162120.928 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.978839 min 
2021-12-10T18:48:40.928Z,1639162120.928 [Default:CheckIn:E] Stopped
2021-12-10T18:48:40.928Z,1639162120.928 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T18:48:40.929Z,1639162120.929 [Default:CheckIn] Stopped
2021-12-10T18:48:40.929Z,1639162120.929 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T18:48:40.929Z,1639162120.929 [Default:CheckIn](INFO): Running loop #4
2021-12-10T18:48:40.929Z,1639162120.929 [Default:CheckIn] Running Loop=4
2021-12-10T18:48:40.929Z,1639162120.929 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T18:48:40.929Z,1639162120.929 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T18:48:42.922Z,1639162122.922 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184842.00,A,3648.16387,N,12147.29013,W,3.499,117.64,101221,,,A*76
2021-12-10T18:48:42.925Z,1639162122.925 [NAL9602](INFO): GPS fix at 20211210T184842: (36.802731, -121.788169)
2021-12-10T18:48:42.937Z,1639162122.937 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T18:48:42.937Z,1639162122.937 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T18:48:51.038Z,1639162131.038 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20211210T162424/Courier0058.lzma
2021-12-10T18:48:52.041Z,1639162132.041 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0058.lzma.bak
2021-12-10T18:48:52.041Z,1639162132.041 [DataOverHttps](INFO): SBD MOMSN=16342442
2021-12-10T18:49:05.946Z,1639162145.946 [NAL9602](INFO): SBD MO Status=0, MOMSN=17877, MT Status=0, MTMSN=0
2021-12-10T18:49:05.946Z,1639162145.946 [NAL9602](INFO): No messages in MT queue
2021-12-10T18:49:08.910Z,1639162148.910 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20211210T162424/Express0059.lzma
2021-12-10T18:49:09.913Z,1639162149.913 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0059.lzma.bak
2021-12-10T18:49:09.913Z,1639162149.913 [DataOverHttps](INFO): SBD MOMSN=16342449
2021-12-10T18:49:11.212Z,1639162151.212 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T18:49:11.212Z,1639162151.212 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T18:49:11.212Z,1639162151.212 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T18:49:36.648Z,1639162176.648 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T18:51:41.941Z,1639162301.941 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2021-12-10T18:53:28.304Z,1639162408.304 [DataOverHttps](IMPORTANT): SBD MTMSN=20211210T185327
2021-12-10T18:53:36.158Z,1639162416.158 [DataOverHttps](INFO): Received command: failc
2021-12-10T18:53:36.187Z,1639162416.187 [CommandExec](IMPORTANT): got command failComponent
2021-12-10T18:53:36.187Z,1639162416.187 [CommandExec](IMPORTANT): Failed components:
2021-12-10T18:53:36.188Z,1639162416.188 [CommandExec](IMPORTANT): No failed Components.
2021-12-10T18:54:11.812Z,1639162451.812 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T18:54:11.812Z,1639162451.812 [Default:CheckIn:C.Wait] Stopped
2021-12-10T18:54:11.812Z,1639162451.812 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T18:54:11.812Z,1639162451.812 [Default:CheckIn:D] Running Loop=1
2021-12-10T18:54:12.253Z,1639162452.253 [Default:CheckIn:D] Stopped
2021-12-10T18:54:12.253Z,1639162452.253 [Default:CheckIn:E] Running Loop=1
2021-12-10T18:54:12.621Z,1639162452.621 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.507524 min 
2021-12-10T18:54:12.621Z,1639162452.621 [Default:CheckIn:E] Stopped
2021-12-10T18:54:12.621Z,1639162452.621 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T18:54:12.621Z,1639162452.621 [Default:CheckIn] Stopped
2021-12-10T18:54:12.621Z,1639162452.621 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T18:54:12.621Z,1639162452.621 [Default:CheckIn](INFO): Running loop #5
2021-12-10T18:54:12.622Z,1639162452.622 [Default:CheckIn] Running Loop=5
2021-12-10T18:54:12.622Z,1639162452.622 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T18:54:12.622Z,1639162452.622 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T18:54:14.641Z,1639162454.641 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185413.00,A,3648.16346,N,12147.27938,W,0.136,0.00,101221,,,A*7A
2021-12-10T18:54:14.643Z,1639162454.643 [NAL9602](INFO): GPS fix at 20211210T185413: (36.802724, -121.787990)
2021-12-10T18:54:14.656Z,1639162454.656 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T18:54:14.656Z,1639162454.656 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T18:54:25.830Z,1639162465.830 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0061.lzma
2021-12-10T18:54:26.833Z,1639162466.833 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0061.lzma.bak
2021-12-10T18:54:26.833Z,1639162466.833 [DataOverHttps](INFO): SBD MOMSN=16342541
2021-12-10T18:54:44.131Z,1639162484.131 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20211210T162424/Express0062.lzma
2021-12-10T18:54:45.133Z,1639162485.133 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0062.lzma.bak
2021-12-10T18:54:45.133Z,1639162485.133 [DataOverHttps](INFO): SBD MOMSN=16342554
2021-12-10T18:55:01.970Z,1639162501.970 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20211210T162424/Express0065.lzma
2021-12-10T18:55:02.973Z,1639162502.973 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0065.lzma.bak
2021-12-10T18:55:02.973Z,1639162502.973 [DataOverHttps](INFO): SBD MOMSN=16342564
2021-12-10T18:55:04.072Z,1639162504.072 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T18:55:04.073Z,1639162504.073 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T18:55:04.073Z,1639162504.073 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T18:56:50.721Z,1639162610.721 [NAL9602](INFO): SBD MO Status=2, MOMSN=17878, MT Status=2, MTMSN=0
2021-12-10T18:56:50.722Z,1639162610.722 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:57:47.686Z,1639162667.686 [NAL9602](INFO): SBD MO Status=2, MOMSN=17878, MT Status=2, MTMSN=0
2021-12-10T18:57:47.687Z,1639162667.687 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:58:23.650Z,1639162703.650 [NAL9602](INFO): SBD MO Status=2, MOMSN=17878, MT Status=2, MTMSN=0
2021-12-10T18:58:23.651Z,1639162703.651 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:59:22.647Z,1639162762.647 [NAL9602](INFO): SBD MO Status=2, MOMSN=17878, MT Status=2, MTMSN=0
2021-12-10T18:59:22.648Z,1639162762.648 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T18:59:23.037Z,1639162763.037 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T18:59:53.744Z,1639162793.744 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T19:00:04.706Z,1639162804.706 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T19:00:04.706Z,1639162804.706 [Default:CheckIn:C.Wait] Stopped
2021-12-10T19:00:04.706Z,1639162804.706 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T19:00:04.707Z,1639162804.707 [Default:CheckIn:D] Running Loop=1
2021-12-10T19:00:05.065Z,1639162805.065 [Default:CheckIn:D] Stopped
2021-12-10T19:00:05.065Z,1639162805.065 [Default:CheckIn:E] Running Loop=1
2021-12-10T19:00:05.497Z,1639162805.497 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.387724 min 
2021-12-10T19:00:05.497Z,1639162805.497 [Default:CheckIn:E] Stopped
2021-12-10T19:00:05.498Z,1639162805.498 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T19:00:05.498Z,1639162805.498 [Default:CheckIn] Stopped
2021-12-10T19:00:05.498Z,1639162805.498 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T19:00:05.498Z,1639162805.498 [Default:CheckIn](INFO): Running loop #6
2021-12-10T19:00:05.498Z,1639162805.498 [Default:CheckIn] Running Loop=6
2021-12-10T19:00:05.498Z,1639162805.498 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T19:00:05.499Z,1639162805.499 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T19:00:07.482Z,1639162807.482 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190006.00,A,3648.16494,N,12147.28175,W,0.019,0.00,101221,,,A*74
2021-12-10T19:00:07.485Z,1639162807.485 [NAL9602](INFO): GPS fix at 20211210T190006: (36.802749, -121.788029)
2021-12-10T19:00:07.541Z,1639162807.541 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T19:00:07.541Z,1639162807.541 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T19:00:15.390Z,1639162815.390 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20211210T162424/Courier0067.lzma
2021-12-10T19:00:16.393Z,1639162816.393 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0067.lzma.bak
2021-12-10T19:00:16.393Z,1639162816.393 [DataOverHttps](INFO): SBD MOMSN=16342647
2021-12-10T19:00:36.611Z,1639162836.611 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20211210T162424/Express0068.lzma
2021-12-10T19:00:37.614Z,1639162837.614 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0068.lzma.bak
2021-12-10T19:00:37.614Z,1639162837.614 [DataOverHttps](INFO): SBD MOMSN=16342654
2021-12-10T19:00:38.689Z,1639162838.689 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T19:00:38.689Z,1639162838.689 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T19:00:38.689Z,1639162838.689 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T19:04:45.540Z,1639163085.540 [NAL9602](INFO): SBD MO Status=2, MOMSN=17878, MT Status=2, MTMSN=0
2021-12-10T19:04:45.540Z,1639163085.540 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-12-10T19:05:09.362Z,1639163109.362 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T19:05:39.315Z,1639163139.315 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T19:05:39.316Z,1639163139.316 [Default:CheckIn:C.Wait] Stopped
2021-12-10T19:05:39.316Z,1639163139.316 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T19:05:39.316Z,1639163139.316 [Default:CheckIn:D] Running Loop=1
2021-12-10T19:05:39.691Z,1639163139.691 [Default:CheckIn:D] Stopped
2021-12-10T19:05:39.691Z,1639163139.691 [Default:CheckIn:E] Running Loop=1
2021-12-10T19:05:40.056Z,1639163140.056 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T19:05:40.070Z,1639163140.070 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.964823 min 
2021-12-10T19:05:40.070Z,1639163140.070 [Default:CheckIn:E] Stopped
2021-12-10T19:05:40.070Z,1639163140.070 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T19:05:40.070Z,1639163140.070 [Default:CheckIn] Stopped
2021-12-10T19:05:40.070Z,1639163140.070 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T19:05:40.091Z,1639163140.091 [Default:CheckIn](INFO): Running loop #7
2021-12-10T19:05:40.091Z,1639163140.091 [Default:CheckIn] Running Loop=7
2021-12-10T19:05:40.091Z,1639163140.091 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T19:05:40.091Z,1639163140.091 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T19:05:42.078Z,1639163142.078 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190541.00,A,3648.16294,N,12147.28551,W,0.292,0.00,101221,,,A*77
2021-12-10T19:05:42.080Z,1639163142.080 [NAL9602](INFO): GPS fix at 20211210T190541: (36.802716, -121.788092)
2021-12-10T19:05:42.093Z,1639163142.093 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T19:05:42.093Z,1639163142.093 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T19:05:42.912Z,1639163142.912 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T19:05:42.912Z,1639163142.912 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T19:05:42.912Z,1639163142.912 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T19:06:12.807Z,1639163172.807 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-12-10T19:06:12.891Z,1639163172.891 [NAL9602](ERROR): received: 
+CSQ:0

OK878, 2, 0, 0, 0

OK
2021-12-10T19:10:43.567Z,1639163443.567 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T19:10:43.567Z,1639163443.567 [Default:CheckIn:C.Wait] Stopped
2021-12-10T19:10:43.567Z,1639163443.567 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T19:10:43.567Z,1639163443.567 [Default:CheckIn:D] Running Loop=1
2021-12-10T19:10:43.992Z,1639163443.992 [Default:CheckIn:D] Stopped
2021-12-10T19:10:43.993Z,1639163443.993 [Default:CheckIn:E] Running Loop=1
2021-12-10T19:10:44.349Z,1639163444.349 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-12-10T19:10:44.362Z,1639163444.362 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.036515 min 
2021-12-10T19:10:44.362Z,1639163444.362 [Default:CheckIn:E] Stopped
2021-12-10T19:10:44.362Z,1639163444.362 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T19:10:44.362Z,1639163444.362 [Default:CheckIn] Stopped
2021-12-10T19:10:44.363Z,1639163444.363 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T19:10:44.363Z,1639163444.363 [Default:CheckIn](INFO): Running loop #8
2021-12-10T19:10:44.363Z,1639163444.363 [Default:CheckIn] Running Loop=8
2021-12-10T19:10:44.363Z,1639163444.363 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T19:10:44.363Z,1639163444.363 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T19:10:46.779Z,1639163446.779 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191046.00,A,3648.16677,N,12147.28713,W,0.175,0.00,101221,,,A*73
2021-12-10T19:10:46.782Z,1639163446.782 [NAL9602](INFO): GPS fix at 20211210T191046: (36.802779, -121.788119)
2021-12-10T19:10:46.843Z,1639163446.843 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T19:10:46.844Z,1639163446.844 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T19:10:54.214Z,1639163454.214 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0070.lzma
2021-12-10T19:10:55.217Z,1639163455.217 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0070.lzma.bak
2021-12-10T19:10:55.217Z,1639163455.217 [DataOverHttps](INFO): SBD MOMSN=16342863
2021-12-10T19:11:11.854Z,1639163471.854 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20211210T162424/Courier0073.lzma
2021-12-10T19:11:12.857Z,1639163472.857 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0073.lzma.bak
2021-12-10T19:11:12.857Z,1639163472.857 [DataOverHttps](INFO): SBD MOMSN=16342869
2021-12-10T19:11:19.536Z,1639163479.536 [NAL9602](INFO): Not Powering down - fast GPS
2021-12-10T19:11:29.651Z,1639163489.651 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20211210T162424/Express0071.lzma
2021-12-10T19:11:30.653Z,1639163490.653 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0071.lzma.bak
2021-12-10T19:11:30.653Z,1639163490.653 [DataOverHttps](INFO): SBD MOMSN=16342877
2021-12-10T19:11:47.359Z,1639163507.359 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20211210T162424/Express0074.lzma
2021-12-10T19:11:48.361Z,1639163508.361 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0074.lzma.bak
2021-12-10T19:11:48.361Z,1639163508.361 [DataOverHttps](INFO): SBD MOMSN=16342883
2021-12-10T19:11:49.437Z,1639163509.437 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T19:11:49.437Z,1639163509.437 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T19:11:49.438Z,1639163509.438 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T19:16:50.027Z,1639163810.027 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-12-10T19:16:50.028Z,1639163810.028 [Default:CheckIn:C.Wait] Stopped
2021-12-10T19:16:50.028Z,1639163810.028 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-12-10T19:16:50.029Z,1639163810.029 [Default:CheckIn:D] Running Loop=1
2021-12-10T19:16:50.473Z,1639163810.473 [Default:CheckIn:D] Stopped
2021-12-10T19:16:50.473Z,1639163810.473 [Default:CheckIn:E] Running Loop=1
2021-12-10T19:16:50.844Z,1639163810.844 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.144519 min 
2021-12-10T19:16:50.844Z,1639163810.844 [Default:CheckIn:E] Stopped
2021-12-10T19:16:50.845Z,1639163810.845 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-12-10T19:16:50.845Z,1639163810.845 [Default:CheckIn] Stopped
2021-12-10T19:16:50.845Z,1639163810.845 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-12-10T19:16:50.845Z,1639163810.845 [Default:CheckIn](INFO): Running loop #9
2021-12-10T19:16:50.845Z,1639163810.845 [Default:CheckIn] Running Loop=9
2021-12-10T19:16:50.845Z,1639163810.845 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-12-10T19:16:50.845Z,1639163810.845 [Default:CheckIn:Read_GPS] Running Loop=1
2021-12-10T19:16:52.846Z,1639163812.846 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191652.00,A,3648.16587,N,12147.28577,W,0.369,0.00,101221,,,A*73
2021-12-10T19:16:52.848Z,1639163812.848 [NAL9602](INFO): GPS fix at 20211210T191652: (36.802765, -121.788096)
2021-12-10T19:16:52.889Z,1639163812.889 [Default:CheckIn:Read_GPS] Stopped
2021-12-10T19:16:52.889Z,1639163812.889 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-12-10T19:17:00.522Z,1639163820.522 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20211210T162424/Courier0076.lzma
2021-12-10T19:17:01.525Z,1639163821.525 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Courier0076.lzma.bak
2021-12-10T19:17:01.525Z,1639163821.525 [DataOverHttps](INFO): SBD MOMSN=16343001
2021-12-10T19:17:18.382Z,1639163838.382 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20211210T162424/Express0077.lzma
2021-12-10T19:17:19.385Z,1639163839.385 [DataOverHttps](INFO): Moved sent file to Logs/20211210T162424/Express0077.lzma.bak
2021-12-10T19:17:19.385Z,1639163839.385 [DataOverHttps](INFO): SBD MOMSN=16343007
2021-12-10T19:17:20.771Z,1639163840.771 [Default:CheckIn:Read_Iridium] Stopped
2021-12-10T19:17:20.771Z,1639163840.771 [Default:CheckIn:C.Wait] Running Loop=1
2021-12-10T19:17:20.771Z,1639163840.771 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-12-10T19:17:23.548Z,1639163843.548 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-12-10T19:17:23.631Z,1639163843.631 [NAL9602](ERROR): received: 
+CSQ:0

OK878, 2, 0, 0, 0

OK
2021-12-10T19:19:13.471Z,1639163953.471 [RDI_Pathfinder](ERROR): only read 3 of 4 d