2021-09-29T19:07:40.538Z,1632942460.538 [Supervisor](DEBUG): Initializing supervisor.
2021-09-29T19:07:40.543Z,1632942460.543 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-09-29T19:07:40.544Z,1632942460.544 [SyncHandler](INFO): Protected caller Thread ID is 1732
2021-09-29T19:07:40.544Z,1632942460.544 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-09-29T19:07:40.545Z,1632942460.545 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-09-29T19:07:40.545Z,1632942460.545 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1733
2021-09-29T19:07:40.550Z,1632942460.550 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-09-29T19:07:40.570Z,1632942460.570 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-09-29T19:07:40.571Z,1632942460.571 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-09-29T19:07:40.572Z,1632942460.572 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1734
2021-09-29T19:07:40.574Z,1632942460.574 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-09-29T19:07:40.575Z,1632942460.575 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-09-29T19:07:40.575Z,1632942460.575 [logger ThreadHandler](INFO): Protected caller Thread ID is 1735
2021-09-29T19:07:40.579Z,1632942460.579 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-09-29T19:07:40.579Z,1632942460.579 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-09-29T19:07:40.581Z,1632942460.581 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-09-29T19:07:41.047Z,1632942461.047 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-09-29T19:07:41.047Z,1632942461.047 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-09-29T19:07:41.203Z,1632942461.203 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-09-29T19:07:41.204Z,1632942461.204 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-09-29T19:07:41.287Z,1632942461.287 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-09-29T19:07:41.534Z,1632942461.534 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-09-29T19:07:41.535Z,1632942461.535 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-09-29T19:07:41.615Z,1632942461.615 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-09-29T19:07:41.714Z,1632942461.714 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-09-29T19:07:41.715Z,1632942461.715 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-09-29T19:07:42.091Z,1632942462.091 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-09-29T19:07:42.091Z,1632942462.091 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-09-29T19:07:42.223Z,1632942462.223 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-09-29T19:07:42.223Z,1632942462.223 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-09-29T19:07:42.816Z,1632942462.816 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-09-29T19:07:42.817Z,1632942462.817 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-09-29T19:07:43.032Z,1632942463.032 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-09-29T19:07:43.033Z,1632942463.033 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-09-29T19:07:43.454Z,1632942463.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-09-29T19:07:43.454Z,1632942463.454 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-09-29T19:07:43.717Z,1632942463.717 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-09-29T19:07:43.718Z,1632942463.718 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-09-29T19:07:43.832Z,1632942463.832 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-09-29T19:07:43.833Z,1632942463.833 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-09-29T19:07:44.567Z,1632942464.567 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-09-29T19:07:44.568Z,1632942464.568 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-09-29T19:07:44.954Z,1632942464.954 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-09-29T19:07:44.955Z,1632942464.955 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-09-29T19:07:45.184Z,1632942465.184 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-09-29T19:07:45.186Z,1632942465.186 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-triton/
2021-09-29T19:07:45.187Z,1632942465.187 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/vehicle.cfg
2021-09-29T19:07:45.401Z,1632942465.401 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/secure.cfg
2021-09-29T19:07:45.486Z,1632942465.486 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Science.cfg
2021-09-29T19:07:45.645Z,1632942465.645 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Simulator.cfg
2021-09-29T19:07:45.785Z,1632942465.785 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Battery.cfg
2021-09-29T19:07:46.237Z,1632942466.237 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-09-29T19:07:46.238Z,1632942466.238 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/logger.cfg
2021-09-29T19:07:46.502Z,1632942466.502 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Servo.cfg
2021-09-29T19:07:46.839Z,1632942466.839 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Navigation.cfg
2021-09-29T19:07:46.937Z,1632942466.937 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Sensor.cfg
2021-09-29T19:07:47.094Z,1632942467.094 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Control.cfg
2021-09-29T19:07:47.197Z,1632942467.197 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/BIT.cfg
2021-09-29T19:07:47.294Z,1632942467.294 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-09-29T19:07:47.309Z,1632942467.309 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-09-29T19:07:47.326Z,1632942467.326 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-09-29T19:07:47.327Z,1632942467.327 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-09-29T19:07:47.459Z,1632942467.459 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-09-29T19:07:47.460Z,1632942467.460 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-09-29T19:07:47.537Z,1632942467.537 [VerticalControl](DEBUG): Construct VerticalControl.
2021-09-29T19:07:47.602Z,1632942467.602 [VerticalControl] Loaded
2021-09-29T19:07:47.602Z,1632942467.602 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-09-29T19:07:47.605Z,1632942467.605 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-09-29T19:07:47.645Z,1632942467.645 [HorizontalControl] Loaded
2021-09-29T19:07:47.645Z,1632942467.645 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-09-29T19:07:47.648Z,1632942467.648 [SpeedControl](DEBUG): Construct SpeedControl.
2021-09-29T19:07:47.652Z,1632942467.652 [SpeedControl] Loaded
2021-09-29T19:07:47.652Z,1632942467.652 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-09-29T19:07:47.654Z,1632942467.654 [LoopControl](DEBUG): Construct LoopControl.
2021-09-29T19:07:47.655Z,1632942467.655 [LoopControl] Loaded
2021-09-29T19:07:47.655Z,1632942467.655 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-09-29T19:07:47.656Z,1632942467.656 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-09-29T19:07:47.656Z,1632942467.656 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-09-29T19:07:47.848Z,1632942467.848 [BuoyancyServo] Loaded
2021-09-29T19:07:47.848Z,1632942467.848 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-09-29T19:07:47.869Z,1632942467.869 [ElevatorServo] Loaded
2021-09-29T19:07:47.869Z,1632942467.869 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-09-29T19:07:47.889Z,1632942467.889 [MassServo] Loaded
2021-09-29T19:07:47.889Z,1632942467.889 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-09-29T19:07:47.908Z,1632942467.908 [RudderServo] Loaded
2021-09-29T19:07:47.908Z,1632942467.908 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-09-29T19:07:47.923Z,1632942467.923 [ThrusterHE] Loaded
2021-09-29T19:07:47.924Z,1632942467.924 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2021-09-29T19:07:47.924Z,1632942467.924 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-09-29T19:07:47.925Z,1632942467.925 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-09-29T19:07:47.990Z,1632942467.990 [DepthRateCalculator] Loaded
2021-09-29T19:07:47.990Z,1632942467.990 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-09-29T19:07:47.995Z,1632942467.995 [PitchRateCalculator] Loaded
2021-09-29T19:07:47.995Z,1632942467.995 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-09-29T19:07:48.006Z,1632942468.006 [SpeedCalculator] Loaded
2021-09-29T19:07:48.006Z,1632942468.006 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-09-29T19:07:48.021Z,1632942468.021 [TempGradientCalculator] Loaded
2021-09-29T19:07:48.021Z,1632942468.021 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-09-29T19:07:48.026Z,1632942468.026 [YawRateCalculator] Loaded
2021-09-29T19:07:48.026Z,1632942468.026 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-09-29T19:07:48.044Z,1632942468.044 [ElevatorOffsetCalculator] Loaded
2021-09-29T19:07:48.044Z,1632942468.044 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-09-29T19:07:48.045Z,1632942468.045 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-09-29T19:07:48.045Z,1632942468.045 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-09-29T19:07:48.150Z,1632942468.150 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-09-29T19:07:48.150Z,1632942468.150 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-09-29T19:07:48.164Z,1632942468.164 [NavChart] Loaded
2021-09-29T19:07:48.165Z,1632942468.165 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-09-29T19:07:48.170Z,1632942468.170 [UniversalFixResidualReporter] Loaded
2021-09-29T19:07:48.171Z,1632942468.171 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-09-29T19:07:48.171Z,1632942468.171 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-09-29T19:07:48.172Z,1632942468.172 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-09-29T19:07:48.698Z,1632942468.698 [AHRS_M2] Loaded
2021-09-29T19:07:48.698Z,1632942468.698 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-09-29T19:07:48.730Z,1632942468.730 [BackseatComponent] Loaded
2021-09-29T19:07:48.730Z,1632942468.730 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2021-09-29T19:07:48.731Z,1632942468.731 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 4086D4E0
2021-09-29T19:07:48.732Z,1632942468.732 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 1817
2021-09-29T19:07:48.734Z,1632942468.734 [LcmUniversalReporter] Loaded
2021-09-29T19:07:48.735Z,1632942468.735 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2021-09-29T19:07:49.582Z,1632942469.582 [BPC1] Loaded
2021-09-29T19:07:49.583Z,1632942469.583 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-09-29T19:07:49.656Z,1632942469.656 [DataOverHttps] Loaded
2021-09-29T19:07:49.657Z,1632942469.657 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-09-29T19:07:49.658Z,1632942469.658 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4089D4E0
2021-09-29T19:07:49.658Z,1632942469.658 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1818
2021-09-29T19:07:49.679Z,1632942469.679 [Depth_Keller] Loaded
2021-09-29T19:07:49.679Z,1632942469.679 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-09-29T19:07:49.684Z,1632942469.684 [DropWeight] Loaded
2021-09-29T19:07:49.684Z,1632942469.684 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-09-29T19:07:49.747Z,1632942469.747 [NAL9602] Loaded
2021-09-29T19:07:49.747Z,1632942469.747 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-09-29T19:07:49.777Z,1632942469.777 [Onboard] Loaded
2021-09-29T19:07:49.778Z,1632942469.778 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-09-29T19:07:49.779Z,1632942469.779 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408CD4E0
2021-09-29T19:07:49.779Z,1632942469.779 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 1819
2021-09-29T19:07:49.793Z,1632942469.793 [Power24vConverter] Loaded
2021-09-29T19:07:49.793Z,1632942469.793 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-09-29T19:07:49.807Z,1632942469.807 [Radio_Surface] Loaded
2021-09-29T19:07:49.807Z,1632942469.807 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-09-29T19:07:49.808Z,1632942469.808 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408FD4E0
2021-09-29T19:07:49.809Z,1632942469.809 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1820
2021-09-29T19:07:49.809Z,1632942469.809 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-09-29T19:07:49.810Z,1632942469.810 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-09-29T19:07:49.900Z,1632942469.900 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-09-29T19:07:49.900Z,1632942469.900 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-09-29T19:07:50.049Z,1632942470.049 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-09-29T19:07:50.050Z,1632942470.050 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-09-29T19:07:50.094Z,1632942470.094 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-09-29T19:07:50.095Z,1632942470.095 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-09-29T19:07:50.335Z,1632942470.335 [CTD_Seabird] Loaded
2021-09-29T19:07:50.335Z,1632942470.335 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-09-29T19:07:50.336Z,1632942470.336 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A1D4E0
2021-09-29T19:07:50.337Z,1632942470.337 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1821
2021-09-29T19:07:50.370Z,1632942470.370 [ESPComponent] Loaded
2021-09-29T19:07:50.371Z,1632942470.371 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2021-09-29T19:07:50.392Z,1632942470.392 [PAR_Licor] Loaded
2021-09-29T19:07:50.392Z,1632942470.392 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-09-29T19:07:50.425Z,1632942470.425 [WetLabsBB2FL] Loaded
2021-09-29T19:07:50.426Z,1632942470.426 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-09-29T19:07:50.427Z,1632942470.427 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A4D4E0
2021-09-29T19:07:50.427Z,1632942470.427 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1822
2021-09-29T19:07:50.428Z,1632942470.428 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-09-29T19:07:50.429Z,1632942470.429 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-09-29T19:07:50.854Z,1632942470.854 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-09-29T19:07:50.855Z,1632942470.855 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-09-29T19:07:51.370Z,1632942471.370 [SBIT](DEBUG): Construct Startup Built In Test.
2021-09-29T19:07:51.379Z,1632942471.379 [SBIT] Loaded
2021-09-29T19:07:51.380Z,1632942471.380 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-09-29T19:07:51.383Z,1632942471.383 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-09-29T19:07:51.396Z,1632942471.396 [IBIT] Loaded
2021-09-29T19:07:51.396Z,1632942471.396 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-09-29T19:07:51.402Z,1632942471.402 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-09-29T19:07:51.509Z,1632942471.509 [CBIT] Loaded
2021-09-29T19:07:51.510Z,1632942471.510 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-09-29T19:07:51.510Z,1632942471.510 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-09-29T19:07:51.516Z,1632942471.516 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-09-29T19:07:51.519Z,1632942471.519 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-09-29T19:07:51.530Z,1632942471.530 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-09-29T19:07:51.531Z,1632942471.531 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B354E0
2021-09-29T19:07:51.531Z,1632942471.531 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1823
2021-09-29T19:07:51.536Z,1632942471.536 [Supervisor](INFO): Main Thread ID is 835
2021-09-29T19:07:51.536Z,1632942471.536 [Supervisor](DEBUG): Running supervisor.
2021-09-29T19:07:51.537Z,1632942471.537 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1824
2021-09-29T19:07:51.539Z,1632942471.539 [controlThread ThreadHandler](INFO): Handler Thread ID is 1825
2021-09-29T19:07:51.540Z,1632942471.540 [controlThread](DEBUG): Initializing ControlThread
2021-09-29T19:07:51.541Z,1632942471.541 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-09-29T19:07:51.543Z,1632942471.543 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-09-29T19:07:51.543Z,1632942471.543 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-09-29T19:07:51.544Z,1632942471.544 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-09-29T19:07:51.545Z,1632942471.545 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-09-29T19:07:51.546Z,1632942471.546 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-09-29T19:07:51.546Z,1632942471.546 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-09-29T19:07:51.546Z,1632942471.546 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-09-29T19:07:51.547Z,1632942471.547 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-09-29T19:07:51.548Z,1632942471.548 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-09-29T19:07:51.549Z,1632942471.549 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-09-29T19:07:51.549Z,1632942471.549 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-09-29T19:07:51.556Z,1632942471.556 [SBIT](INFO): Initialize SBIT Component.
2021-09-29T19:07:51.557Z,1632942471.557 [SBIT](IMPORTANT): git: 2021-09-29
2021-09-29T19:07:51.557Z,1632942471.557 [SBIT](INFO): git hash: d0bedea221735b48726a30f35f8acb1d414c6dbf
2021-09-29T19:07:51.557Z,1632942471.557 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-09-29T19:07:51.558Z,1632942471.558 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2021-09-29T19:07:51.560Z,1632942471.560 [SBIT](INFO): Beginning SBIT in 62.000000 seconds.
2021-09-29T19:07:51.560Z,1632942471.560 [IBIT](INFO): Initialize IBIT Component.
2021-09-29T19:07:51.561Z,1632942471.561 [CBIT](DEBUG): Initialize CBIT Component.
2021-09-29T19:07:51.562Z,1632942471.562 [logger ThreadHandler](INFO): Handler Thread ID is 1826
2021-09-29T19:07:51.576Z,1632942471.576 [CBIT](DEBUG): Initialized mux pins.
2021-09-29T19:07:51.576Z,1632942471.576 [CBIT](DEBUG): Initializing the watchdog timer.
2021-09-29T19:07:51.580Z,1632942471.580 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 1827
2021-09-29T19:07:51.588Z,1632942471.588 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1828
2021-09-29T19:07:51.589Z,1632942471.589 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-09-29T19:07:51.596Z,1632942471.596 [Onboard ThreadHandler](INFO): Handler Thread ID is 1829
2021-09-29T19:07:51.600Z,1632942471.600 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-09-29T19:07:51.601Z,1632942471.601 [CBIT](DEBUG): Initializing heartbeat.
2021-09-29T19:07:51.617Z,1632942471.617 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1830
2021-09-29T19:07:51.632Z,1632942471.632 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1831
2021-09-29T19:07:51.633Z,1632942471.633 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-09-29T19:07:51.638Z,1632942471.638 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1833
2021-09-29T19:07:51.640Z,1632942471.640 [WetLabsBB2FL](INFO): Powering up
2021-09-29T19:07:51.641Z,1632942471.641 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1835
2021-09-29T19:07:51.645Z,1632942471.645 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-09-29T19:07:51.645Z,1632942471.645 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-09-29T19:07:51.645Z,1632942471.645 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-09-29T19:07:51.646Z,1632942471.646 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-09-29T19:07:51.646Z,1632942471.646 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-09-29T19:07:51.646Z,1632942471.646 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-09-29T19:07:51.646Z,1632942471.646 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-09-29T19:07:51.646Z,1632942471.646 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-09-29T19:07:51.646Z,1632942471.646 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-09-29T19:07:51.647Z,1632942471.647 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-09-29T19:07:51.647Z,1632942471.647 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-09-29T19:07:51.647Z,1632942471.647 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-09-29T19:07:51.647Z,1632942471.647 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-09-29T19:07:51.647Z,1632942471.647 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-09-29T19:07:51.647Z,1632942471.647 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-09-29T19:07:51.648Z,1632942471.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-09-29T19:07:51.672Z,1632942471.672 [CBIT](DEBUG): Deactivating GF circuits.
2021-09-29T19:07:51.672Z,1632942471.672 [CBIT](DEBUG): Deactivating emergency mode.
2021-09-29T19:07:51.708Z,1632942471.708 [CBIT](DEBUG): Backplane powered.
2021-09-29T19:07:51.709Z,1632942471.709 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-09-29T19:07:51.723Z,1632942471.723 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-09-29T19:07:51.755Z,1632942471.755 [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-09-29T19:07:51.755Z,1632942471.755 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-09-29T19:07:51.826Z,1632942471.826 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-09-29T19:07:51.827Z,1632942471.827 [Default:A.Wait](DEBUG): Construct Wait.
2021-09-29T19:07:51.846Z,1632942471.846 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-09-29T19:07:51.877Z,1632942471.877 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-09-29T19:07:51.896Z,1632942471.896 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-09-29T19:07:51.902Z,1632942471.902 [Default:E.Execute](DEBUG): Construct Execute.
2021-09-29T19:07:51.926Z,1632942471.926 [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-09-29T19:07:51.931Z,1632942471.931 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2021-09-29T19:07:51.957Z,1632942471.957 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-09-29T19:07:52.020Z,1632942472.020 [Radio_Surface](INFO): Powering up
2021-09-29T19:07:52.029Z,1632942472.029 [Depth_Keller](ERROR): Pressure reading out of range: 962.881653 decibar
2021-09-29T19:07:52.030Z,1632942472.030 [Power24vConverter](INFO): Powering up.
2021-09-29T19:07:52.042Z,1632942472.042 [DepthRateCalculator](ERROR): Depth measurement is not active
2021-09-29T19:07:52.086Z,1632942472.086 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-09-29T19:07:52.092Z,1632942472.092 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-09-29T19:07:52.093Z,1632942472.093 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-09-29T19:07:52.100Z,1632942472.100 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-09-29T19:07:52.101Z,1632942472.101 [MassServo](DEBUG): Initializing EZServoServo.
2021-09-29T19:07:52.108Z,1632942472.108 [MassServo](DEBUG): Initializing MassServo.
2021-09-29T19:07:52.109Z,1632942472.109 [RudderServo](DEBUG): Initializing EZServoServo.
2021-09-29T19:07:52.116Z,1632942472.116 [RudderServo](DEBUG): Initializing RudderServo.
2021-09-29T19:07:52.117Z,1632942472.117 [ThrusterHE](DEBUG): Initializing EZServoServo.
2021-09-29T19:07:52.124Z,1632942472.124 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2021-09-29T19:07:53.108Z,1632942473.108 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-09-29T19:07:53.109Z,1632942473.109 [RudderServo](FAULT): Rudder failed to initialize
2021-09-29T19:07:53.109Z,1632942473.109 [RudderServo] Communications Fault, FailCount= 1
2021-09-29T19:07:53.109Z,1632942473.109 [RudderServo](ERROR): Communications Fault
2021-09-29T19:07:53.131Z,1632942473.131 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-09-29T19:07:53.377Z,1632942473.377 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-09-29T19:07:53.377Z,1632942473.377 [RudderServo](INFO): Powering down
2021-09-29T19:07:53.748Z,1632942473.748 [WetLabsBB2FL](INFO): Powering down
2021-09-29T19:07:53.977Z,1632942473.977 [RudderServo](DEBUG): Initializing EZServoServo.
2021-09-29T19:07:54.097Z,1632942474.097 [RudderServo](DEBUG): Initializing RudderServo.
2021-09-29T19:07:54.101Z,1632942474.101 [CBIT](INFO): Clearing failed state for component RudderServo
2021-09-29T19:07:54.101Z,1632942474.101 [RudderServo] No Fault, FailCount= 1
2021-09-29T19:07:58.664Z,1632942478.664 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2021-09-29T19:08:19.818Z,1632942499.818 [NAL9602](INFO): Powering up NAL9602
2021-09-29T19:08:30.734Z,1632942510.734 [NAL9602](INFO): NAL9602 initialized
2021-09-29T19:08:52.575Z,1632942532.575 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T19:08:52.575Z,1632942532.575 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T19:08:54.179Z,1632942534.179 [SBIT](IMPORTANT): Beginning Startup BIT
2021-09-29T19:08:54.184Z,1632942534.184 [CBIT](IMPORTANT): Beginning ground fault scan
2021-09-29T19:09:05.102Z,1632942545.102 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004681
CHAN A1 (24V): -0.009064
CHAN A2 (12V): -0.003637
CHAN A3 (5V): -0.002274
CHAN B0 (3.3V): -0.000237
CHAN B1 (3.15aV): -0.000805
CHAN B2 (3.15bV): -0.000788
CHAN B3 (GND): 0.000306
OPEN: 0.003564
Full Scale: +/- 1 mA
2021-09-29T19:09:09.519Z,1632942549.519 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T19:09:09.519Z,1632942549.519 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T19:09:48.325Z,1632942588.325 [SBIT](IMPORTANT): SBIT PASSED
2021-09-29T19:09:48.325Z,1632942588.325 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-09-29T19:09:48.326Z,1632942588.326 [SBIT](IMPORTANT): AHRS_M2.loadAtStartup=1 bool;

2021-09-29T19:09:48.326Z,1632942588.326 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=8 count;

2021-09-29T19:09:48.326Z,1632942588.326 [SBIT](IMPORTANT): BPC1.batterySamplingInterval=1 minute;

2021-09-29T19:09:48.326Z,1632942588.326 [SBIT](IMPORTANT): BPC1.batteryStickCommsTimeout=10 second;

2021-09-29T19:09:48.326Z,1632942588.326 [SBIT](IMPORTANT): BackseatComponent.loadAtStartup=1 bool;

2021-09-29T19:09:48.326Z,1632942588.326 [SBIT](IMPORTANT): CBIT.gf24Offset=-18.106 microampere;

2021-09-29T19:09:48.326Z,1632942588.326 [SBIT](IMPORTANT): CBIT.stopDepth=295 meter;

2021-09-29T19:09:48.327Z,1632942588.327 [SBIT](IMPORTANT): DAT.loadAtStartup=0 bool;

2021-09-29T19:09:48.327Z,1632942588.327 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2021-09-29T19:09:48.327Z,1632942588.327 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2021-09-29T19:09:48.327Z,1632942588.327 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water;

2021-09-29T19:09:48.327Z,1632942588.327 [SBIT](IMPORTANT): Express linearApproximation platform_pitch_angle 5.000000 degree;

2021-09-29T19:09:48.327Z,1632942588.327 [SBIT](IMPORTANT): Express none platform_roll_angle;

2021-09-29T19:09:48.327Z,1632942588.327 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=164.896380 cubic_centimeter;

2021-09-29T19:09:48.328Z,1632942588.328 [SBIT](IMPORTANT): VerticalControl.massDefault=10.537965 millimeter;

2021-09-29T19:09:48.719Z,1632942588.719 [MissionManager](IMPORTANT): Started mission Startup
2021-09-29T19:09:48.719Z,1632942588.719 [Startup] Running Loop=1
2021-09-29T19:09:48.719Z,1632942588.719 [Startup](DEBUG): Aggregate::initialize Startup
2021-09-29T19:09:48.719Z,1632942588.719 [Startup:A.GoToSurface] Running Loop=1
2021-09-29T19:09:48.720Z,1632942588.720 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-09-29T19:09:48.720Z,1632942588.720 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-09-29T19:09:48.721Z,1632942588.721 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-09-29T19:09:48.721Z,1632942588.721 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-09-29T19:09:48.722Z,1632942588.722 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-09-29T19:09:48.722Z,1632942588.722 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-09-29T19:09:48.748Z,1632942588.748 [Startup:StartupSatComms] Running Loop=1
2021-09-29T19:09:48.748Z,1632942588.748 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-09-29T19:09:48.748Z,1632942588.748 [Startup:StartupSatComms:A] Running Loop=1
2021-09-29T19:09:49.118Z,1632942589.118 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-09-29T19:10:48.922Z,1632942648.922 [Startup:StartupSatComms:A](INFO): Timed out from 2021-09-29T19:09:48.7Z
2021-09-29T19:10:48.922Z,1632942648.922 [Startup:StartupSatComms:A] Stopped
2021-09-29T19:10:48.922Z,1632942648.922 [Startup:StartupSatComms:B] Running Loop=1
2021-09-29T19:10:49.315Z,1632942649.315 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-09-29T19:10:51.937Z,1632942651.937 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-09-29T19:10:51.937Z,1632942651.937 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:10:51.948Z,1632942651.948 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:10:52.359Z,1632942652.359 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:10:52.362Z,1632942652.362 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-09-29T19:11:29.714Z,1632942689.714 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004451
2021-09-29T19:11:39.676Z,1632942699.676 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210929T183020/Courier0022.lzma
2021-09-29T19:11:40.678Z,1632942700.678 [DataOverHttps](INFO): Moved sent file to Logs/20210929T183020/Courier0022.lzma.bak
2021-09-29T19:11:40.678Z,1632942700.678 [DataOverHttps](INFO): SBD MOMSN=15950433
2021-09-29T19:11:48.944Z,1632942708.944 [Startup:StartupSatComms:B](INFO): Timed out from 2021-09-29T19:10:48.9Z
2021-09-29T19:11:48.944Z,1632942708.944 [Startup:StartupSatComms:B] Stopped
2021-09-29T19:11:48.945Z,1632942708.945 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-09-29T19:11:48.945Z,1632942708.945 [Startup:StartupSatComms] Stopped
2021-09-29T19:11:48.945Z,1632942708.945 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-09-29T19:11:48.946Z,1632942708.946 [Startup](INFO): Completed Startup
2021-09-29T19:11:48.946Z,1632942708.946 [MissionManager](INFO): Startup is completed.
2021-09-29T19:11:48.946Z,1632942708.946 [MissionManager](INFO): Uninitializing Mission Startup
2021-09-29T19:11:48.946Z,1632942708.946 [Startup] Stopped
2021-09-29T19:11:48.946Z,1632942708.946 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-09-29T19:11:48.946Z,1632942708.946 [Startup:A.GoToSurface] Stopped
2021-09-29T19:11:48.946Z,1632942708.946 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-09-29T19:11:49.359Z,1632942709.359 [MissionManager](IMPORTANT): Started mission Default
2021-09-29T19:11:49.359Z,1632942709.359 [Default] Running Loop=1
2021-09-29T19:11:49.359Z,1632942709.359 [Default](DEBUG): Aggregate::initialize Default
2021-09-29T19:11:49.360Z,1632942709.360 [Default:B.GoToSurface] Running Loop=1
2021-09-29T19:11:49.360Z,1632942709.360 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-09-29T19:11:49.360Z,1632942709.360 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-09-29T19:11:49.360Z,1632942709.360 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-09-29T19:11:49.361Z,1632942709.361 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-09-29T19:11:49.361Z,1632942709.361 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-09-29T19:11:49.362Z,1632942709.362 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-09-29T19:11:49.362Z,1632942709.362 [Default:A.Wait] Running Loop=1
2021-09-29T19:11:49.362Z,1632942709.362 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-09-29T19:11:56.475Z,1632942716.475 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20210929T190740/Courier0000.lzma
2021-09-29T19:11:57.477Z,1632942717.477 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0000.lzma.bak
2021-09-29T19:11:57.478Z,1632942717.478 [DataOverHttps](INFO): SBD MOMSN=15950435
2021-09-29T19:12:02.667Z,1632942722.667 [Default:A.Wait](INFO): Done Waiting.
2021-09-29T19:12:02.667Z,1632942722.667 [Default:A.Wait] Stopped
2021-09-29T19:12:02.667Z,1632942722.667 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T19:12:03.070Z,1632942723.070 [Default:CheckIn] Running Loop=1
2021-09-29T19:12:03.070Z,1632942723.070 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T19:12:03.071Z,1632942723.071 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T19:12:03.478Z,1632942723.478 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-09-29T19:13:33.597Z,1632942813.597 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T19:13:53.026Z,1632942833.026 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-09-29T19:13:53.026Z,1632942833.026 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:13:53.037Z,1632942833.037 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:13:53.429Z,1632942833.429 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:13:53.429Z,1632942833.429 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-09-29T19:16:54.026Z,1632943014.026 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-09-29T19:16:54.026Z,1632943014.026 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:16:54.037Z,1632943014.037 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:16:54.433Z,1632943014.433 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:16:54.433Z,1632943014.433 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-09-29T19:17:03.435Z,1632943023.435 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-09-29T19:12:03.1Z
2021-09-29T19:17:03.435Z,1632943023.435 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T19:17:03.435Z,1632943023.435 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T19:17:03.722Z,1632943023.722 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-09-29T19:17:12.439Z,1632943032.439 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210929T190740/Courier0004.lzma
2021-09-29T19:17:13.442Z,1632943033.442 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0004.lzma.bak
2021-09-29T19:17:13.442Z,1632943033.442 [DataOverHttps](INFO): SBD MOMSN=15950438
2021-09-29T19:17:28.947Z,1632943048.947 [DataOverHttps](INFO): Sending 184 bytes from file Logs/20210929T183020/Express0023.lzma
2021-09-29T19:17:29.950Z,1632943049.950 [DataOverHttps](INFO): Moved sent file to Logs/20210929T183020/Express0023.lzma.bak
2021-09-29T19:17:29.950Z,1632943049.950 [DataOverHttps](INFO): SBD MOMSN=15950440
2021-09-29T19:17:45.730Z,1632943065.730 [DataOverHttps](INFO): Sending 1050 bytes from file Logs/20210929T190740/Express0001.lzma
2021-09-29T19:17:46.730Z,1632943066.730 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0001.lzma.bak
2021-09-29T19:17:46.730Z,1632943066.730 [DataOverHttps](INFO): SBD MOMSN=15950444
2021-09-29T19:17:53.136Z,1632943073.136 [Power24vConverter](INFO): Powering down.
2021-09-29T19:18:02.128Z,1632943082.128 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20210929T190740/Express0005.lzma
2021-09-29T19:18:03.129Z,1632943083.129 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0005.lzma.bak
2021-09-29T19:18:03.130Z,1632943083.130 [DataOverHttps](INFO): SBD MOMSN=15950471
2021-09-29T19:18:04.852Z,1632943084.852 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T19:18:04.852Z,1632943084.852 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T19:18:04.852Z,1632943084.852 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T19:18:31.902Z,1632943111.902 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-09-29T19:18:31.902Z,1632943111.902 [NAL9602] Data Fault, FailCount= 1
2021-09-29T19:18:31.902Z,1632943111.902 [NAL9602](ERROR): Data Fault
2021-09-29T19:18:31.921Z,1632943111.921 [CBIT](ERROR): Data Fault in component: NAL9602
2021-09-29T19:18:32.301Z,1632943112.301 [NAL9602](INFO): Powering down
2021-09-29T19:18:33.131Z,1632943113.131 [CBIT](INFO): Clearing failed state for component NAL9602
2021-09-29T19:18:33.131Z,1632943113.131 [NAL9602] No Fault, FailCount= 1
2021-09-29T19:19:01.489Z,1632943141.489 [CommandLine](IMPORTANT): got command maintain control SpeedControl.propOmegaAction 300.000000 revolution_per_minute
2021-09-29T19:19:01.493Z,1632943141.493 [ComponentRegistry](DEBUG): SyncComponent "Maintain_SpeedControl.propOmegaAction" handled in the control thread.
2021-09-29T19:19:01.868Z,1632943141.868 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_SpeedControl.propOmegaAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2021-09-29T19:19:02.708Z,1632943142.708 [NAL9602](INFO): Powering up NAL9602
2021-09-29T19:19:13.534Z,1632943153.534 [NAL9602](INFO): NAL9602 initialized
2021-09-29T19:19:29.145Z,1632943169.145 [CommandLine](IMPORTANT): got command maintain control SpeedControl.propOmegaAction -300.000000 revolution_per_minute
2021-09-29T19:19:50.578Z,1632943190.578 [CommandLine](IMPORTANT): got command maintain control SpeedControl.propOmegaAction 300.000000 revolution_per_minute
2021-09-29T19:19:55.180Z,1632943195.180 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-09-29T19:19:55.180Z,1632943195.180 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:19:55.249Z,1632943195.249 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:19:55.701Z,1632943195.701 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:19:55.702Z,1632943195.702 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-09-29T19:20:10.417Z,1632943210.417 [CommandLine](IMPORTANT): got command maintain clear
2021-09-29T19:20:10.566Z,1632943210.566 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2021-09-29T19:22:56.235Z,1632943376.235 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-09-29T19:22:56.235Z,1632943376.235 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:22:56.300Z,1632943376.300 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:22:56.652Z,1632943376.652 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:22:56.652Z,1632943376.652 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-09-29T19:23:05.507Z,1632943385.507 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T19:23:05.507Z,1632943385.507 [Default:CheckIn:C.Wait] Stopped
2021-09-29T19:23:05.507Z,1632943385.507 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T19:23:05.507Z,1632943385.507 [Default:CheckIn:D] Running Loop=1
2021-09-29T19:23:05.935Z,1632943385.935 [Default:CheckIn:D] Stopped
2021-09-29T19:23:05.935Z,1632943385.935 [Default:CheckIn:E] Running Loop=1
2021-09-29T19:23:06.299Z,1632943386.299 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.276253 min 
2021-09-29T19:23:06.299Z,1632943386.299 [Default:CheckIn:E] Stopped
2021-09-29T19:23:06.299Z,1632943386.299 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T19:23:06.299Z,1632943386.299 [Default:CheckIn] Stopped
2021-09-29T19:23:06.299Z,1632943386.299 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T19:23:06.308Z,1632943386.308 [Default:CheckIn](INFO): Running loop #2
2021-09-29T19:23:06.308Z,1632943386.308 [Default:CheckIn] Running Loop=2
2021-09-29T19:23:06.308Z,1632943386.308 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T19:23:06.308Z,1632943386.308 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T19:23:40.427Z,1632943420.427 [CommandLine](IMPORTANT): got command failComponent
2021-09-29T19:23:40.427Z,1632943420.427 [CommandLine](IMPORTANT): Failed components:
2021-09-29T19:23:40.428Z,1632943420.428 [CommandLine](IMPORTANT): No failed Components.
2021-09-29T19:24:06.601Z,1632943446.601 [DataOverHttps](IMPORTANT): SBD MTMSN=20210929T192406
2021-09-29T19:24:16.716Z,1632943456.716 [DataOverHttps](INFO): Received command:strobe off
2021-09-29T19:24:16.757Z,1632943456.757 [CommandLine](IMPORTANT): got command strobe off
2021-09-29T19:24:16.757Z,1632943456.757 [CommandLine](IMPORTANT): Deactivating strobe
2021-09-29T19:25:57.219Z,1632943557.219 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-09-29T19:25:57.219Z,1632943557.219 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:25:57.243Z,1632943557.243 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:25:57.654Z,1632943557.654 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:25:57.654Z,1632943557.654 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-09-29T19:28:06.510Z,1632943686.510 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-09-29T19:23:06.3Z
2021-09-29T19:28:06.510Z,1632943686.510 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T19:28:06.510Z,1632943686.510 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T19:28:16.215Z,1632943696.215 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210929T190740/Courier0007.lzma
2021-09-29T19:28:17.218Z,1632943697.218 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0007.lzma.bak
2021-09-29T19:28:17.218Z,1632943697.218 [DataOverHttps](INFO): SBD MOMSN=15950477
2021-09-29T19:28:39.764Z,1632943719.764 [DataOverHttps](INFO): Sending 423 bytes from file Logs/20210929T190740/Express0008.lzma
2021-09-29T19:28:40.765Z,1632943720.765 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0008.lzma.bak
2021-09-29T19:28:40.766Z,1632943720.766 [DataOverHttps](INFO): SBD MOMSN=15950479
2021-09-29T19:28:42.490Z,1632943722.490 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T19:28:42.490Z,1632943722.490 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T19:28:42.491Z,1632943722.491 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T19:28:58.253Z,1632943738.253 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-09-29T19:28:58.253Z,1632943738.253 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:28:58.264Z,1632943738.264 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:28:58.647Z,1632943738.647 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:28:58.647Z,1632943738.647 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-09-29T19:29:15.194Z,1632943755.194 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-09-29T19:29:15.194Z,1632943755.194 [NAL9602] Data Fault, FailCount= 2
2021-09-29T19:29:15.194Z,1632943755.194 [NAL9602](ERROR): Data Fault
2021-09-29T19:29:15.216Z,1632943755.216 [CBIT](ERROR): Data Fault in component: NAL9602
2021-09-29T19:29:15.605Z,1632943755.605 [NAL9602](INFO): Powering down
2021-09-29T19:29:16.423Z,1632943756.423 [CBIT](INFO): Clearing failed state for component NAL9602
2021-09-29T19:29:16.423Z,1632943756.423 [NAL9602] No Fault, FailCount= 2
2021-09-29T19:29:45.957Z,1632943785.957 [NAL9602](INFO): Powering up NAL9602
2021-09-29T19:29:56.801Z,1632943796.801 [NAL9602](INFO): NAL9602 initialized
2021-09-29T19:30:12.676Z,1632943812.676 [CommandLine](IMPORTANT): got command failComponent
2021-09-29T19:30:12.677Z,1632943812.677 [CommandLine](IMPORTANT): Failed components:
2021-09-29T19:30:12.677Z,1632943812.677 [CommandLine](IMPORTANT): No failed Components.
2021-09-29T19:30:21.270Z,1632943821.270 [CommandLine](IMPORTANT): got command get platform_battery_charge
2021-09-29T19:30:21.271Z,1632943821.271 [CommandLine](FAULT): Element has no value
2021-09-29T19:31:59.285Z,1632943919.285 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2021-09-29T19:31:59.285Z,1632943919.285 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-09-29T19:31:59.297Z,1632943919.297 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-09-29T19:31:59.705Z,1632943919.705 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-09-29T19:31:59.705Z,1632943919.705 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2021-09-29T19:32:15.839Z,1632943935.839 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193215.00,A,3648.16726,N,12147.28897,W,0.622,0.00,290921,,,A*76
2021-09-29T19:32:15.843Z,1632943935.843 [NAL9602](INFO): GPS fix at 20210929T193215: (36.802788, -121.788150)
2021-09-29T19:32:48.285Z,1632943968.285 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T19:33:43.243Z,1632944023.243 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T19:33:43.243Z,1632944023.243 [Default:CheckIn:C.Wait] Stopped
2021-09-29T19:33:43.243Z,1632944023.243 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T19:33:43.244Z,1632944023.244 [Default:CheckIn:D] Running Loop=1
2021-09-29T19:33:43.664Z,1632944023.664 [Default:CheckIn:D] Stopped
2021-09-29T19:33:43.664Z,1632944023.664 [Default:CheckIn:E] Running Loop=1
2021-09-29T19:33:44.052Z,1632944024.052 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.905005 min 
2021-09-29T19:33:44.052Z,1632944024.052 [Default:CheckIn:E] Stopped
2021-09-29T19:33:44.053Z,1632944024.053 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T19:33:44.053Z,1632944024.053 [Default:CheckIn] Stopped
2021-09-29T19:33:44.053Z,1632944024.053 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T19:33:44.053Z,1632944024.053 [Default:CheckIn](INFO): Running loop #3
2021-09-29T19:33:44.053Z,1632944024.053 [Default:CheckIn] Running Loop=3
2021-09-29T19:33:44.053Z,1632944024.053 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T19:33:44.053Z,1632944024.053 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T19:35:06.895Z,1632944106.895 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T19:35:06.895Z,1632944106.895 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T19:35:28.305Z,1632944128.305 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T19:35:28.305Z,1632944128.305 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T19:38:44.336Z,1632944324.336 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-09-29T19:33:44.1Z
2021-09-29T19:38:44.336Z,1632944324.336 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T19:38:44.336Z,1632944324.336 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T19:38:48.337Z,1632944328.337 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T19:38:51.184Z,1632944331.184 [DataOverHttps](INFO): Sending 226 bytes from file Logs/20210929T190740/Courier0010.lzma
2021-09-29T19:38:52.186Z,1632944332.186 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0010.lzma.bak
2021-09-29T19:38:52.186Z,1632944332.186 [DataOverHttps](INFO): SBD MOMSN=15950493
2021-09-29T19:38:52.373Z,1632944332.373 [BPC1](INFO): Calculating totals. Valid battery stick count: 28. Valid reserve battery stick count: 3.
2021-09-29T19:38:52.379Z,1632944332.379 [BPC1](FAULT): Failed to receive data from 31 sticks prior to timeout. Missing stick IDs are: 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62.
2021-09-29T19:38:52.379Z,1632944332.379 [BPC1] Data Fault, FailCount= 1
2021-09-29T19:38:52.379Z,1632944332.379 [BPC1](ERROR): Data Fault
2021-09-29T19:38:52.441Z,1632944332.441 [CBIT](ERROR): Data Fault in component: BPC1
2021-09-29T19:39:10.776Z,1632944350.776 [DataOverHttps](INFO): Sending 401 bytes from file Logs/20210929T190740/Express0012.lzma
2021-09-29T19:39:11.778Z,1632944351.778 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0012.lzma.bak
2021-09-29T19:39:11.778Z,1632944351.778 [DataOverHttps](INFO): SBD MOMSN=15950496
2021-09-29T19:39:13.882Z,1632944353.882 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T19:39:13.882Z,1632944353.882 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T19:39:13.882Z,1632944353.882 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T19:39:19.113Z,1632944359.113 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T19:44:14.495Z,1632944654.495 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T19:44:14.495Z,1632944654.495 [Default:CheckIn:C.Wait] Stopped
2021-09-29T19:44:14.495Z,1632944654.495 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T19:44:14.495Z,1632944654.495 [Default:CheckIn:D] Running Loop=1
2021-09-29T19:44:14.900Z,1632944654.900 [Default:CheckIn:D] Stopped
2021-09-29T19:44:14.901Z,1632944654.901 [Default:CheckIn:E] Running Loop=1
2021-09-29T19:44:15.317Z,1632944655.317 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.425684 min 
2021-09-29T19:44:15.317Z,1632944655.317 [Default:CheckIn:E] Stopped
2021-09-29T19:44:15.317Z,1632944655.317 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T19:44:15.317Z,1632944655.317 [Default:CheckIn] Stopped
2021-09-29T19:44:15.317Z,1632944655.317 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T19:44:15.318Z,1632944655.318 [Default:CheckIn](INFO): Running loop #4
2021-09-29T19:44:15.318Z,1632944655.318 [Default:CheckIn] Running Loop=4
2021-09-29T19:44:15.318Z,1632944655.318 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T19:44:15.318Z,1632944655.318 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T19:44:16.905Z,1632944656.905 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-09-29T19:44:16.905Z,1632944656.905 [NAL9602] Data Fault, FailCount= 3
2021-09-29T19:44:16.905Z,1632944656.905 [NAL9602](ERROR): Data Fault
2021-09-29T19:44:16.964Z,1632944656.964 [CBIT](ERROR): Data Fault in component: NAL9602
2021-09-29T19:44:17.313Z,1632944657.313 [NAL9602](INFO): Powering down
2021-09-29T19:44:18.144Z,1632944658.144 [CBIT](INFO): Clearing failed state for component NAL9602
2021-09-29T19:44:18.144Z,1632944658.144 [NAL9602] No Fault, FailCount= 3
2021-09-29T19:44:47.612Z,1632944687.612 [NAL9602](INFO): Powering up NAL9602
2021-09-29T19:44:58.543Z,1632944698.543 [NAL9602](INFO): NAL9602 initialized
2021-09-29T19:48:53.363Z,1632944933.363 [CBIT](INFO): Clearing failed state for component BPC1
2021-09-29T19:48:53.363Z,1632944933.363 [BPC1] No Fault, FailCount= 1
2021-09-29T19:49:15.572Z,1632944955.572 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-09-29T19:44:15.3Z
2021-09-29T19:49:15.572Z,1632944955.572 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T19:49:15.572Z,1632944955.572 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T19:49:22.715Z,1632944962.715 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20210929T190740/Courier0016.lzma
2021-09-29T19:49:23.718Z,1632944963.718 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0016.lzma.bak
2021-09-29T19:49:23.718Z,1632944963.718 [DataOverHttps](INFO): SBD MOMSN=15950505
2021-09-29T19:49:39.721Z,1632944979.721 [DataOverHttps](INFO): Sending 367 bytes from file Logs/20210929T190740/Express0017.lzma
2021-09-29T19:49:40.722Z,1632944980.722 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0017.lzma.bak
2021-09-29T19:49:40.722Z,1632944980.722 [DataOverHttps](INFO): SBD MOMSN=15950507
2021-09-29T19:49:42.253Z,1632944982.253 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T19:49:42.253Z,1632944982.253 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T19:49:42.253Z,1632944982.253 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T19:50:01.639Z,1632945001.639 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T19:50:32.389Z,1632945032.389 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T19:54:42.879Z,1632945282.879 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T19:54:42.879Z,1632945282.879 [Default:CheckIn:C.Wait] Stopped
2021-09-29T19:54:42.879Z,1632945282.879 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T19:54:42.879Z,1632945282.879 [Default:CheckIn:D] Running Loop=1
2021-09-29T19:54:43.284Z,1632945283.284 [Default:CheckIn:D] Stopped
2021-09-29T19:54:43.284Z,1632945283.284 [Default:CheckIn:E] Running Loop=1
2021-09-29T19:54:43.691Z,1632945283.691 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.898739 min 
2021-09-29T19:54:43.692Z,1632945283.692 [Default:CheckIn:E] Stopped
2021-09-29T19:54:43.692Z,1632945283.692 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T19:54:43.692Z,1632945283.692 [Default:CheckIn] Stopped
2021-09-29T19:54:43.692Z,1632945283.692 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T19:54:43.692Z,1632945283.692 [Default:CheckIn](INFO): Running loop #5
2021-09-29T19:54:43.692Z,1632945283.692 [Default:CheckIn] Running Loop=5
2021-09-29T19:54:43.693Z,1632945283.693 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T19:54:43.693Z,1632945283.693 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T19:54:45.715Z,1632945285.715 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195446.00,A,3648.16432,N,12147.28905,W,1.536,153.41,290921,,,A*79
2021-09-29T19:54:45.717Z,1632945285.717 [NAL9602](INFO): GPS fix at 20210929T195446: (36.802739, -121.788151)
2021-09-29T19:54:45.732Z,1632945285.732 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T19:54:45.732Z,1632945285.732 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T19:54:53.175Z,1632945293.175 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0019.lzma
2021-09-29T19:54:54.178Z,1632945294.178 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0019.lzma.bak
2021-09-29T19:54:54.178Z,1632945294.178 [DataOverHttps](INFO): SBD MOMSN=15950513
2021-09-29T19:55:13.228Z,1632945313.228 [DataOverHttps](INFO): Sending 217 bytes from file Logs/20210929T190740/Express0020.lzma
2021-09-29T19:55:14.230Z,1632945314.230 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0020.lzma.bak
2021-09-29T19:55:14.230Z,1632945314.230 [DataOverHttps](INFO): SBD MOMSN=15950516
2021-09-29T19:55:16.045Z,1632945316.045 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T19:55:16.045Z,1632945316.045 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T19:55:16.045Z,1632945316.045 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T19:55:16.425Z,1632945316.425 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T19:55:16.504Z,1632945316.504 [NAL9602](ERROR): received: 
+CSQ:0

OK51, 2, 0, 0, 0

OK
2021-09-29T19:59:48.422Z,1632945588.422 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T20:00:16.714Z,1632945616.714 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:00:16.714Z,1632945616.714 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:00:16.714Z,1632945616.714 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:00:16.714Z,1632945616.714 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:00:17.123Z,1632945617.123 [Default:CheckIn:D] Stopped
2021-09-29T20:00:17.123Z,1632945617.123 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:00:17.515Z,1632945617.515 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.462732 min 
2021-09-29T20:00:17.540Z,1632945617.540 [Default:CheckIn:E] Stopped
2021-09-29T20:00:17.540Z,1632945617.540 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:00:17.540Z,1632945617.540 [Default:CheckIn] Stopped
2021-09-29T20:00:17.540Z,1632945617.540 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:00:17.540Z,1632945617.540 [Default:CheckIn](INFO): Running loop #6
2021-09-29T20:00:17.540Z,1632945617.540 [Default:CheckIn] Running Loop=6
2021-09-29T20:00:17.540Z,1632945617.540 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:00:17.541Z,1632945617.541 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:00:19.527Z,1632945619.527 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200019.00,A,3648.16366,N,12147.27763,W,0.253,153.41,290921,,,A*7A
2021-09-29T20:00:19.530Z,1632945619.530 [NAL9602](INFO): GPS fix at 20210929T200019: (36.802728, -121.787960)
2021-09-29T20:00:19.541Z,1632945619.541 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:00:19.541Z,1632945619.541 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:00:29.972Z,1632945629.972 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0022.lzma
2021-09-29T20:00:30.974Z,1632945630.974 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0022.lzma.bak
2021-09-29T20:00:30.974Z,1632945630.974 [DataOverHttps](INFO): SBD MOMSN=15950520
2021-09-29T20:00:52.285Z,1632945652.285 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T20:01:03.100Z,1632945663.100 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2021-09-29T20:01:24.632Z,1632945684.632 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20210929T190740/Express0023.lzma
2021-09-29T20:01:25.634Z,1632945685.634 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0023.lzma.bak
2021-09-29T20:01:25.634Z,1632945685.634 [DataOverHttps](INFO): SBD MOMSN=15950523
2021-09-29T20:01:27.481Z,1632945687.481 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:01:27.481Z,1632945687.481 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:01:27.481Z,1632945687.481 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:06:28.154Z,1632945988.154 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:06:28.154Z,1632945988.154 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:06:28.154Z,1632945988.154 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:06:28.154Z,1632945988.154 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:06:28.527Z,1632945988.527 [Default:CheckIn:D] Stopped
2021-09-29T20:06:28.527Z,1632945988.527 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:06:28.934Z,1632945988.934 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.652795 min 
2021-09-29T20:06:28.934Z,1632945988.934 [Default:CheckIn:E] Stopped
2021-09-29T20:06:28.934Z,1632945988.934 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:06:28.934Z,1632945988.934 [Default:CheckIn] Stopped
2021-09-29T20:06:28.934Z,1632945988.934 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:06:28.934Z,1632945988.934 [Default:CheckIn](INFO): Running loop #7
2021-09-29T20:06:28.934Z,1632945988.934 [Default:CheckIn] Running Loop=7
2021-09-29T20:06:28.935Z,1632945988.935 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:06:28.935Z,1632945988.935 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:06:30.947Z,1632945990.947 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200631.00,A,3648.16056,N,12147.27902,W,0.117,0.00,290921,,,A*7E
2021-09-29T20:06:30.949Z,1632945990.949 [NAL9602](INFO): GPS fix at 20210929T200631: (36.802676, -121.787984)
2021-09-29T20:06:30.977Z,1632945990.977 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:06:30.977Z,1632945990.977 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:06:38.107Z,1632945998.107 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0025.lzma
2021-09-29T20:06:39.110Z,1632945999.110 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0025.lzma.bak
2021-09-29T20:06:39.110Z,1632945999.110 [DataOverHttps](INFO): SBD MOMSN=15950527
2021-09-29T20:06:58.312Z,1632946018.312 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20210929T190740/Express0026.lzma
2021-09-29T20:06:59.314Z,1632946019.314 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0026.lzma.bak
2021-09-29T20:06:59.314Z,1632946019.314 [DataOverHttps](INFO): SBD MOMSN=15950530
2021-09-29T20:07:01.266Z,1632946021.266 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:07:01.266Z,1632946021.266 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:07:01.266Z,1632946021.266 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:11:33.187Z,1632946293.187 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T20:12:01.891Z,1632946321.891 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:12:01.891Z,1632946321.891 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:12:01.891Z,1632946321.891 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:12:01.891Z,1632946321.891 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:12:02.289Z,1632946322.289 [Default:CheckIn:D] Stopped
2021-09-29T20:12:02.289Z,1632946322.289 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:12:02.707Z,1632946322.707 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.215495 min 
2021-09-29T20:12:02.707Z,1632946322.707 [Default:CheckIn:E] Stopped
2021-09-29T20:12:02.708Z,1632946322.708 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:12:02.708Z,1632946322.708 [Default:CheckIn] Stopped
2021-09-29T20:12:02.708Z,1632946322.708 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:12:02.708Z,1632946322.708 [Default:CheckIn](INFO): Running loop #8
2021-09-29T20:12:02.708Z,1632946322.708 [Default:CheckIn] Running Loop=8
2021-09-29T20:12:02.708Z,1632946322.708 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:12:02.708Z,1632946322.708 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:12:04.724Z,1632946324.724 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201205.00,A,3648.16048,N,12147.27948,W,0.680,0.00,290921,,,A*74
2021-09-29T20:12:04.726Z,1632946324.726 [NAL9602](INFO): GPS fix at 20210929T201205: (36.802675, -121.787991)
2021-09-29T20:12:04.738Z,1632946324.738 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:12:04.738Z,1632946324.738 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:12:11.887Z,1632946331.887 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0028.lzma
2021-09-29T20:12:12.890Z,1632946332.890 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0028.lzma.bak
2021-09-29T20:12:12.890Z,1632946332.890 [DataOverHttps](INFO): SBD MOMSN=15950533
2021-09-29T20:12:32.532Z,1632946352.532 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20210929T190740/Express0029.lzma
2021-09-29T20:12:33.534Z,1632946353.534 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0029.lzma.bak
2021-09-29T20:12:33.534Z,1632946353.534 [DataOverHttps](INFO): SBD MOMSN=15950536
2021-09-29T20:12:35.467Z,1632946355.467 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:12:35.467Z,1632946355.467 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:12:35.467Z,1632946355.467 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:12:37.469Z,1632946357.469 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T20:17:36.045Z,1632946656.045 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:17:36.045Z,1632946656.045 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:17:36.045Z,1632946656.045 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:17:36.045Z,1632946656.045 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:17:36.451Z,1632946656.451 [Default:CheckIn:D] Stopped
2021-09-29T20:17:36.451Z,1632946656.451 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:17:36.853Z,1632946656.853 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.784859 min 
2021-09-29T20:17:36.853Z,1632946656.853 [Default:CheckIn:E] Stopped
2021-09-29T20:17:36.854Z,1632946656.854 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:17:36.854Z,1632946656.854 [Default:CheckIn] Stopped
2021-09-29T20:17:36.854Z,1632946656.854 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:17:36.854Z,1632946656.854 [Default:CheckIn](INFO): Running loop #9
2021-09-29T20:17:36.854Z,1632946656.854 [Default:CheckIn] Running Loop=9
2021-09-29T20:17:36.854Z,1632946656.854 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:17:36.854Z,1632946656.854 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:17:38.867Z,1632946658.867 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201739.00,A,3648.16068,N,12147.28469,W,0.156,0.00,290921,,,A*71
2021-09-29T20:17:38.879Z,1632946658.879 [NAL9602](INFO): GPS fix at 20210929T201739: (36.802678, -121.788078)
2021-09-29T20:17:38.890Z,1632946658.890 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:17:38.890Z,1632946658.890 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:17:45.891Z,1632946665.891 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0031.lzma
2021-09-29T20:17:46.894Z,1632946666.894 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0031.lzma.bak
2021-09-29T20:17:46.894Z,1632946666.894 [DataOverHttps](INFO): SBD MOMSN=15950540
2021-09-29T20:18:03.131Z,1632946683.131 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20210929T190740/Express0032.lzma
2021-09-29T20:18:04.134Z,1632946684.134 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0032.lzma.bak
2021-09-29T20:18:04.134Z,1632946684.134 [DataOverHttps](INFO): SBD MOMSN=15950543
2021-09-29T20:18:06.057Z,1632946686.057 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:18:06.057Z,1632946686.057 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:18:06.057Z,1632946686.057 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:18:09.613Z,1632946689.613 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T20:18:09.696Z,1632946689.696 [NAL9602](ERROR): received: 
+CSQ:0

OK51, 2, 0, 0, 0

OK
2021-09-29T20:19:54.269Z,1632946794.269 [BPC1](INFO): Calculating totals. Valid battery stick count: 28. Valid reserve battery stick count: 3.
2021-09-29T20:19:54.285Z,1632946794.285 [BPC1](FAULT): Failed to receive data from 31 sticks prior to timeout. Missing stick IDs are: 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62.
2021-09-29T20:19:54.285Z,1632946794.285 [BPC1] Data Fault, FailCount= 2
2021-09-29T20:19:54.285Z,1632946794.285 [BPC1](ERROR): Data Fault
2021-09-29T20:19:54.309Z,1632946794.309 [CBIT](ERROR): Data Fault in component: BPC1
2021-09-29T20:22:41.245Z,1632946961.245 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T20:23:06.717Z,1632946986.717 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:23:06.718Z,1632946986.718 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:23:06.718Z,1632946986.718 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:23:06.718Z,1632946986.718 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:23:07.109Z,1632946987.109 [Default:CheckIn:D] Stopped
2021-09-29T20:23:07.109Z,1632946987.109 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:23:07.511Z,1632946987.511 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 71.295825 min 
2021-09-29T20:23:07.511Z,1632946987.511 [Default:CheckIn:E] Stopped
2021-09-29T20:23:07.512Z,1632946987.512 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:23:07.512Z,1632946987.512 [Default:CheckIn] Stopped
2021-09-29T20:23:07.512Z,1632946987.512 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:23:07.512Z,1632946987.512 [Default:CheckIn](INFO): Running loop #10
2021-09-29T20:23:07.512Z,1632946987.512 [Default:CheckIn] Running Loop=10
2021-09-29T20:23:07.512Z,1632946987.512 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:23:07.512Z,1632946987.512 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:23:09.523Z,1632946989.523 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202309.00,A,3648.16144,N,12147.28356,W,0.700,0.00,290921,,,A*74
2021-09-29T20:23:09.526Z,1632946989.526 [NAL9602](INFO): GPS fix at 20210929T202309: (36.802691, -121.788059)
2021-09-29T20:23:09.574Z,1632946989.574 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:23:09.574Z,1632946989.574 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:23:17.255Z,1632946997.255 [DataOverHttps](INFO): Sending 86 bytes from file Logs/20210929T190740/Courier0034.lzma
2021-09-29T20:23:18.258Z,1632946998.258 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0034.lzma.bak
2021-09-29T20:23:18.258Z,1632946998.258 [DataOverHttps](INFO): SBD MOMSN=15950546
2021-09-29T20:23:34.160Z,1632947014.160 [DataOverHttps](INFO): Sending 329 bytes from file Logs/20210929T190740/Express0035.lzma
2021-09-29T20:23:35.162Z,1632947015.162 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0035.lzma.bak
2021-09-29T20:23:35.162Z,1632947015.162 [DataOverHttps](INFO): SBD MOMSN=15950549
2021-09-29T20:23:37.012Z,1632947017.012 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:23:37.013Z,1632947017.013 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:23:37.013Z,1632947017.013 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:23:42.249Z,1632947022.249 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T20:28:37.615Z,1632947317.615 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:28:37.615Z,1632947317.615 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:28:37.615Z,1632947317.615 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:28:37.615Z,1632947317.615 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:28:38.029Z,1632947318.029 [Default:CheckIn:D] Stopped
2021-09-29T20:28:38.029Z,1632947318.029 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:28:38.423Z,1632947318.423 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 76.811157 min 
2021-09-29T20:28:38.423Z,1632947318.423 [Default:CheckIn:E] Stopped
2021-09-29T20:28:38.423Z,1632947318.423 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:28:38.423Z,1632947318.423 [Default:CheckIn] Stopped
2021-09-29T20:28:38.423Z,1632947318.423 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:28:38.436Z,1632947318.436 [Default:CheckIn](INFO): Running loop #11
2021-09-29T20:28:38.436Z,1632947318.436 [Default:CheckIn] Running Loop=11
2021-09-29T20:28:38.436Z,1632947318.436 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:28:38.436Z,1632947318.436 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:28:40.435Z,1632947320.435 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202840.00,A,3648.16341,N,12147.28033,W,0.914,192.02,290921,,,A*76
2021-09-29T20:28:40.437Z,1632947320.437 [NAL9602](INFO): GPS fix at 20210929T202840: (36.802723, -121.788005)
2021-09-29T20:28:40.480Z,1632947320.480 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:28:40.480Z,1632947320.480 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:28:47.847Z,1632947327.847 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210929T190740/Courier0037.lzma
2021-09-29T20:28:48.850Z,1632947328.850 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0037.lzma.bak
2021-09-29T20:28:48.850Z,1632947328.850 [DataOverHttps](INFO): SBD MOMSN=15950554
2021-09-29T20:29:07.175Z,1632947347.175 [DataOverHttps](INFO): Sending 139 bytes from file Logs/20210929T190740/Express0038.lzma
2021-09-29T20:29:08.178Z,1632947348.178 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0038.lzma.bak
2021-09-29T20:29:08.178Z,1632947348.178 [DataOverHttps](INFO): SBD MOMSN=15950557
2021-09-29T20:29:10.442Z,1632947350.442 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:29:10.442Z,1632947350.442 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:29:10.442Z,1632947350.442 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:29:11.198Z,1632947351.198 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T20:29:11.272Z,1632947351.272 [NAL9602](ERROR): received: 
+CSQ:1

OK51, 2, 0, 0, 0

OK
2021-09-29T20:29:52.819Z,1632947392.819 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T20:29:52.819Z,1632947392.819 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T20:29:55.270Z,1632947395.270 [CBIT](INFO): Clearing failed state for component BPC1
2021-09-29T20:29:55.270Z,1632947395.270 [BPC1] No Fault, FailCount= 2
2021-09-29T20:33:39.916Z,1632947619.916 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T20:33:39.917Z,1632947619.917 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T20:33:42.333Z,1632947622.333 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T20:34:11.107Z,1632947651.107 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:34:11.107Z,1632947651.107 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:34:11.107Z,1632947651.107 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:34:11.107Z,1632947651.107 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:34:11.440Z,1632947651.440 [Default:CheckIn:D] Stopped
2021-09-29T20:34:11.441Z,1632947651.441 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:34:11.857Z,1632947651.857 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 82.368018 min 
2021-09-29T20:34:11.857Z,1632947651.857 [Default:CheckIn:E] Stopped
2021-09-29T20:34:11.857Z,1632947651.857 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:34:11.858Z,1632947651.858 [Default:CheckIn] Stopped
2021-09-29T20:34:11.858Z,1632947651.858 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:34:11.858Z,1632947651.858 [Default:CheckIn](INFO): Running loop #12
2021-09-29T20:34:11.858Z,1632947651.858 [Default:CheckIn] Running Loop=12
2021-09-29T20:34:11.858Z,1632947651.858 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:34:11.858Z,1632947651.858 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:34:13.851Z,1632947653.851 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203414.00,A,3648.16957,N,12147.28562,W,0.544,192.02,290921,,,A*7F
2021-09-29T20:34:13.854Z,1632947653.854 [NAL9602](INFO): GPS fix at 20210929T203414: (36.802826, -121.788094)
2021-09-29T20:34:13.893Z,1632947653.893 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:34:13.893Z,1632947653.893 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:34:23.975Z,1632947663.975 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0040.lzma
2021-09-29T20:34:24.978Z,1632947664.978 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0040.lzma.bak
2021-09-29T20:34:24.978Z,1632947664.978 [DataOverHttps](INFO): SBD MOMSN=15950560
2021-09-29T20:34:42.140Z,1632947682.140 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20210929T190740/Express0041.lzma
2021-09-29T20:34:43.142Z,1632947683.142 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0041.lzma.bak
2021-09-29T20:34:43.142Z,1632947683.142 [DataOverHttps](INFO): SBD MOMSN=15950563
2021-09-29T20:34:44.668Z,1632947684.668 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:34:44.668Z,1632947684.668 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:34:44.668Z,1632947684.668 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:34:46.237Z,1632947686.237 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T20:39:45.327Z,1632947985.327 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:39:45.327Z,1632947985.327 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:39:45.327Z,1632947985.327 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:39:45.327Z,1632947985.327 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:39:45.708Z,1632947985.708 [Default:CheckIn:D] Stopped
2021-09-29T20:39:45.708Z,1632947985.708 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:39:46.119Z,1632947986.119 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.939136 min 
2021-09-29T20:39:46.119Z,1632947986.119 [Default:CheckIn:E] Stopped
2021-09-29T20:39:46.120Z,1632947986.120 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:39:46.120Z,1632947986.120 [Default:CheckIn] Stopped
2021-09-29T20:39:46.120Z,1632947986.120 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:39:46.121Z,1632947986.121 [Default:CheckIn](INFO): Running loop #13
2021-09-29T20:39:46.121Z,1632947986.121 [Default:CheckIn] Running Loop=13
2021-09-29T20:39:46.121Z,1632947986.121 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:39:46.121Z,1632947986.121 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:39:48.123Z,1632947988.123 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203948.99,A,3648.16348,N,12147.28886,W,0.408,192.02,290921,,,A*71
2021-09-29T20:39:48.126Z,1632947988.126 [NAL9602](INFO): GPS fix at 20210929T203948: (36.802725, -121.788148)
2021-09-29T20:39:48.157Z,1632947988.157 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:39:48.157Z,1632947988.157 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:39:55.391Z,1632947995.391 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0043.lzma
2021-09-29T20:39:56.394Z,1632947996.394 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0043.lzma.bak
2021-09-29T20:39:56.394Z,1632947996.394 [DataOverHttps](INFO): SBD MOMSN=15950567
2021-09-29T20:40:12.435Z,1632948012.435 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20210929T190740/Express0044.lzma
2021-09-29T20:40:13.438Z,1632948013.438 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0044.lzma.bak
2021-09-29T20:40:13.438Z,1632948013.438 [DataOverHttps](INFO): SBD MOMSN=15950570
2021-09-29T20:40:15.207Z,1632948015.207 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:40:15.207Z,1632948015.207 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:40:15.207Z,1632948015.207 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:40:18.869Z,1632948018.869 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T20:40:18.952Z,1632948018.952 [NAL9602](ERROR): received: 
+SBDI: 2, 5751, 2, 0, 0, 0

OK
2021-09-29T20:40:57.679Z,1632948057.679 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T20:40:57.679Z,1632948057.679 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T20:41:34.851Z,1632948094.851 [NAL9602](INFO): SBD MO Status=2, MOMSN=5751, MT Status=2, MTMSN=0
2021-09-29T20:41:34.851Z,1632948094.851 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T20:41:58.686Z,1632948118.686 [NAL9602](INFO): SBD MO Status=0, MOMSN=5751, MT Status=0, MTMSN=0
2021-09-29T20:41:58.687Z,1632948118.687 [NAL9602](INFO): No messages in MT queue
2021-09-29T20:42:29.385Z,1632948149.385 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T20:45:15.931Z,1632948315.931 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:45:15.931Z,1632948315.931 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:45:15.931Z,1632948315.931 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:45:15.931Z,1632948315.931 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:45:16.331Z,1632948316.331 [Default:CheckIn:D] Stopped
2021-09-29T20:45:16.331Z,1632948316.331 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:45:16.736Z,1632948316.736 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 93.449528 min 
2021-09-29T20:45:16.736Z,1632948316.736 [Default:CheckIn:E] Stopped
2021-09-29T20:45:16.736Z,1632948316.736 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:45:16.736Z,1632948316.736 [Default:CheckIn] Stopped
2021-09-29T20:45:16.736Z,1632948316.736 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:45:16.737Z,1632948316.737 [Default:CheckIn](INFO): Running loop #14
2021-09-29T20:45:16.737Z,1632948316.737 [Default:CheckIn] Running Loop=14
2021-09-29T20:45:16.737Z,1632948316.737 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:45:16.737Z,1632948316.737 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:45:18.763Z,1632948318.763 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204519.00,A,3648.16505,N,12147.28593,W,0.330,0.00,290921,,,A*7C
2021-09-29T20:45:18.765Z,1632948318.765 [NAL9602](INFO): GPS fix at 20210929T204519: (36.802751, -121.788099)
2021-09-29T20:45:18.776Z,1632948318.776 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:45:18.776Z,1632948318.776 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:45:25.975Z,1632948325.975 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0046.lzma
2021-09-29T20:45:26.978Z,1632948326.978 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0046.lzma.bak
2021-09-29T20:45:26.978Z,1632948326.978 [DataOverHttps](INFO): SBD MOMSN=15950574
2021-09-29T20:45:43.119Z,1632948343.119 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20210929T190740/Express0047.lzma
2021-09-29T20:45:44.122Z,1632948344.122 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0047.lzma.bak
2021-09-29T20:45:44.122Z,1632948344.122 [DataOverHttps](INFO): SBD MOMSN=15950577
2021-09-29T20:45:45.877Z,1632948345.877 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:45:45.877Z,1632948345.877 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:45:45.878Z,1632948345.878 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:48:46.407Z,1632948526.407 [NAL9602](INFO): SBD MO Status=2, MOMSN=5752, MT Status=2, MTMSN=0
2021-09-29T20:48:46.407Z,1632948526.407 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T20:49:47.031Z,1632948587.031 [NAL9602](INFO): SBD MO Status=0, MOMSN=5752, MT Status=0, MTMSN=0
2021-09-29T20:49:47.031Z,1632948587.031 [NAL9602](INFO): No messages in MT queue
2021-09-29T20:50:17.713Z,1632948617.713 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T20:50:46.412Z,1632948646.412 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:50:46.412Z,1632948646.412 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:50:46.412Z,1632948646.412 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:50:46.412Z,1632948646.412 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:50:46.819Z,1632948646.819 [Default:CheckIn:D] Stopped
2021-09-29T20:50:46.819Z,1632948646.819 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:50:47.228Z,1632948647.228 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.957666 min 
2021-09-29T20:50:47.228Z,1632948647.228 [Default:CheckIn:E] Stopped
2021-09-29T20:50:47.229Z,1632948647.229 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:50:47.229Z,1632948647.229 [Default:CheckIn] Stopped
2021-09-29T20:50:47.229Z,1632948647.229 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:50:47.229Z,1632948647.229 [Default:CheckIn](INFO): Running loop #15
2021-09-29T20:50:47.229Z,1632948647.229 [Default:CheckIn] Running Loop=15
2021-09-29T20:50:47.229Z,1632948647.229 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:50:47.229Z,1632948647.229 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:50:49.231Z,1632948649.231 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205049.00,A,3648.16202,N,12147.28497,W,0.330,0.00,290921,,,A*78
2021-09-29T20:50:49.233Z,1632948649.233 [NAL9602](INFO): GPS fix at 20210929T205049: (36.802700, -121.788083)
2021-09-29T20:50:49.265Z,1632948649.265 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:50:49.266Z,1632948649.266 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:50:56.503Z,1632948656.503 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20210929T190740/Courier0049.lzma
2021-09-29T20:50:57.506Z,1632948657.506 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0049.lzma.bak
2021-09-29T20:50:57.506Z,1632948657.506 [DataOverHttps](INFO): SBD MOMSN=15950580
2021-09-29T20:51:17.055Z,1632948677.055 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20210929T190740/Express0050.lzma
2021-09-29T20:51:18.058Z,1632948678.058 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0050.lzma.bak
2021-09-29T20:51:18.058Z,1632948678.058 [DataOverHttps](INFO): SBD MOMSN=15950583
2021-09-29T20:51:19.673Z,1632948679.673 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:51:19.674Z,1632948679.674 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:51:19.674Z,1632948679.674 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:51:26.935Z,1632948686.935 [NAL9602](INFO): SBD MO Status=2, MOMSN=5753, MT Status=2, MTMSN=0
2021-09-29T20:51:26.936Z,1632948686.936 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T20:52:01.675Z,1632948721.675 [NAL9602](INFO): SBD MO Status=2, MOMSN=5753, MT Status=2, MTMSN=0
2021-09-29T20:52:01.676Z,1632948721.676 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T20:55:50.861Z,1632948950.861 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T20:56:20.363Z,1632948980.363 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T20:56:20.363Z,1632948980.363 [Default:CheckIn:C.Wait] Stopped
2021-09-29T20:56:20.363Z,1632948980.363 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T20:56:20.363Z,1632948980.363 [Default:CheckIn:D] Running Loop=1
2021-09-29T20:56:20.782Z,1632948980.782 [Default:CheckIn:D] Stopped
2021-09-29T20:56:20.782Z,1632948980.782 [Default:CheckIn:E] Running Loop=1
2021-09-29T20:56:21.200Z,1632948981.200 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 104.523706 min 
2021-09-29T20:56:21.200Z,1632948981.200 [Default:CheckIn:E] Stopped
2021-09-29T20:56:21.200Z,1632948981.200 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T20:56:21.201Z,1632948981.201 [Default:CheckIn] Stopped
2021-09-29T20:56:21.201Z,1632948981.201 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T20:56:21.201Z,1632948981.201 [Default:CheckIn](INFO): Running loop #16
2021-09-29T20:56:21.201Z,1632948981.201 [Default:CheckIn] Running Loop=16
2021-09-29T20:56:21.201Z,1632948981.201 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T20:56:21.201Z,1632948981.201 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T20:56:21.565Z,1632948981.565 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T20:56:23.186Z,1632948983.186 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205623.00,A,3648.15957,N,12147.29145,W,0.583,0.00,290921,,,A*7F
2021-09-29T20:56:23.188Z,1632948983.188 [NAL9602](INFO): GPS fix at 20210929T205623: (36.802659, -121.788191)
2021-09-29T20:56:23.207Z,1632948983.207 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T20:56:23.207Z,1632948983.207 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T20:56:30.895Z,1632948990.895 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0052.lzma
2021-09-29T20:56:31.898Z,1632948991.898 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0052.lzma.bak
2021-09-29T20:56:31.898Z,1632948991.898 [DataOverHttps](INFO): SBD MOMSN=15950587
2021-09-29T20:56:47.656Z,1632949007.656 [DataOverHttps](INFO): Sending 219 bytes from file Logs/20210929T190740/Express0053.lzma
2021-09-29T20:56:48.658Z,1632949008.658 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0053.lzma.bak
2021-09-29T20:56:48.658Z,1632949008.658 [DataOverHttps](INFO): SBD MOMSN=15950590
2021-09-29T20:56:50.331Z,1632949010.331 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T20:56:50.332Z,1632949010.332 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T20:56:50.332Z,1632949010.332 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T20:56:53.957Z,1632949013.957 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T20:56:54.032Z,1632949014.032 [NAL9602](ERROR): received: 
+CSQ:0

OK53, 2, 0, 0, 0

OK
2021-09-29T21:00:30.531Z,1632949230.531 [NAL9602](INFO): SBD MO Status=2, MOMSN=5753, MT Status=2, MTMSN=0
2021-09-29T21:00:30.531Z,1632949230.531 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:00:55.968Z,1632949255.968 [BPC1](INFO): Calculating totals. Valid battery stick count: 28. Valid reserve battery stick count: 3.
2021-09-29T21:00:55.974Z,1632949255.974 [BPC1](FAULT): Failed to receive data from 31 sticks prior to timeout. Missing stick IDs are: 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62.
2021-09-29T21:00:55.974Z,1632949255.974 [BPC1] Data Fault, FailCount= 3
2021-09-29T21:00:55.974Z,1632949255.974 [BPC1](ERROR): Data Fault
2021-09-29T21:00:56.055Z,1632949256.055 [CBIT](ERROR): Data Fault in component: BPC1
2021-09-29T21:01:23.096Z,1632949283.096 [NAL9602](INFO): SBD MO Status=2, MOMSN=5753, MT Status=2, MTMSN=0
2021-09-29T21:01:23.096Z,1632949283.096 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:01:25.113Z,1632949285.113 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T21:01:50.985Z,1632949310.985 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:01:50.985Z,1632949310.985 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:01:50.985Z,1632949310.985 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:01:50.985Z,1632949310.985 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:01:51.400Z,1632949311.400 [Default:CheckIn:D] Stopped
2021-09-29T21:01:51.400Z,1632949311.400 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:01:51.788Z,1632949311.788 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 110.034009 min 
2021-09-29T21:01:51.788Z,1632949311.788 [Default:CheckIn:E] Stopped
2021-09-29T21:01:51.788Z,1632949311.788 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:01:51.788Z,1632949311.788 [Default:CheckIn] Stopped
2021-09-29T21:01:51.788Z,1632949311.788 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:01:51.788Z,1632949311.788 [Default:CheckIn](INFO): Running loop #17
2021-09-29T21:01:51.788Z,1632949311.788 [Default:CheckIn] Running Loop=17
2021-09-29T21:01:51.789Z,1632949311.789 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:01:51.789Z,1632949311.789 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:01:53.803Z,1632949313.803 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210154.00,A,3648.16669,N,12147.28338,W,0.292,0.00,290921,,,A*73
2021-09-29T21:01:53.805Z,1632949313.805 [NAL9602](INFO): GPS fix at 20210929T210154: (36.802778, -121.788056)
2021-09-29T21:01:53.816Z,1632949313.816 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:01:53.816Z,1632949313.816 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:02:00.959Z,1632949320.959 [DataOverHttps](INFO): Sending 86 bytes from file Logs/20210929T190740/Courier0055.lzma
2021-09-29T21:02:01.962Z,1632949321.962 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0055.lzma.bak
2021-09-29T21:02:01.962Z,1632949321.962 [DataOverHttps](INFO): SBD MOMSN=15950594
2021-09-29T21:02:18.213Z,1632949338.213 [DataOverHttps](INFO): Sending 328 bytes from file Logs/20210929T190740/Express0056.lzma
2021-09-29T21:02:19.214Z,1632949339.214 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0056.lzma.bak
2021-09-29T21:02:19.214Z,1632949339.214 [DataOverHttps](INFO): SBD MOMSN=15950597
2021-09-29T21:02:21.333Z,1632949341.333 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:02:21.333Z,1632949341.333 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:02:21.333Z,1632949341.333 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:02:26.182Z,1632949346.182 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T21:07:22.001Z,1632949642.001 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:07:22.001Z,1632949642.001 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:07:22.001Z,1632949642.001 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:07:22.001Z,1632949642.001 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:07:22.381Z,1632949642.381 [Default:CheckIn:D] Stopped
2021-09-29T21:07:22.381Z,1632949642.381 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:07:22.795Z,1632949642.795 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 115.550358 min 
2021-09-29T21:07:22.795Z,1632949642.795 [Default:CheckIn:E] Stopped
2021-09-29T21:07:22.795Z,1632949642.795 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:07:22.795Z,1632949642.795 [Default:CheckIn] Stopped
2021-09-29T21:07:22.796Z,1632949642.796 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:07:22.796Z,1632949642.796 [Default:CheckIn](INFO): Running loop #18
2021-09-29T21:07:22.796Z,1632949642.796 [Default:CheckIn] Running Loop=18
2021-09-29T21:07:22.796Z,1632949642.796 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:07:22.796Z,1632949642.796 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:07:24.791Z,1632949644.791 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210725.00,A,3648.16639,N,12147.27944,W,0.389,0.00,290921,,,A*73
2021-09-29T21:07:24.801Z,1632949644.801 [NAL9602](INFO): GPS fix at 20210929T210725: (36.802773, -121.787991)
2021-09-29T21:07:24.812Z,1632949644.812 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:07:24.812Z,1632949644.812 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:07:32.475Z,1632949652.475 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0058.lzma
2021-09-29T21:07:33.478Z,1632949653.478 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0058.lzma.bak
2021-09-29T21:07:33.478Z,1632949653.478 [DataOverHttps](INFO): SBD MOMSN=15950602
2021-09-29T21:07:49.451Z,1632949669.451 [DataOverHttps](INFO): Sending 138 bytes from file Logs/20210929T190740/Express0059.lzma
2021-09-29T21:07:50.454Z,1632949670.454 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0059.lzma.bak
2021-09-29T21:07:50.454Z,1632949670.454 [DataOverHttps](INFO): SBD MOMSN=15950605
2021-09-29T21:07:52.273Z,1632949672.273 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:07:52.273Z,1632949672.273 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:07:52.273Z,1632949672.273 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:07:55.489Z,1632949675.489 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T21:07:55.564Z,1632949675.564 [NAL9602](ERROR): received: 
+SBDI: 2, 5753, 2, 0, 0, 0

OK
2021-09-29T21:10:34.759Z,1632949834.759 [NAL9602](INFO): SBD MO Status=2, MOMSN=5753, MT Status=2, MTMSN=0
2021-09-29T21:10:34.760Z,1632949834.760 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:10:57.033Z,1632949857.033 [CBIT](INFO): Clearing failed state for component BPC1
2021-09-29T21:10:57.033Z,1632949857.033 [BPC1] No Fault, FailCount= 3
2021-09-29T21:11:19.610Z,1632949879.610 [NAL9602](INFO): SBD MO Status=2, MOMSN=5753, MT Status=2, MTMSN=0
2021-09-29T21:11:19.610Z,1632949879.610 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:11:48.699Z,1632949908.699 [NAL9602](INFO): SBD MO Status=2, MOMSN=5753, MT Status=2, MTMSN=0
2021-09-29T21:11:48.699Z,1632949908.699 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:12:06.075Z,1632949926.075 [NAL9602](INFO): SBD MO Status=0, MOMSN=5753, MT Status=0, MTMSN=0
2021-09-29T21:12:06.075Z,1632949926.075 [NAL9602](INFO): No messages in MT queue
2021-09-29T21:12:36.781Z,1632949956.781 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T21:12:52.955Z,1632949972.955 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:12:52.955Z,1632949972.955 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:12:52.955Z,1632949972.955 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:12:52.956Z,1632949972.956 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:12:53.365Z,1632949973.365 [Default:CheckIn:D] Stopped
2021-09-29T21:12:53.365Z,1632949973.365 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:12:53.776Z,1632949973.776 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 121.066764 min 
2021-09-29T21:12:53.776Z,1632949973.776 [Default:CheckIn:E] Stopped
2021-09-29T21:12:53.776Z,1632949973.776 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:12:53.776Z,1632949973.776 [Default:CheckIn] Stopped
2021-09-29T21:12:53.776Z,1632949973.776 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:12:53.776Z,1632949973.776 [Default:CheckIn](INFO): Running loop #19
2021-09-29T21:12:53.776Z,1632949973.776 [Default:CheckIn] Running Loop=19
2021-09-29T21:12:53.777Z,1632949973.777 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:12:53.777Z,1632949973.777 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:12:55.771Z,1632949975.771 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211256.00,A,3648.16233,N,12147.28185,W,0.214,0.00,290921,,,A*72
2021-09-29T21:12:55.774Z,1632949975.774 [NAL9602](INFO): GPS fix at 20210929T211256: (36.802706, -121.788031)
2021-09-29T21:12:55.788Z,1632949975.788 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:12:55.788Z,1632949975.788 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:13:04.379Z,1632949984.379 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210929T190740/Courier0061.lzma
2021-09-29T21:13:05.382Z,1632949985.382 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0061.lzma.bak
2021-09-29T21:13:05.382Z,1632949985.382 [DataOverHttps](INFO): SBD MOMSN=15950609
2021-09-29T21:13:23.623Z,1632950003.623 [DataOverHttps](INFO): Sending 139 bytes from file Logs/20210929T190740/Express0062.lzma
2021-09-29T21:13:24.626Z,1632950004.626 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0062.lzma.bak
2021-09-29T21:13:24.626Z,1632950004.626 [DataOverHttps](INFO): SBD MOMSN=15950612
2021-09-29T21:13:26.162Z,1632950006.162 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:13:26.162Z,1632950006.162 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:13:26.162Z,1632950006.162 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:14:31.579Z,1632950071.579 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2021-09-29T21:17:28.187Z,1632950248.187 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:17:28.187Z,1632950248.187 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:17:54.879Z,1632950274.879 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:17:54.879Z,1632950274.879 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:17:58.101Z,1632950278.101 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T21:18:26.806Z,1632950306.806 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:18:26.806Z,1632950306.806 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:18:26.806Z,1632950306.806 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:18:26.806Z,1632950306.806 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:18:27.227Z,1632950307.227 [Default:CheckIn:D] Stopped
2021-09-29T21:18:27.227Z,1632950307.227 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:18:27.607Z,1632950307.607 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 126.631128 min 
2021-09-29T21:18:27.607Z,1632950307.607 [Default:CheckIn:E] Stopped
2021-09-29T21:18:27.608Z,1632950307.608 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:18:27.608Z,1632950307.608 [Default:CheckIn] Stopped
2021-09-29T21:18:27.608Z,1632950307.608 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:18:27.608Z,1632950307.608 [Default:CheckIn](INFO): Running loop #20
2021-09-29T21:18:27.608Z,1632950307.608 [Default:CheckIn] Running Loop=20
2021-09-29T21:18:27.608Z,1632950307.608 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:18:27.609Z,1632950307.609 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:18:29.623Z,1632950309.623 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211830.00,A,3648.16239,N,12147.29211,W,0.661,0.00,290921,,,A*7B
2021-09-29T21:18:29.625Z,1632950309.625 [NAL9602](INFO): GPS fix at 20210929T211830: (36.802706, -121.788202)
2021-09-29T21:18:29.636Z,1632950309.636 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:18:29.636Z,1632950309.636 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:18:37.099Z,1632950317.099 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0064.lzma
2021-09-29T21:18:38.102Z,1632950318.102 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0064.lzma.bak
2021-09-29T21:18:38.102Z,1632950318.102 [DataOverHttps](INFO): SBD MOMSN=15950615
2021-09-29T21:18:53.928Z,1632950333.928 [DataOverHttps](INFO): Sending 219 bytes from file Logs/20210929T190740/Express0065.lzma
2021-09-29T21:18:54.930Z,1632950334.930 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0065.lzma.bak
2021-09-29T21:18:54.930Z,1632950334.930 [DataOverHttps](INFO): SBD MOMSN=15950618
2021-09-29T21:18:56.699Z,1632950336.699 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:18:56.699Z,1632950336.699 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:18:56.700Z,1632950336.700 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:19:02.337Z,1632950342.337 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T21:21:38.713Z,1632950498.713 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2021-09-29T21:23:57.288Z,1632950637.288 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:23:57.288Z,1632950637.288 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:23:57.288Z,1632950637.288 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:23:57.288Z,1632950637.288 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:23:57.697Z,1632950637.697 [Default:CheckIn:D] Stopped
2021-09-29T21:23:57.697Z,1632950637.697 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 132.138957 min 
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn:E] Stopped
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn] Stopped
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn](INFO): Running loop #21
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn] Running Loop=21
2021-09-29T21:23:58.098Z,1632950638.098 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:23:58.099Z,1632950638.099 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:24:00.111Z,1632950640.111 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212400.00,A,3648.15878,N,12147.28698,W,0.778,0.00,290921,,,A*76
2021-09-29T21:24:00.114Z,1632950640.114 [NAL9602](INFO): GPS fix at 20210929T212400: (36.802646, -121.788116)
2021-09-29T21:24:00.141Z,1632950640.141 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:24:00.141Z,1632950640.141 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:24:07.039Z,1632950647.039 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210929T190740/Courier0067.lzma
2021-09-29T21:24:08.042Z,1632950648.042 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0067.lzma.bak
2021-09-29T21:24:08.042Z,1632950648.042 [DataOverHttps](INFO): SBD MOMSN=15950622
2021-09-29T21:24:26.736Z,1632950666.736 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20210929T190740/Express0068.lzma
2021-09-29T21:24:27.738Z,1632950667.738 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0068.lzma.bak
2021-09-29T21:24:27.738Z,1632950667.738 [DataOverHttps](INFO): SBD MOMSN=15950625
2021-09-29T21:24:29.693Z,1632950669.693 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:24:29.693Z,1632950669.693 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:24:29.693Z,1632950669.693 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:24:30.881Z,1632950670.881 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T21:24:30.960Z,1632950670.960 [NAL9602](ERROR): received: 
+SBDI: 2, 5754, 2, 0, 0, 0

OK
2021-09-29T21:26:27.299Z,1632950787.299 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:26:27.299Z,1632950787.299 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:26:40.227Z,1632950800.227 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:26:40.227Z,1632950800.227 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:27:05.676Z,1632950825.676 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:27:05.676Z,1632950825.676 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:27:50.115Z,1632950870.115 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:27:50.115Z,1632950870.115 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:28:31.351Z,1632950911.351 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:28:31.351Z,1632950911.351 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:28:53.147Z,1632950933.147 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:28:53.147Z,1632950933.147 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:29:02.441Z,1632950942.441 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T21:29:30.355Z,1632950970.355 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:29:30.355Z,1632950970.355 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:29:30.355Z,1632950970.355 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:29:30.355Z,1632950970.355 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:29:30.760Z,1632950970.760 [Default:CheckIn:D] Stopped
2021-09-29T21:29:30.760Z,1632950970.760 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:29:31.152Z,1632950971.152 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 137.690007 min 
2021-09-29T21:29:31.152Z,1632950971.152 [Default:CheckIn:E] Stopped
2021-09-29T21:29:31.152Z,1632950971.152 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:29:31.152Z,1632950971.152 [Default:CheckIn] Stopped
2021-09-29T21:29:31.152Z,1632950971.152 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:29:31.152Z,1632950971.152 [Default:CheckIn](INFO): Running loop #22
2021-09-29T21:29:31.153Z,1632950971.153 [Default:CheckIn] Running Loop=22
2021-09-29T21:29:31.153Z,1632950971.153 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:29:31.153Z,1632950971.153 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:29:33.145Z,1632950973.145 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212933.00,A,3648.16635,N,12147.28272,W,0.661,214.77,290921,,,A*71
2021-09-29T21:29:33.148Z,1632950973.148 [NAL9602](INFO): GPS fix at 20210929T212933: (36.802773, -121.788045)
2021-09-29T21:29:33.159Z,1632950973.159 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:29:33.159Z,1632950973.159 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:29:40.359Z,1632950980.359 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0070.lzma
2021-09-29T21:29:41.362Z,1632950981.362 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0070.lzma.bak
2021-09-29T21:29:41.362Z,1632950981.362 [DataOverHttps](INFO): SBD MOMSN=15950628
2021-09-29T21:29:57.112Z,1632950997.112 [DataOverHttps](INFO): Sending 218 bytes from file Logs/20210929T190740/Express0071.lzma
2021-09-29T21:29:58.114Z,1632950998.114 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0071.lzma.bak
2021-09-29T21:29:58.114Z,1632950998.114 [DataOverHttps](INFO): SBD MOMSN=15950631
2021-09-29T21:29:59.822Z,1632950999.822 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:29:59.822Z,1632950999.822 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:29:59.822Z,1632950999.822 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:30:05.471Z,1632951005.471 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T21:35:00.444Z,1632951300.444 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:35:00.444Z,1632951300.444 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:35:00.444Z,1632951300.444 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:35:00.444Z,1632951300.444 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:35:00.866Z,1632951300.866 [Default:CheckIn:D] Stopped
2021-09-29T21:35:00.866Z,1632951300.866 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:35:01.357Z,1632951301.357 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 143.191781 min 
2021-09-29T21:35:01.357Z,1632951301.357 [Default:CheckIn:E] Stopped
2021-09-29T21:35:01.357Z,1632951301.357 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:35:01.357Z,1632951301.357 [Default:CheckIn] Stopped
2021-09-29T21:35:01.357Z,1632951301.357 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:35:01.358Z,1632951301.358 [Default:CheckIn](INFO): Running loop #23
2021-09-29T21:35:01.358Z,1632951301.358 [Default:CheckIn] Running Loop=23
2021-09-29T21:35:01.358Z,1632951301.358 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:35:01.358Z,1632951301.358 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:35:03.267Z,1632951303.267 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213503.00,A,3648.16294,N,12147.28311,W,0.389,214.77,290921,,,A*77
2021-09-29T21:35:03.278Z,1632951303.278 [NAL9602](INFO): GPS fix at 20210929T213503: (36.802716, -121.788052)
2021-09-29T21:35:03.289Z,1632951303.289 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:35:03.289Z,1632951303.289 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:35:12.971Z,1632951312.971 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0073.lzma
2021-09-29T21:35:13.974Z,1632951313.974 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0073.lzma.bak
2021-09-29T21:35:13.974Z,1632951313.974 [DataOverHttps](INFO): SBD MOMSN=15950635
2021-09-29T21:35:29.836Z,1632951329.836 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20210929T190740/Express0074.lzma
2021-09-29T21:35:30.838Z,1632951330.838 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0074.lzma.bak
2021-09-29T21:35:30.838Z,1632951330.838 [DataOverHttps](INFO): SBD MOMSN=15950638
2021-09-29T21:35:32.741Z,1632951332.741 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:35:32.741Z,1632951332.741 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:35:32.741Z,1632951332.741 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:35:33.954Z,1632951333.954 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T21:35:34.032Z,1632951334.032 [NAL9602](ERROR): received: 
+CSQ:0

OK54, 2, 0, 0, 0

OK
2021-09-29T21:36:03.833Z,1632951363.833 [NAL9602](INFO): SBD MO Status=2, MOMSN=5754, MT Status=2, MTMSN=0
2021-09-29T21:36:03.833Z,1632951363.833 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2021-09-29T21:38:06.244Z,1632951486.244 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2021-09-29T21:40:05.061Z,1632951605.061 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T21:40:33.419Z,1632951633.419 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:40:33.419Z,1632951633.419 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:40:33.419Z,1632951633.419 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:40:33.419Z,1632951633.419 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:40:33.832Z,1632951633.832 [Default:CheckIn:D] Stopped
2021-09-29T21:40:33.832Z,1632951633.832 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:40:34.224Z,1632951634.224 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 148.741211 min 
2021-09-29T21:40:34.224Z,1632951634.224 [Default:CheckIn:E] Stopped
2021-09-29T21:40:34.224Z,1632951634.224 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:40:34.224Z,1632951634.224 [Default:CheckIn] Stopped
2021-09-29T21:40:34.224Z,1632951634.224 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:40:34.225Z,1632951634.225 [Default:CheckIn](INFO): Running loop #24
2021-09-29T21:40:34.225Z,1632951634.225 [Default:CheckIn] Running Loop=24
2021-09-29T21:40:34.225Z,1632951634.225 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:40:34.225Z,1632951634.225 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:40:36.232Z,1632951636.232 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214036.00,A,3648.18152,N,12147.26544,W,0.758,47.51,290921,,,A*44
2021-09-29T21:40:36.234Z,1632951636.234 [NAL9602](INFO): GPS fix at 20210929T214036: (36.803025, -121.787757)
2021-09-29T21:40:36.246Z,1632951636.246 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:40:36.246Z,1632951636.246 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:40:43.535Z,1632951643.535 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210929T190740/Courier0076.lzma
2021-09-29T21:40:44.538Z,1632951644.538 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0076.lzma.bak
2021-09-29T21:40:44.538Z,1632951644.538 [DataOverHttps](INFO): SBD MOMSN=15950641
2021-09-29T21:41:00.456Z,1632951660.456 [DataOverHttps](INFO): Sending 229 bytes from file Logs/20210929T190740/Express0077.lzma
2021-09-29T21:41:01.458Z,1632951661.458 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0077.lzma.bak
2021-09-29T21:41:01.458Z,1632951661.458 [DataOverHttps](INFO): SBD MOMSN=15950644
2021-09-29T21:41:03.954Z,1632951663.954 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:41:03.954Z,1632951663.954 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:41:03.954Z,1632951663.954 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:41:08.205Z,1632951668.205 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T21:41:57.930Z,1632951717.930 [BPC1](INFO): Calculating totals. Valid battery stick count: 28. Valid reserve battery stick count: 3.
2021-09-29T21:41:57.935Z,1632951717.935 [BPC1](FAULT): Failed to receive data from 31 sticks prior to timeout. Missing stick IDs are: 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62.
2021-09-29T21:41:57.935Z,1632951717.935 [BPC1] Data Fault, FailCount= 4
2021-09-29T21:41:57.935Z,1632951717.935 [BPC1](ERROR): Data Fault
2021-09-29T21:41:57.959Z,1632951717.959 [CBIT](ERROR): Data Fault in component: BPC1
2021-09-29T21:46:04.515Z,1632951964.515 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:46:04.515Z,1632951964.515 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:46:04.515Z,1632951964.515 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:46:04.515Z,1632951964.515 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:46:04.933Z,1632951964.933 [Default:CheckIn:D] Stopped
2021-09-29T21:46:04.933Z,1632951964.933 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:46:05.318Z,1632951965.318 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 154.259554 min 
2021-09-29T21:46:05.318Z,1632951965.318 [Default:CheckIn:E] Stopped
2021-09-29T21:46:05.318Z,1632951965.318 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:46:05.318Z,1632951965.318 [Default:CheckIn] Stopped
2021-09-29T21:46:05.318Z,1632951965.318 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:46:05.319Z,1632951965.319 [Default:CheckIn](INFO): Running loop #25
2021-09-29T21:46:05.319Z,1632951965.319 [Default:CheckIn] Running Loop=25
2021-09-29T21:46:05.319Z,1632951965.319 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:46:05.319Z,1632951965.319 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:46:07.311Z,1632951967.311 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214607.00,A,3648.17029,N,12147.28513,W,1.613,29.23,290921,,,A*4C
2021-09-29T21:46:07.314Z,1632951967.314 [NAL9602](INFO): GPS fix at 20210929T214607: (36.802838, -121.788085)
2021-09-29T21:46:07.349Z,1632951967.349 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:46:07.349Z,1632951967.349 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:46:14.915Z,1632951974.915 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20210929T190740/Courier0079.lzma
2021-09-29T21:46:15.930Z,1632951975.930 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0079.lzma.bak
2021-09-29T21:46:15.930Z,1632951975.930 [DataOverHttps](INFO): SBD MOMSN=15950648
2021-09-29T21:46:34.416Z,1632951994.416 [DataOverHttps](INFO): Sending 277 bytes from file Logs/20210929T190740/Express0080.lzma
2021-09-29T21:46:35.418Z,1632951995.418 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0080.lzma.bak
2021-09-29T21:46:35.418Z,1632951995.418 [DataOverHttps](INFO): SBD MOMSN=15950651
2021-09-29T21:46:37.285Z,1632951997.285 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:46:37.285Z,1632951997.285 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:46:37.285Z,1632951997.285 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:46:38.087Z,1632951998.087 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T21:46:38.164Z,1632951998.164 [NAL9602](ERROR): received: 
+CSQ:0

OK54, 2, 0, 0, 0

OK
2021-09-29T21:51:09.225Z,1632952269.225 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-09-29T21:51:37.919Z,1632952297.919 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:51:37.919Z,1632952297.919 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:51:37.919Z,1632952297.919 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:51:37.919Z,1632952297.919 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:51:38.337Z,1632952298.337 [Default:CheckIn:D] Stopped
2021-09-29T21:51:38.337Z,1632952298.337 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:51:38.724Z,1632952298.724 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 159.816292 min 
2021-09-29T21:51:38.724Z,1632952298.724 [Default:CheckIn:E] Stopped
2021-09-29T21:51:38.724Z,1632952298.724 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:51:38.724Z,1632952298.724 [Default:CheckIn] Stopped
2021-09-29T21:51:38.724Z,1632952298.724 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:51:38.725Z,1632952298.725 [Default:CheckIn](INFO): Running loop #26
2021-09-29T21:51:38.725Z,1632952298.725 [Default:CheckIn] Running Loop=26
2021-09-29T21:51:38.725Z,1632952298.725 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:51:38.725Z,1632952298.725 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:51:40.731Z,1632952300.731 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215141.00,A,3648.17584,N,12147.28404,W,1.555,34.79,290921,,,A*4F
2021-09-29T21:51:40.734Z,1632952300.734 [NAL9602](INFO): GPS fix at 20210929T215141: (36.802931, -121.788067)
2021-09-29T21:51:40.745Z,1632952300.745 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T21:51:40.745Z,1632952300.745 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-09-29T21:51:48.007Z,1632952308.007 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210929T190740/Courier0082.lzma
2021-09-29T21:51:49.010Z,1632952309.010 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Courier0082.lzma.bak
2021-09-29T21:51:49.010Z,1632952309.010 [DataOverHttps](INFO): SBD MOMSN=15950655
2021-09-29T21:51:58.932Z,1632952318.932 [CBIT](INFO): Clearing failed state for component BPC1
2021-09-29T21:51:58.932Z,1632952318.932 [BPC1] No Fault, FailCount= 4
2021-09-29T21:52:04.735Z,1632952324.735 [DataOverHttps](INFO): Sending 219 bytes from file Logs/20210929T190740/Express0083.lzma
2021-09-29T21:52:05.738Z,1632952325.738 [DataOverHttps](INFO): Moved sent file to Logs/20210929T190740/Express0083.lzma.bak
2021-09-29T21:52:05.738Z,1632952325.738 [DataOverHttps](INFO): SBD MOMSN=15950658
2021-09-29T21:52:07.416Z,1632952327.416 [Default:CheckIn:Read_Iridium] Stopped
2021-09-29T21:52:07.417Z,1632952327.417 [Default:CheckIn:C.Wait] Running Loop=1
2021-09-29T21:52:07.417Z,1632952327.417 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-09-29T21:52:13.057Z,1632952333.057 [NAL9602](INFO): Not Powering down - fast GPS
2021-09-29T21:57:08.094Z,1632952628.094 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-09-29T21:57:08.094Z,1632952628.094 [Default:CheckIn:C.Wait] Stopped
2021-09-29T21:57:08.094Z,1632952628.094 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-09-29T21:57:08.095Z,1632952628.095 [Default:CheckIn:D] Running Loop=1
2021-09-29T21:57:08.496Z,1632952628.496 [Default:CheckIn:D] Stopped
2021-09-29T21:57:08.496Z,1632952628.496 [Default:CheckIn:E] Running Loop=1
2021-09-29T21:57:08.871Z,1632952628.871 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 165.318929 min 
2021-09-29T21:57:08.872Z,1632952628.872 [Default:CheckIn:E] Stopped
2021-09-29T21:57:08.872Z,1632952628.872 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-09-29T21:57:08.872Z,1632952628.872 [Default:CheckIn] Stopped
2021-09-29T21:57:08.872Z,1632952628.872 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T21:57:08.872Z,1632952628.872 [Default:CheckIn](INFO): Running loop #27
2021-09-29T21:57:08.872Z,1632952628.872 [Default:CheckIn] Running Loop=27
2021-09-29T21:57:08.872Z,1632952628.872 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-09-29T21:57:08.873Z,1632952628.873 [Default:CheckIn:Read_GPS] Running Loop=1
2021-09-29T21:57:41.588Z,1632952661.588 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-09-29T21:57:41.672Z,1632952661.672 [NAL9602](ERROR): received: 
+CSQ:0

OK54, 2, 0, 0, 0

OK
2021-09-29T21:59:09.448Z,1632952749.448 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239311
2021-09-29T21:59:20.200Z,1632952760.200 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002694
2021-09-29T22:00:39.960Z,1632952839.960 [CommandLine](IMPORTANT): got command quit
2021-09-29T22:00:40.964Z,1632952840.964 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2021-09-29T22:00:40.964Z,1632952840.964 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:40.964Z,1632952840.964 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.012Z,1632952841.012 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2021-09-29T22:00:41.012Z,1632952841.012 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.013Z,1632952841.013 [CommandLine](INFO): Join timeout helper Thread ID is 2715
2021-09-29T22:00:41.014Z,1632952841.014 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2021-09-29T22:00:41.015Z,1632952841.015 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.015Z,1632952841.015 [NavChartDb](INFO): Join timeout helper Thread ID is 2716
2021-09-29T22:00:41.180Z,1632952841.180 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:41.180Z,1632952841.180 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.200Z,1632952841.200 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2021-09-29T22:00:41.200Z,1632952841.200 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.200Z,1632952841.200 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 2717
2021-09-29T22:00:41.560Z,1632952841.560 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:41.560Z,1632952841.560 [WetLabsBB2FL](INFO): Powering down
2021-09-29T22:00:41.561Z,1632952841.561 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.572Z,1632952841.572 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2021-09-29T22:00:41.572Z,1632952841.572 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.572Z,1632952841.572 [CTD_Seabird](INFO): Join timeout helper Thread ID is 2718
2021-09-29T22:00:41.908Z,1632952841.908 [CTD_Seabird](INFO): Powering down
2021-09-29T22:00:41.920Z,1632952841.920 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:41.920Z,1632952841.920 [CTD_Seabird](INFO): Powering down
2021-09-29T22:00:41.932Z,1632952841.932 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.932Z,1632952841.932 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2021-09-29T22:00:41.932Z,1632952841.932 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:41.933Z,1632952841.933 [Radio_Surface](INFO): Join timeout helper Thread ID is 2719
2021-09-29T22:00:42.104Z,1632952842.104 [Radio_Surface](INFO): Powering down
2021-09-29T22:00:42.105Z,1632952842.105 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:42.105Z,1632952842.105 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:42.117Z,1632952842.117 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2021-09-29T22:00:42.117Z,1632952842.117 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:42.117Z,1632952842.117 [Onboard](INFO): Join timeout helper Thread ID is 2720
2021-09-29T22:00:42.192Z,1632952842.192 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2021-09-29T22:00:45.576Z,1632952845.576 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:45.576Z,1632952845.576 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:45.592Z,1632952845.592 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2021-09-29T22:00:45.593Z,1632952845.593 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:45.593Z,1632952845.593 [DataOverHttps](INFO): Join timeout helper Thread ID is 2721
2021-09-29T22:00:45.864Z,1632952845.864 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-09-29T22:00:46.208Z,1632952846.208 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:46.208Z,1632952846.208 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.221Z,1632952846.221 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler
2021-09-29T22:00:46.221Z,1632952846.221 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.221Z,1632952846.221 [BackseatComponent](INFO): Join timeout helper Thread ID is 2722
2021-09-29T22:00:46.316Z,1632952846.316 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:46.316Z,1632952846.316 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.329Z,1632952846.329 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2021-09-29T22:00:46.329Z,1632952846.329 [logger ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.329Z,1632952846.329 [logger](INFO): Join timeout helper Thread ID is 2723
2021-09-29T22:00:46.340Z,1632952846.340 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:46.340Z,1632952846.340 [logger ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.348Z,1632952846.348 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2021-09-29T22:00:46.349Z,1632952846.349 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.349Z,1632952846.349 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2021-09-29T22:00:46.349Z,1632952846.349 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.349Z,1632952846.349 [controlThread](INFO): Join timeout helper Thread ID is 2724
2021-09-29T22:00:46.604Z,1632952846.604 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2021-09-29T22:00:46.604Z,1632952846.604 [controlThread](DEBUG): Uninitializing ControlThread
2021-09-29T22:00:46.605Z,1632952846.605 [AHRS_M2](INFO): Powering down
2021-09-29T22:00:46.677Z,1632952846.677 [NAL9602](INFO): Powering down
2021-09-29T22:00:46.679Z,1632952846.679 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2021-09-29T22:00:46.680Z,1632952846.680 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2021-09-29T22:00:46.681Z,1632952846.681 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2021-09-29T22:00:46.681Z,1632952846.681 [MissionManager](INFO): Uninitializing Mission Default
2021-09-29T22:00:46.681Z,1632952846.681 [Default] Stopped
2021-09-29T22:00:46.681Z,1632952846.681 [Default](DEBUG): Aggregate::uninitialize Default
2021-09-29T22:00:46.681Z,1632952846.681 [Default:B.GoToSurface] Stopped
2021-09-29T22:00:46.682Z,1632952846.682 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-09-29T22:00:46.682Z,1632952846.682 [Default:CheckIn] Stopped
2021-09-29T22:00:46.682Z,1632952846.682 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-09-29T22:00:46.682Z,1632952846.682 [Default:CheckIn:Read_GPS] Stopped
2021-09-29T22:00:46.685Z,1632952846.685 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2021-09-29T22:00:46.685Z,1632952846.685 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2021-09-29T22:00:46.686Z,1632952846.686 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2021-09-29T22:00:46.686Z,1632952846.686 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2021-09-29T22:00:46.686Z,1632952846.686 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2021-09-29T22:00:46.686Z,1632952846.686 [BuoyancyServo](INFO): Powering down
2021-09-29T22:00:46.700Z,1632952846.700 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2021-09-29T22:00:46.700Z,1632952846.700 [ElevatorServo](INFO): Powering down
2021-09-29T22:00:46.701Z,1632952846.701 [MassServo](DEBUG): Uninitialize Mass Servo.
2021-09-29T22:00:46.701Z,1632952846.701 [MassServo](INFO): Powering down
2021-09-29T22:00:46.702Z,1632952846.702 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-09-29T22:00:46.702Z,1632952846.702 [RudderServo](INFO): Powering down
2021-09-29T22:00:46.703Z,1632952846.703 [ThrusterHE](DEBUG): Uninitialize Thruster Servo.
2021-09-29T22:00:46.703Z,1632952846.703 [ThrusterHE](INFO): Powering down
2021-09-29T22:00:46.704Z,1632952846.704 [SBIT](DEBUG): Uninitialize SBIT Component.
2021-09-29T22:00:46.705Z,1632952846.705 [IBIT](DEBUG): Uninitialize IBIT Component.
2021-09-29T22:00:46.705Z,1632952846.705 [CBIT](DEBUG): Uninitialize CBIT Component.
2021-09-29T22:00:46.705Z,1632952846.705 [CBIT](DEBUG): Powering off loads.
2021-09-29T22:00:46.716Z,1632952846.716 [CBIT](DEBUG): Disabling WDT.
2021-09-29T22:00:46.728Z,1632952846.728 [CBIT](DEBUG): Opening all GF detection circuits.
2021-09-29T22:00:46.729Z,1632952846.729 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.786Z,1632952846.786 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.789Z,1632952846.789 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.796Z,1632952846.796 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.842Z,1632952846.842 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.874Z,1632952846.874 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.879Z,1632952846.879 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.911Z,1632952846.911 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-09-29T22:00:46.988Z,1632952846.988 [logger ThreadHandler](INFO): Thread cancelled.