2020-09-11T17:15:03.897Z,1599844503.897 [Supervisor](DEBUG): Initializing supervisor.
2020-09-11T17:15:03.899Z,1599844503.899 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2020-09-11T17:15:03.900Z,1599844503.900 [SyncHandler](INFO): Protected caller Thread ID is 3322
2020-09-11T17:15:03.900Z,1599844503.900 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2020-09-11T17:15:03.901Z,1599844503.901 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2020-09-11T17:15:03.902Z,1599844503.902 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3323
2020-09-11T17:15:03.904Z,1599844503.904 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2020-09-11T17:15:03.918Z,1599844503.918 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2020-09-11T17:15:03.919Z,1599844503.919 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2020-09-11T17:15:03.919Z,1599844503.919 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3324
2020-09-11T17:15:03.920Z,1599844503.920 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2020-09-11T17:15:03.921Z,1599844503.921 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2020-09-11T17:15:03.921Z,1599844503.921 [logger ThreadHandler](INFO): Protected caller Thread ID is 3325
2020-09-11T17:15:03.923Z,1599844503.923 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2020-09-11T17:15:03.924Z,1599844503.924 [Supervisor](INFO): Looking for Config files in directory: Config/
2020-09-11T17:15:03.925Z,1599844503.925 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2020-09-11T17:15:04.019Z,1599844504.019 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2020-09-11T17:15:04.019Z,1599844504.019 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2020-09-11T17:15:04.633Z,1599844504.633 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2020-09-11T17:15:04.633Z,1599844504.633 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2020-09-11T17:15:04.826Z,1599844504.826 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2020-09-11T17:15:04.826Z,1599844504.826 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2020-09-11T17:15:04.924Z,1599844504.924 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2020-09-11T17:15:04.925Z,1599844504.925 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2020-09-11T17:15:05.026Z,1599844505.026 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2020-09-11T17:15:05.026Z,1599844505.026 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2020-09-11T17:15:05.105Z,1599844505.105 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2020-09-11T17:15:05.242Z,1599844505.242 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2020-09-11T17:15:05.242Z,1599844505.242 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2020-09-11T17:15:05.534Z,1599844505.534 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2020-09-11T17:15:05.534Z,1599844505.534 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2020-09-11T17:15:05.992Z,1599844505.992 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2020-09-11T17:15:05.992Z,1599844505.992 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2020-09-11T17:15:06.135Z,1599844506.135 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2020-09-11T17:15:06.136Z,1599844506.136 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2020-09-11T17:15:06.401Z,1599844506.401 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2020-09-11T17:15:06.401Z,1599844506.401 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2020-09-11T17:15:06.877Z,1599844506.877 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2020-09-11T17:15:06.878Z,1599844506.878 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2020-09-11T17:15:07.093Z,1599844507.093 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2020-09-11T17:15:07.094Z,1599844507.094 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2020-09-11T17:15:07.297Z,1599844507.297 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2020-09-11T17:15:07.297Z,1599844507.297 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2020-09-11T17:15:07.709Z,1599844507.709 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2020-09-11T17:15:07.710Z,1599844507.710 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2020-09-11T17:15:08.043Z,1599844508.043 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2020-09-11T17:15:08.045Z,1599844508.045 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2020-09-11T17:15:08.046Z,1599844508.046 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2020-09-11T17:15:08.128Z,1599844508.128 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2020-09-11T17:15:08.286Z,1599844508.286 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2020-09-11T17:15:08.392Z,1599844508.392 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2020-09-11T17:15:08.477Z,1599844508.477 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2020-09-11T17:15:08.569Z,1599844508.569 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2020-09-11T17:15:08.786Z,1599844508.786 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2020-09-11T17:15:09.316Z,1599844509.316 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2020-09-11T17:15:09.317Z,1599844509.317 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2020-09-11T17:15:09.519Z,1599844509.519 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2020-09-11T17:15:09.834Z,1599844509.834 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2020-09-11T17:15:09.964Z,1599844509.964 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2020-09-11T17:15:10.063Z,1599844510.063 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/root/
2020-09-11T17:15:10.063Z,1599844510.063 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2020-09-11T17:15:10.079Z,1599844510.079 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2020-09-11T17:15:10.155Z,1599844510.155 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2020-09-11T17:15:10.156Z,1599844510.156 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2020-09-11T17:15:10.202Z,1599844510.202 [VerticalControl](DEBUG): Construct VerticalControl.
2020-09-11T17:15:10.315Z,1599844510.315 [VerticalControl] Loaded
2020-09-11T17:15:10.315Z,1599844510.315 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2020-09-11T17:15:10.316Z,1599844510.316 [HorizontalControl](DEBUG): Construct HorizontalControl.
2020-09-11T17:15:10.396Z,1599844510.396 [HorizontalControl] Loaded
2020-09-11T17:15:10.396Z,1599844510.396 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2020-09-11T17:15:10.397Z,1599844510.397 [SpeedControl](DEBUG): Construct SpeedControl.
2020-09-11T17:15:10.403Z,1599844510.403 [SpeedControl] Loaded
2020-09-11T17:15:10.403Z,1599844510.403 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2020-09-11T17:15:10.404Z,1599844510.404 [LoopControl](DEBUG): Construct LoopControl.
2020-09-11T17:15:10.404Z,1599844510.404 [LoopControl] Loaded
2020-09-11T17:15:10.404Z,1599844510.404 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2020-09-11T17:15:10.405Z,1599844510.405 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2020-09-11T17:15:10.405Z,1599844510.405 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2020-09-11T17:15:10.446Z,1599844510.446 [DepthRateCalculator] Loaded
2020-09-11T17:15:10.446Z,1599844510.446 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2020-09-11T17:15:10.452Z,1599844510.452 [PitchRateCalculator] Loaded
2020-09-11T17:15:10.452Z,1599844510.452 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2020-09-11T17:15:10.467Z,1599844510.467 [SpeedCalculator] Loaded
2020-09-11T17:15:10.468Z,1599844510.468 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2020-09-11T17:15:10.490Z,1599844510.490 [TempGradientCalculator] Loaded
2020-09-11T17:15:10.490Z,1599844510.490 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2020-09-11T17:15:10.495Z,1599844510.495 [YawRateCalculator] Loaded
2020-09-11T17:15:10.495Z,1599844510.495 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2020-09-11T17:15:10.525Z,1599844510.525 [ElevatorOffsetCalculator] Loaded
2020-09-11T17:15:10.525Z,1599844510.525 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2020-09-11T17:15:10.525Z,1599844510.525 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2020-09-11T17:15:10.526Z,1599844510.526 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2020-09-11T17:15:10.552Z,1599844510.552 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2020-09-11T17:15:10.553Z,1599844510.553 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2020-09-11T17:15:10.636Z,1599844510.636 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2020-09-11T17:15:10.636Z,1599844510.636 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2020-09-11T17:15:10.919Z,1599844510.919 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2020-09-11T17:15:10.920Z,1599844510.920 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2020-09-11T17:15:11.016Z,1599844511.016 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2020-09-11T17:15:11.017Z,1599844511.017 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2020-09-11T17:15:11.323Z,1599844511.323 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2020-09-11T17:15:11.328Z,1599844511.328 [AHRS_M2](INFO): created writer for : platform_orientation
2020-09-11T17:15:11.329Z,1599844511.329 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2020-09-11T17:15:11.335Z,1599844511.335 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2020-09-11T17:15:11.335Z,1599844511.335 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2020-09-11T17:15:11.340Z,1599844511.340 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2020-09-11T17:15:11.341Z,1599844511.341 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2020-09-11T17:15:11.346Z,1599844511.346 [AHRS_M2](INFO): created writer for : platform_roll_angle
2020-09-11T17:15:11.417Z,1599844511.417 [AHRS_M2] Loaded
2020-09-11T17:15:11.417Z,1599844511.417 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2020-09-11T17:15:11.495Z,1599844511.495 [DataOverHttps] Loaded
2020-09-11T17:15:11.496Z,1599844511.496 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2020-09-11T17:15:11.497Z,1599844511.497 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4090D4E0
2020-09-11T17:15:11.497Z,1599844511.497 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3408
2020-09-11T17:15:11.527Z,1599844511.527 [Depth_Keller] Loaded
2020-09-11T17:15:11.528Z,1599844511.528 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2020-09-11T17:15:11.532Z,1599844511.532 [DropWeight] Loaded
2020-09-11T17:15:11.533Z,1599844511.533 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2020-09-11T17:15:11.647Z,1599844511.647 [NAL9602] Loaded
2020-09-11T17:15:11.647Z,1599844511.647 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2020-09-11T17:15:11.697Z,1599844511.697 [Onboard] Loaded
2020-09-11T17:15:11.697Z,1599844511.697 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2020-09-11T17:15:11.698Z,1599844511.698 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4093D4E0
2020-09-11T17:15:11.698Z,1599844511.698 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 3409
2020-09-11T17:15:11.718Z,1599844511.718 [Radio_Surface] Loaded
2020-09-11T17:15:11.718Z,1599844511.718 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2020-09-11T17:15:11.719Z,1599844511.719 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4096D4E0
2020-09-11T17:15:11.719Z,1599844511.719 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3410
2020-09-11T17:15:11.870Z,1599844511.870 [DAT] Loaded
2020-09-11T17:15:11.871Z,1599844511.871 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2020-09-11T17:15:13.368Z,1599844513.368 [BPC1] Loaded
2020-09-11T17:15:13.368Z,1599844513.368 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2020-09-11T17:15:13.401Z,1599844513.401 [AMEcho] Loaded
2020-09-11T17:15:13.401Z,1599844513.401 [ComponentRegistry](DEBUG): SyncComponent "AMEcho" handled in the control thread.
2020-09-11T17:15:13.401Z,1599844513.401 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2020-09-11T17:15:13.402Z,1599844513.402 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2020-09-11T17:15:13.520Z,1599844513.520 [DeadReckonUsingMultipleVelocitySources] Loaded
2020-09-11T17:15:13.520Z,1599844513.520 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2020-09-11T17:15:13.541Z,1599844513.541 [NavChart] Loaded
2020-09-11T17:15:13.541Z,1599844513.541 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2020-09-11T17:15:13.545Z,1599844513.545 [UniversalFixResidualReporter] Loaded
2020-09-11T17:15:13.546Z,1599844513.546 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2020-09-11T17:15:13.546Z,1599844513.546 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2020-09-11T17:15:13.547Z,1599844513.547 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2020-09-11T17:15:13.679Z,1599844513.679 [SBIT](DEBUG): Construct Startup Built In Test.
2020-09-11T17:15:13.690Z,1599844513.690 [SBIT] Loaded
2020-09-11T17:15:13.691Z,1599844513.691 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2020-09-11T17:15:13.691Z,1599844513.691 [IBIT](DEBUG): Construct Initiated Built In Test.
2020-09-11T17:15:13.704Z,1599844513.704 [IBIT] Loaded
2020-09-11T17:15:13.705Z,1599844513.705 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2020-09-11T17:15:13.708Z,1599844513.708 [CBIT](DEBUG): Construct Continuous Built In Test.
2020-09-11T17:15:13.850Z,1599844513.850 [CBIT] Loaded
2020-09-11T17:15:13.850Z,1599844513.850 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2020-09-11T17:15:13.850Z,1599844513.850 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2020-09-11T17:15:13.851Z,1599844513.851 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2020-09-11T17:15:14.072Z,1599844514.072 [BuoyancyServo] Loaded
2020-09-11T17:15:14.072Z,1599844514.072 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2020-09-11T17:15:14.122Z,1599844514.122 [ElevatorServo] Loaded
2020-09-11T17:15:14.122Z,1599844514.122 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2020-09-11T17:15:14.150Z,1599844514.150 [MassServo] Loaded
2020-09-11T17:15:14.151Z,1599844514.151 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2020-09-11T17:15:14.178Z,1599844514.178 [RudderServo] Loaded
2020-09-11T17:15:14.178Z,1599844514.178 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2020-09-11T17:15:14.205Z,1599844514.205 [ThrusterServo] Loaded
2020-09-11T17:15:14.206Z,1599844514.206 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2020-09-11T17:15:14.206Z,1599844514.206 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2020-09-11T17:15:14.207Z,1599844514.207 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2020-09-11T17:15:14.225Z,1599844514.225 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2020-09-11T17:15:14.225Z,1599844514.225 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2020-09-11T17:15:14.463Z,1599844514.463 [BackSeatDriver] Loaded
2020-09-11T17:15:14.464Z,1599844514.464 [ComponentRegistry](DEBUG): Component "BackSeatDriver" handled in its own thread.
2020-09-11T17:15:14.465Z,1599844514.465 [BackSeatDriver ThreadHandler](DEBUG): Created PCaller Thread at 40B034E0
2020-09-11T17:15:14.465Z,1599844514.465 [BackSeatDriver ThreadHandler](INFO): Protected caller Thread ID is 3411
2020-09-11T17:15:14.494Z,1599844514.494 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2020-09-11T17:15:14.499Z,1599844514.499 [CTD_Seabird](INFO): created writer for : sea_water_density
2020-09-11T17:15:14.500Z,1599844514.500 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2020-09-11T17:15:14.506Z,1599844514.506 [CTD_Seabird](INFO): created writer for : depth
2020-09-11T17:15:14.506Z,1599844514.506 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2020-09-11T17:15:14.511Z,1599844514.511 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2020-09-11T17:15:14.512Z,1599844514.512 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2020-09-11T17:15:14.517Z,1599844514.517 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2020-09-11T17:15:14.517Z,1599844514.517 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2020-09-11T17:15:14.522Z,1599844514.522 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2020-09-11T17:15:14.523Z,1599844514.523 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2020-09-11T17:15:14.529Z,1599844514.529 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2020-09-11T17:15:14.529Z,1599844514.529 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2020-09-11T17:15:14.535Z,1599844514.535 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2020-09-11T17:15:14.563Z,1599844514.563 [CTD_Seabird] Loaded
2020-09-11T17:15:14.563Z,1599844514.563 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2020-09-11T17:15:14.564Z,1599844514.564 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B334E0
2020-09-11T17:15:14.564Z,1599844514.564 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 3412
2020-09-11T17:15:14.587Z,1599844514.587 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470
2020-09-11T17:15:14.587Z,1599844514.587 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470
2020-09-11T17:15:14.591Z,1599844514.591 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650
2020-09-11T17:15:14.591Z,1599844514.591 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650
2020-09-11T17:15:14.595Z,1599844514.595 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl
2020-09-11T17:15:14.595Z,1599844514.595 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl
2020-09-11T17:15:14.600Z,1599844514.600 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm
2020-09-11T17:15:14.600Z,1599844514.600 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm
2020-09-11T17:15:14.604Z,1599844514.604 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm
2020-09-11T17:15:14.604Z,1599844514.604 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm
2020-09-11T17:15:14.609Z,1599844514.609 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm
2020-09-11T17:15:14.609Z,1599844514.609 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm
2020-09-11T17:15:14.613Z,1599844514.613 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm
2020-09-11T17:15:14.613Z,1599844514.613 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm
2020-09-11T17:15:14.618Z,1599844514.618 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.622Z,1599844514.622 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.623Z,1599844514.623 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.623Z,1599844514.623 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.627Z,1599844514.627 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.627Z,1599844514.627 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.631Z,1599844514.631 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.631Z,1599844514.631 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2020-09-11T17:15:14.636Z,1599844514.636 [WetLabsBB2FL] Loaded
2020-09-11T17:15:14.636Z,1599844514.636 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2020-09-11T17:15:14.637Z,1599844514.637 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B634E0
2020-09-11T17:15:14.637Z,1599844514.637 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 3413
2020-09-11T17:15:14.638Z,1599844514.638 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2020-09-11T17:15:14.642Z,1599844514.642 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2020-09-11T17:15:14.643Z,1599844514.643 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2020-09-11T17:15:14.650Z,1599844514.650 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2020-09-11T17:15:14.651Z,1599844514.651 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B934E0
2020-09-11T17:15:14.651Z,1599844514.651 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3414
2020-09-11T17:15:14.656Z,1599844514.656 [Supervisor](INFO): Main Thread ID is 3321
2020-09-11T17:15:14.656Z,1599844514.656 [Supervisor](DEBUG): Running supervisor.
2020-09-11T17:15:14.657Z,1599844514.657 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3415
2020-09-11T17:15:14.659Z,1599844514.659 [controlThread ThreadHandler](INFO): Handler Thread ID is 3416
2020-09-11T17:15:14.660Z,1599844514.660 [controlThread](DEBUG): Initializing ControlThread
2020-09-11T17:15:14.660Z,1599844514.660 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2020-09-11T17:15:14.662Z,1599844514.662 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2020-09-11T17:15:14.663Z,1599844514.663 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2020-09-11T17:15:14.663Z,1599844514.663 [LoopControl](DEBUG): Initialize LoopControlComponent.
2020-09-11T17:15:14.664Z,1599844514.664 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2020-09-11T17:15:14.664Z,1599844514.664 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2020-09-11T17:15:14.664Z,1599844514.664 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2020-09-11T17:15:14.665Z,1599844514.665 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2020-09-11T17:15:14.665Z,1599844514.665 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2020-09-11T17:15:14.665Z,1599844514.665 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2020-09-11T17:15:14.672Z,1599844514.672 [NavChart](DEBUG): Initialize NavChart Navigation.
2020-09-11T17:15:14.672Z,1599844514.672 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2020-09-11T17:15:14.672Z,1599844514.672 [SBIT](INFO): Initialize SBIT Component.
2020-09-11T17:15:14.673Z,1599844514.673 [SBIT](IMPORTANT): git: 2020-08-31
2020-09-11T17:15:14.673Z,1599844514.673 [SBIT](INFO): git hash: b6c0ec5a69f4280de3f7606c4f2437bb78ebd873
2020-09-11T17:15:14.674Z,1599844514.674 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2020-09-11T17:15:14.675Z,1599844514.675 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
Kernel Reported: #1 PREEMPT Thu Aug 6 12:04:53 PDT 2020
2020-09-11T17:15:14.676Z,1599844514.676 [SBIT](INFO): Beginning SBIT in 75.000000 seconds.
2020-09-11T17:15:14.676Z,1599844514.676 [IBIT](INFO): Initialize IBIT Component.
2020-09-11T17:15:14.677Z,1599844514.677 [CBIT](DEBUG): Initialize CBIT Component.
2020-09-11T17:15:14.678Z,1599844514.678 [logger ThreadHandler](INFO): Handler Thread ID is 3417
2020-09-11T17:15:14.689Z,1599844514.689 [CBIT](DEBUG): Initialized mux pins.
2020-09-11T17:15:14.689Z,1599844514.689 [CBIT](DEBUG): Initializing the watchdog timer.
2020-09-11T17:15:14.698Z,1599844514.698 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3418
2020-09-11T17:15:14.699Z,1599844514.699 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2020-09-11T17:15:14.710Z,1599844514.710 [Onboard ThreadHandler](INFO): Handler Thread ID is 3419
2020-09-11T17:15:14.714Z,1599844514.714 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2020-09-11T17:15:14.714Z,1599844514.714 [CBIT](DEBUG): Initializing heartbeat.
2020-09-11T17:15:14.727Z,1599844514.727 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3420
2020-09-11T17:15:14.750Z,1599844514.750 [BackSeatDriver ThreadHandler](INFO): Handler Thread ID is 3421
2020-09-11T17:15:14.769Z,1599844514.769 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 3422
2020-09-11T17:15:14.770Z,1599844514.770 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2020-09-11T17:15:14.775Z,1599844514.775 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 3424
2020-09-11T17:15:14.775Z,1599844514.775 [WetLabsBB2FL](INFO): Powering down
2020-09-11T17:15:14.785Z,1599844514.785 [CBIT](DEBUG): Deactivating GF circuits.
2020-09-11T17:15:14.786Z,1599844514.786 [CBIT](DEBUG): Deactivating emergency mode.
2020-09-11T17:15:14.810Z,1599844514.810 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3425
2020-09-11T17:15:14.813Z,1599844514.813 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2020-09-11T17:15:14.813Z,1599844514.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2020-09-11T17:15:14.813Z,1599844514.813 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2020-09-11T17:15:14.813Z,1599844514.813 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2020-09-11T17:15:14.813Z,1599844514.813 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2020-09-11T17:15:14.814Z,1599844514.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2020-09-11T17:15:14.814Z,1599844514.814 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2020-09-11T17:15:14.814Z,1599844514.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2020-09-11T17:15:14.814Z,1599844514.814 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2020-09-11T17:15:14.814Z,1599844514.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2020-09-11T17:15:14.814Z,1599844514.814 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2020-09-11T17:15:14.814Z,1599844514.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2020-09-11T17:15:14.815Z,1599844514.815 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2020-09-11T17:15:14.815Z,1599844514.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2020-09-11T17:15:14.815Z,1599844514.815 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2020-09-11T17:15:14.815Z,1599844514.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2020-09-11T17:15:14.821Z,1599844514.821 [CBIT](DEBUG): Backplane powered.
2020-09-11T17:15:14.824Z,1599844514.824 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2020-09-11T17:15:14.838Z,1599844514.838 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2020-09-11T17:15:14.857Z,1599844514.857 [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>


2020-09-11T17:15:14.877Z,1599844514.877 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2020-09-11T17:15:14.940Z,1599844514.940 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2020-09-11T17:15:14.957Z,1599844514.957 [Default:A.Wait](DEBUG): Construct Wait.
2020-09-11T17:15:14.959Z,1599844514.959 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2020-09-11T17:15:15.005Z,1599844515.005 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2020-09-11T17:15:15.008Z,1599844515.008 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2020-09-11T17:15:15.028Z,1599844515.028 [Default:E.Execute](DEBUG): Construct Execute.
2020-09-11T17:15:15.031Z,1599844515.031 [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>


2020-09-11T17:15:15.049Z,1599844515.049 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,DAT,BPC1,AMEcho,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2020-09-11T17:15:15.054Z,1599844515.054 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2020-09-11T17:15:15.087Z,1599844515.087 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar
2020-09-11T17:15:15.090Z,1599844515.090 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2020-09-11T17:15:15.091Z,1599844515.091 [DAT](INFO): Powering up
2020-09-11T17:15:15.091Z,1599844515.091 [DAT](DEBUG): Initializing DAT.
2020-09-11T17:15:15.133Z,1599844515.133 [Radio_Surface](INFO): Powering up
2020-09-11T17:15:15.138Z,1599844515.138 [AMEcho](INFO): Powering up
2020-09-11T17:15:15.157Z,1599844515.157 [DepthRateCalculator](ERROR): Depth measurement is not active
2020-09-11T17:15:15.161Z,1599844515.161 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2020-09-11T17:15:15.209Z,1599844515.209 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-09-11T17:15:15.221Z,1599844515.221 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-09-11T17:15:15.223Z,1599844515.223 [ElevatorServo](DEBUG): Initializing EZServoServo.
2020-09-11T17:15:15.233Z,1599844515.233 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2020-09-11T17:15:15.235Z,1599844515.235 [MassServo](DEBUG): Initializing EZServoServo.
2020-09-11T17:15:15.245Z,1599844515.245 [MassServo](DEBUG): Initializing MassServo.
2020-09-11T17:15:15.246Z,1599844515.246 [RudderServo](DEBUG): Initializing EZServoServo.
2020-09-11T17:15:15.262Z,1599844515.262 [RudderServo](DEBUG): Initializing RudderServo.
2020-09-11T17:15:15.263Z,1599844515.263 [ThrusterServo](DEBUG): Initializing EZServoServo.
2020-09-11T17:15:15.273Z,1599844515.273 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2020-09-11T17:15:15.483Z,1599844515.483 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2020-09-11T17:15:15.483Z,1599844515.483 [DropWeight] Hardware Fault, FailCount= 1
2020-09-11T17:15:15.483Z,1599844515.483 [DropWeight](ERROR): Hardware Fault
2020-09-11T17:15:15.653Z,1599844515.653 [AMEcho](INFO): Powering down
2020-09-11T17:15:15.667Z,1599844515.667 [CommandLine](FAULT): Scheduling is paused
2020-09-11T17:15:15.667Z,1599844515.667 [CBIT](INFO): Critical error at 20200911T171515
2020-09-11T17:15:15.667Z,1599844515.667 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2020-09-11T17:15:15.670Z,1599844515.670 [CBIT](ERROR): Hardware Fault in component: DropWeight
2020-09-11T17:15:15.670Z,1599844515.670 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2020-09-11T17:15:16.189Z,1599844516.189 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2020-09-11T17:15:16.189Z,1599844516.189 [RudderServo](FAULT): Rudder failed to initialize
2020-09-11T17:15:16.189Z,1599844516.189 [RudderServo] Communications Fault, FailCount= 1
2020-09-11T17:15:16.189Z,1599844516.189 [RudderServo](ERROR): Communications Fault
2020-09-11T17:15:16.298Z,1599844516.298 [CBIT](INFO): Critical error at 20200911T171515
2020-09-11T17:15:16.301Z,1599844516.301 [CBIT](ERROR): Communications Fault in component: RudderServo
2020-09-11T17:15:16.466Z,1599844516.466 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2020-09-11T17:15:16.466Z,1599844516.466 [RudderServo](INFO): Powering down
2020-09-11T17:15:17.129Z,1599844517.129 [RudderServo](DEBUG): Initializing EZServoServo.
2020-09-11T17:15:17.250Z,1599844517.250 [RudderServo](DEBUG): Initializing RudderServo.
2020-09-11T17:15:17.254Z,1599844517.254 [CBIT](INFO): Clearing failed state for component RudderServo
2020-09-11T17:15:17.254Z,1599844517.254 [RudderServo] No Fault, FailCount= 1
2020-09-11T17:15:18.649Z,1599844518.649 [AHRS_M2](ERROR): setBoresightMatrix UART error: serial timeout
2020-09-11T17:15:19.053Z,1599844519.053 [AHRS_M2](ERROR): setBoresightMatrix UART error: serial timeout
2020-09-11T17:15:19.521Z,1599844519.521 [AHRS_M2](ERROR): setBoresightMatrix UART error: serial timeout
2020-09-11T17:15:25.799Z,1599844525.799 [DAT](INFO): DAT read: 

2020-09-11T17:15:25.800Z,1599844525.800 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2020-09-11T17:15:27.011Z,1599844527.011 [DAT](INFO): DAT read: MF Frequency Band

2020-09-11T17:15:27.012Z,1599844527.012 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.12.21

2020-09-11T17:15:27.013Z,1599844527.013 [DAT](INFO): DAT read: Sep 11 2020 17:15:02 

2020-09-11T17:15:27.819Z,1599844527.819 [DAT](INFO): DAT read: Features enabled [Bearing]

2020-09-11T17:15:27.821Z,1599844527.821 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2020-09-11T17:15:27.821Z,1599844527.821 [DAT](INFO): commRate: 800
2020-09-11T17:15:27.821Z,1599844527.821 [DAT](INFO): commRate: 800
2020-09-11T17:15:28.111Z,1599844528.111 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004745
2020-09-11T17:15:28.223Z,1599844528.223 [DAT](INFO): entering command mode
2020-09-11T17:15:28.627Z,1599844528.627 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:29.031Z,1599844529.031 [DAT](INFO): DAT read: 

2020-09-11T17:15:29.031Z,1599844529.031 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:29.434Z,1599844529.434 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:29.847Z,1599844529.847 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:30.253Z,1599844530.253 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:30.646Z,1599844530.646 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:31.050Z,1599844531.050 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:31.454Z,1599844531.454 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:31.859Z,1599844531.859 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:32.263Z,1599844532.263 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:32.667Z,1599844532.667 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:33.070Z,1599844533.070 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:33.475Z,1599844533.475 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:33.879Z,1599844533.879 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:34.283Z,1599844534.283 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:34.707Z,1599844534.707 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:35.119Z,1599844535.119 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:35.547Z,1599844535.547 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:35.939Z,1599844535.939 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:36.335Z,1599844536.335 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:36.723Z,1599844536.723 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:37.131Z,1599844537.131 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:37.531Z,1599844537.531 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:37.947Z,1599844537.947 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:38.343Z,1599844538.343 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:38.747Z,1599844538.747 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:39.151Z,1599844539.151 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:39.551Z,1599844539.551 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:39.954Z,1599844539.954 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:40.358Z,1599844540.358 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:40.763Z,1599844540.763 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:41.166Z,1599844541.166 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:41.581Z,1599844541.581 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:41.976Z,1599844541.976 [NAL9602](INFO): Powering up NAL9602
2020-09-11T17:15:41.978Z,1599844541.978 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:42.382Z,1599844542.382 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:42.782Z,1599844542.782 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:43.187Z,1599844543.187 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:43.591Z,1599844543.591 [DAT](DEBUG): checking for command mode acknowledgment
2020-09-11T17:15:43.591Z,1599844543.591 [DAT](FAULT): failed to enter command mode
2020-09-11T17:15:43.995Z,1599844543.995 [DAT](INFO): entering command mode
2020-09-11T17:15:44.399Z,1599844544.399 [DAT](INFO): DAT read: user:1>

2020-09-11T17:15:44.400Z,1599844544.400 [DAT](INFO): DAT read: Command '+++' not found

2020-09-11T17:15:44.400Z,1599844544.400 [DAT](INFO): DAT read: Error

2020-09-11T17:15:44.400Z,1599844544.400 [DAT](INFO): setting verbose to 3
2020-09-11T17:15:44.799Z,1599844544.799 [DAT](INFO): DAT read: user:2>

2020-09-11T17:15:44.800Z,1599844544.800 [DAT](INFO): DAT read: Verbose         | 3           

2020-09-11T17:15:44.800Z,1599844544.800 [DAT](INFO): set verbose to 3
2020-09-11T17:15:44.800Z,1599844544.800 [DAT](INFO): setting DatVerbose to 27440
2020-09-11T17:15:45.207Z,1599844545.207 [DAT](INFO): DAT read: user:3>

2020-09-11T17:15:45.208Z,1599844545.208 [DAT](INFO): DAT read: DatVerbose      | 27440       

2020-09-11T17:15:45.208Z,1599844545.208 [DAT](INFO): set DatVerbose to 27440
2020-09-11T17:15:45.208Z,1599844545.208 [DAT](INFO): setting transmit power to 8
2020-09-11T17:15:45.611Z,1599844545.611 [DAT](INFO): DAT read: user:4>

2020-09-11T17:15:45.612Z,1599844545.612 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2020-09-11T17:15:45.612Z,1599844545.612 [DAT](INFO): set transmit power to 8
2020-09-11T17:15:45.612Z,1599844545.612 [DAT](INFO): setting local address to 9
2020-09-11T17:15:46.015Z,1599844546.015 [DAT](INFO): DAT read: user:5>

2020-09-11T17:15:46.016Z,1599844546.016 [DAT](INFO): DAT read: LocalAddr       | 9           

2020-09-11T17:15:46.016Z,1599844546.016 [DAT](INFO): set local address to 9
2020-09-11T17:15:52.883Z,1599844552.883 [NAL9602](INFO): NAL9602 initialized
2020-09-11T17:16:19.548Z,1599844579.548 [NAL9602](INFO): SBD MO Status=2, MOMSN=9603, MT Status=2, MTMSN=0
2020-09-11T17:16:19.548Z,1599844579.548 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T17:16:30.488Z,1599844590.488 [SBIT](IMPORTANT): Beginning Startup BIT
2020-09-11T17:16:30.500Z,1599844590.500 [CBIT](IMPORTANT): Beginning ground fault scan
2020-09-11T17:16:41.413Z,1599844601.413 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.002613
CHAN A1 (24V): -0.000454
CHAN A2 (12V): -0.006955
CHAN A3 (5V): -0.002172
CHAN B0 (3.3V): 0.000634
CHAN B1 (3.15aV): -0.000360
CHAN B2 (3.15bV): -0.000072
CHAN B3 (GND): 0.002374
OPEN: -0.004076
Full Scale Calc: 4.765 mA, -1.589 mA
2020-09-11T17:17:18.128Z,1599844638.128 [NAL9602](INFO): SBD MO Status=2, MOMSN=9603, MT Status=2, MTMSN=0
2020-09-11T17:17:18.128Z,1599844638.128 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T17:17:24.218Z,1599844644.218 [SBIT](IMPORTANT): SBIT PASSED
2020-09-11T17:17:24.218Z,1599844644.218 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2020-09-11T17:17:24.219Z,1599844644.219 [SBIT](IMPORTANT): AMEcho.enabled=1 bool;

2020-09-11T17:17:24.219Z,1599844644.219 [SBIT](IMPORTANT): CBIT.gf24Offset=145 microampere;

2020-09-11T17:17:24.219Z,1599844644.219 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2020-09-11T17:17:24.219Z,1599844644.219 [SBIT](IMPORTANT): DAT.sbdAddress=0 enum;

2020-09-11T17:17:24.219Z,1599844644.219 [SBIT](IMPORTANT): DAT.surfaceThreshold=5 meter;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): DAT.verbosity=3 count;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): Express linearApproximation AMEcho.altitude 1.000000 meter;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): Express none ThrusterServo.component_avgCurrent;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 1.000000 liter_per_second;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): IBIT.batteryVoltageThreshold=13 volt;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): RDI_Pathfinder.loadAtStartup=0 bool;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=146.161014 cubic_centimeter;

2020-09-11T17:17:24.220Z,1599844644.220 [SBIT](IMPORTANT): VerticalControl.massDefault=13.952984 millimeter;

2020-09-11T17:17:24.221Z,1599844644.221 [SBIT](IMPORTANT): WetLabsUBAT.loadAtStartup=0 bool;

2020-09-11T17:17:24.606Z,1599844644.606 [MissionManager](IMPORTANT): Started mission Startup
2020-09-11T17:17:24.607Z,1599844644.607 [Startup] Running Loop=1
2020-09-11T17:17:24.607Z,1599844644.607 [Startup](DEBUG): Aggregate::initialize Startup
2020-09-11T17:17:24.607Z,1599844644.607 [Startup:A.GoToSurface] Running Loop=1
2020-09-11T17:17:24.607Z,1599844644.607 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-09-11T17:17:24.607Z,1599844644.607 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-09-11T17:17:24.608Z,1599844644.608 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-09-11T17:17:24.608Z,1599844644.608 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-09-11T17:17:24.609Z,1599844644.609 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-09-11T17:17:24.609Z,1599844644.609 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-09-11T17:17:24.610Z,1599844644.610 [Startup:StartupSatComms] Running Loop=1
2020-09-11T17:17:24.611Z,1599844644.611 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2020-09-11T17:17:24.611Z,1599844644.611 [Startup:StartupSatComms:A] Running Loop=1
2020-09-11T17:17:25.012Z,1599844645.012 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2020-09-11T17:17:25.400Z,1599844645.400 [AMEcho](INFO): Powering up
2020-09-11T17:17:48.432Z,1599844668.432 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:17:52.251Z,1599844672.251 [CommandLine](IMPORTANT): got command ! ntpq -pn
2020-09-11T17:17:52.374Z,1599844672.374 [CommandLine](IMPORTANT):      remote           refid      st t when poll reach   delay   offset  jitter
  ==============================================================================
  *134.89.10.5     .GPS.            1 u   30   64  377    0.790  -199.20 107.905
   127.127.1.0     .LOCL.          10 l  745   64    0    0.000   +0.000   0.000
  +3.217.79.242    209.51.161.238   2 u   22   64  377   69.065  -139.09 163.500
  +45.76.244.193   216.239.35.0     2 u   17   64  377   24.084  -202.26 120.353
  
2020-09-11T17:18:01.360Z,1599844681.360 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:18:13.895Z,1599844693.895 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:18:14.701Z,1599844694.701 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2020-09-11T17:18:14.701Z,1599844694.701 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2020-09-11T17:18:14.749Z,1599844694.749 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2020-09-11T17:18:15.152Z,1599844695.152 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2020-09-11T17:18:15.152Z,1599844695.152 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2020-09-11T17:18:24.806Z,1599844704.806 [Startup:StartupSatComms:A](INFO): Timed out from 2020-09-11T17:17:24.6Z
2020-09-11T17:18:24.806Z,1599844704.806 [Startup:StartupSatComms:A] Stopped
2020-09-11T17:18:24.806Z,1599844704.806 [Startup:StartupSatComms:B] Running Loop=1
2020-09-11T17:18:25.204Z,1599844705.204 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-09-11T17:18:26.826Z,1599844706.826 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:18:32.077Z,1599844712.077 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20061002T183518/Courier0037.lzma
2020-09-11T17:18:33.079Z,1599844713.079 [DataOverHttps](INFO): Moved sent file to Logs/20061002T183518/Courier0037.lzma.bak
2020-09-11T17:18:33.079Z,1599844713.079 [DataOverHttps](INFO): SBD MOMSN=12648148
2020-09-11T17:18:39.346Z,1599844719.346 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:18:48.308Z,1599844728.308 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20061002T194754/Courier0000.lzma
2020-09-11T17:18:49.311Z,1599844729.311 [DataOverHttps](INFO): Moved sent file to Logs/20061002T194754/Courier0000.lzma.bak
2020-09-11T17:18:49.311Z,1599844729.311 [DataOverHttps](INFO): SBD MOMSN=12648150
2020-09-11T17:18:51.190Z,1599844731.190 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:19:04.518Z,1599844744.518 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:19:04.816Z,1599844744.816 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20200911T171503/Courier0000.lzma
2020-09-11T17:19:05.817Z,1599844745.817 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0000.lzma.bak
2020-09-11T17:19:05.817Z,1599844745.817 [DataOverHttps](INFO): SBD MOMSN=12648155
2020-09-11T17:19:17.061Z,1599844757.061 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:19:21.323Z,1599844761.323 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20061002T183518/Express0038.lzma
2020-09-11T17:19:22.326Z,1599844762.326 [DataOverHttps](INFO): Moved sent file to Logs/20061002T183518/Express0038.lzma.bak
2020-09-11T17:19:22.326Z,1599844762.326 [DataOverHttps](INFO): SBD MOMSN=12648160
2020-09-11T17:19:25.142Z,1599844765.142 [Startup:StartupSatComms:B](INFO): Timed out from 2020-09-11T17:18:24.8Z
2020-09-11T17:19:25.142Z,1599844765.142 [Startup:StartupSatComms:B] Stopped
2020-09-11T17:19:25.142Z,1599844765.142 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2020-09-11T17:19:25.142Z,1599844765.142 [Startup:StartupSatComms] Stopped
2020-09-11T17:19:25.142Z,1599844765.142 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2020-09-11T17:19:25.143Z,1599844765.143 [Startup](INFO): Completed Startup
2020-09-11T17:19:25.143Z,1599844765.143 [MissionManager](INFO): Startup is completed.
2020-09-11T17:19:25.143Z,1599844765.143 [MissionManager](INFO): Uninitializing Mission Startup
2020-09-11T17:19:25.143Z,1599844765.143 [Startup] Stopped
2020-09-11T17:19:25.144Z,1599844765.144 [Startup](DEBUG): Aggregate::uninitialize Startup
2020-09-11T17:19:25.144Z,1599844765.144 [Startup:A.GoToSurface] Stopped
2020-09-11T17:19:25.144Z,1599844765.144 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-09-11T17:19:25.558Z,1599844765.558 [MissionManager](IMPORTANT): Started mission Default
2020-09-11T17:19:25.558Z,1599844765.558 [Default] Running Loop=1
2020-09-11T17:19:25.558Z,1599844765.558 [Default](DEBUG): Aggregate::initialize Default
2020-09-11T17:19:25.558Z,1599844765.558 [Default:B.GoToSurface] Running Loop=1
2020-09-11T17:19:25.558Z,1599844765.558 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-09-11T17:19:25.559Z,1599844765.559 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-09-11T17:19:25.559Z,1599844765.559 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-09-11T17:19:25.559Z,1599844765.559 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-09-11T17:19:25.560Z,1599844765.560 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-09-11T17:19:25.560Z,1599844765.560 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-09-11T17:19:25.560Z,1599844765.560 [Default:A.Wait] Running Loop=1
2020-09-11T17:19:25.560Z,1599844765.560 [Default:A.Wait](DEBUG): Initialize Wait Component.
2020-09-11T17:19:26.104Z,1599844766.104 [AMEcho](INFO): Powering down
2020-09-11T17:19:27.139Z,1599844767.139 [AMEcho](INFO): Powering up
2020-09-11T17:19:29.970Z,1599844769.970 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:19:37.788Z,1599844777.788 [DataOverHttps](INFO): Sending 407 bytes from file Logs/20061002T194754/Express0001.lzma
2020-09-11T17:19:38.789Z,1599844778.789 [DataOverHttps](INFO): Moved sent file to Logs/20061002T194754/Express0001.lzma.bak
2020-09-11T17:19:38.789Z,1599844778.789 [DataOverHttps](INFO): SBD MOMSN=12648162
2020-09-11T17:19:38.878Z,1599844778.878 [Default:A.Wait](INFO): Done Waiting.
2020-09-11T17:19:38.878Z,1599844778.878 [Default:A.Wait] Stopped
2020-09-11T17:19:38.878Z,1599844778.878 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T17:19:39.271Z,1599844779.271 [Default:CheckIn] Running Loop=1
2020-09-11T17:19:39.271Z,1599844779.271 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T17:19:39.271Z,1599844779.271 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T17:19:39.701Z,1599844779.701 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-09-11T17:19:42.894Z,1599844782.894 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:19:55.848Z,1599844795.848 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:20:08.772Z,1599844808.772 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T17:20:56.192Z,1599844856.192 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T17:21:15.635Z,1599844875.635 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2020-09-11T17:21:15.635Z,1599844875.635 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2020-09-11T17:21:15.654Z,1599844875.654 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2020-09-11T17:21:16.048Z,1599844876.048 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2020-09-11T17:21:16.048Z,1599844876.048 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2020-09-11T17:21:39.830Z,1599844899.830 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172138.00,A,3648.16121,N,12147.29214,W,1.147,233.49,110920,,,A*74
2020-09-11T17:21:39.837Z,1599844899.837 [NAL9602](INFO): GPS fix at 20200911T172138: (36.802687, -121.788202)
2020-09-11T17:21:39.856Z,1599844899.856 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T17:21:39.856Z,1599844899.856 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T17:21:40.266Z,1599844900.266 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-09-11T17:21:49.627Z,1599844909.627 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20200911T171503/Courier0004.lzma
2020-09-11T17:21:50.629Z,1599844910.629 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0004.lzma.bak
2020-09-11T17:21:50.629Z,1599844910.629 [DataOverHttps](INFO): SBD MOMSN=12648171
2020-09-11T17:22:07.641Z,1599844927.641 [DataOverHttps](INFO): Sending 1295 bytes from file Logs/20200911T171503/Express0001.lzma
2020-09-11T17:22:08.641Z,1599844928.641 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0001.lzma.bak
2020-09-11T17:22:08.641Z,1599844928.641 [DataOverHttps](INFO): SBD MOMSN=12648174
2020-09-11T17:22:12.552Z,1599844932.552 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T17:22:24.735Z,1599844944.735 [DataOverHttps](INFO): Sending 314 bytes from file Logs/20200911T171503/Express0005.lzma
2020-09-11T17:22:25.737Z,1599844945.737 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0005.lzma.bak
2020-09-11T17:22:25.737Z,1599844945.737 [DataOverHttps](INFO): SBD MOMSN=12648206
2020-09-11T17:22:27.510Z,1599844947.510 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T17:22:27.510Z,1599844947.510 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T17:22:27.510Z,1599844947.510 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T17:22:54.805Z,1599844974.805 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2020-09-11T17:27:28.126Z,1599845248.126 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T17:27:28.126Z,1599845248.126 [Default:CheckIn:C.Wait] Stopped
2020-09-11T17:27:28.126Z,1599845248.126 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T17:27:28.126Z,1599845248.126 [Default:CheckIn:D] Running Loop=1
2020-09-11T17:27:28.536Z,1599845248.536 [Default:CheckIn:D] Stopped
2020-09-11T17:27:28.536Z,1599845248.536 [Default:CheckIn:E] Running Loop=1
2020-09-11T17:27:28.931Z,1599845248.931 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.049639 min 
2020-09-11T17:27:28.931Z,1599845248.931 [Default:CheckIn:E] Stopped
2020-09-11T17:27:28.931Z,1599845248.931 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T17:27:28.931Z,1599845248.931 [Default:CheckIn] Stopped
2020-09-11T17:27:28.932Z,1599845248.932 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T17:27:28.932Z,1599845248.932 [Default:CheckIn](INFO): Running loop #2
2020-09-11T17:27:28.932Z,1599845248.932 [Default:CheckIn] Running Loop=2
2020-09-11T17:27:28.932Z,1599845248.932 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T17:27:28.932Z,1599845248.932 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T17:27:30.939Z,1599845250.939 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172730.00,A,3648.16397,N,12147.28697,W,2.391,96.27,110920,,,A*44
2020-09-11T17:27:30.941Z,1599845250.941 [NAL9602](INFO): GPS fix at 20200911T172730: (36.802733, -121.788116)
2020-09-11T17:27:30.953Z,1599845250.953 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T17:27:30.953Z,1599845250.953 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T17:27:38.170Z,1599845258.170 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0007.lzma
2020-09-11T17:27:39.173Z,1599845259.173 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0007.lzma.bak
2020-09-11T17:27:39.173Z,1599845259.173 [DataOverHttps](INFO): SBD MOMSN=12648210
2020-09-11T17:27:55.115Z,1599845275.115 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20200911T171503/Express0008.lzma
2020-09-11T17:27:56.117Z,1599845276.117 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0008.lzma.bak
2020-09-11T17:27:56.117Z,1599845276.117 [DataOverHttps](INFO): SBD MOMSN=12648213
2020-09-11T17:27:58.830Z,1599845278.830 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T17:27:58.830Z,1599845278.830 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T17:27:58.830Z,1599845278.830 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T17:28:01.640Z,1599845281.640 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-09-11T17:28:01.715Z,1599845281.715 [NAL9602](FAULT): received: 
+CSQ:0

OK03, 2, 0, 0, 0

OK
2020-09-11T17:28:01.715Z,1599845281.715 [NAL9602] Data Fault, FailCount= 1
2020-09-11T17:28:01.715Z,1599845281.715 [NAL9602](ERROR): Data Fault
2020-09-11T17:28:01.748Z,1599845281.748 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T17:28:02.052Z,1599845282.052 [NAL9602](INFO): Powering down
2020-09-11T17:28:02.911Z,1599845282.911 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T17:28:02.911Z,1599845282.911 [NAL9602] No Fault, FailCount= 1
2020-09-11T17:28:32.348Z,1599845312.348 [NAL9602](INFO): Powering up NAL9602
2020-09-11T17:28:43.252Z,1599845323.252 [NAL9602](INFO): NAL9602 initialized
2020-09-11T17:29:14.364Z,1599845354.364 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T17:30:15.840Z,1599845415.840 [CBIT](INFO): Clearing failed state for component DropWeight
2020-09-11T17:30:15.840Z,1599845415.840 [DropWeight] No Fault, FailCount= 1
2020-09-11T17:32:59.430Z,1599845579.430 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T17:32:59.430Z,1599845579.430 [Default:CheckIn:C.Wait] Stopped
2020-09-11T17:32:59.430Z,1599845579.430 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T17:32:59.430Z,1599845579.430 [Default:CheckIn:D] Running Loop=1
2020-09-11T17:32:59.811Z,1599845579.811 [Default:CheckIn:D] Stopped
2020-09-11T17:32:59.811Z,1599845579.811 [Default:CheckIn:E] Running Loop=1
2020-09-11T17:33:00.227Z,1599845580.227 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.570877 min 
2020-09-11T17:33:00.227Z,1599845580.227 [Default:CheckIn:E] Stopped
2020-09-11T17:33:00.227Z,1599845580.227 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T17:33:00.227Z,1599845580.227 [Default:CheckIn] Stopped
2020-09-11T17:33:00.227Z,1599845580.227 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T17:33:00.227Z,1599845580.227 [Default:CheckIn](INFO): Running loop #3
2020-09-11T17:33:00.227Z,1599845580.227 [Default:CheckIn] Running Loop=3
2020-09-11T17:33:00.228Z,1599845580.228 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T17:33:00.228Z,1599845580.228 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T17:33:03.842Z,1599845583.842 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T17:33:40.632Z,1599845620.632 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2020-09-11T17:37:11.094Z,1599845831.094 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173709.00,A,3648.15561,N,12147.30703,W,1.011,81.46,110920,,,A*4F
2020-09-11T17:37:11.097Z,1599845831.097 [NAL9602](INFO): GPS fix at 20200911T173709: (36.802594, -121.788450)
2020-09-11T17:37:11.127Z,1599845831.127 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T17:37:11.127Z,1599845831.127 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T17:37:18.746Z,1599845838.746 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0010.lzma
2020-09-11T17:37:19.749Z,1599845839.749 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0010.lzma.bak
2020-09-11T17:37:19.749Z,1599845839.749 [DataOverHttps](INFO): SBD MOMSN=12648216
2020-09-11T17:37:35.635Z,1599845855.635 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20200911T171503/Express0011.lzma
2020-09-11T17:37:36.637Z,1599845856.637 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0011.lzma.bak
2020-09-11T17:37:36.637Z,1599845856.637 [DataOverHttps](INFO): SBD MOMSN=12648219
2020-09-11T17:37:38.167Z,1599845858.167 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T17:37:38.167Z,1599845858.167 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T17:37:38.168Z,1599845858.168 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T17:37:43.408Z,1599845863.408 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T17:42:38.746Z,1599846158.746 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T17:42:38.746Z,1599846158.746 [Default:CheckIn:C.Wait] Stopped
2020-09-11T17:42:38.746Z,1599846158.746 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T17:42:38.746Z,1599846158.746 [Default:CheckIn:D] Running Loop=1
2020-09-11T17:42:39.144Z,1599846159.144 [Default:CheckIn:D] Stopped
2020-09-11T17:42:39.144Z,1599846159.144 [Default:CheckIn:E] Running Loop=1
2020-09-11T17:42:39.550Z,1599846159.550 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.226428 min 
2020-09-11T17:42:39.550Z,1599846159.550 [Default:CheckIn:E] Stopped
2020-09-11T17:42:39.550Z,1599846159.550 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T17:42:39.550Z,1599846159.550 [Default:CheckIn] Stopped
2020-09-11T17:42:39.550Z,1599846159.550 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T17:42:39.551Z,1599846159.551 [Default:CheckIn](INFO): Running loop #4
2020-09-11T17:42:39.551Z,1599846159.551 [Default:CheckIn] Running Loop=4
2020-09-11T17:42:39.551Z,1599846159.551 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T17:42:39.551Z,1599846159.551 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T17:42:41.561Z,1599846161.561 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174240.00,A,3648.16879,N,12147.28480,W,0.194,130.53,110920,,,A*74
2020-09-11T17:42:41.563Z,1599846161.563 [NAL9602](INFO): GPS fix at 20200911T174240: (36.802813, -121.788080)
2020-09-11T17:42:41.585Z,1599846161.585 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T17:42:41.586Z,1599846161.586 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T17:42:49.539Z,1599846169.539 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20200911T171503/Courier0013.lzma
2020-09-11T17:42:50.541Z,1599846170.541 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0013.lzma.bak
2020-09-11T17:42:50.541Z,1599846170.541 [DataOverHttps](INFO): SBD MOMSN=12648224
2020-09-11T17:43:06.343Z,1599846186.343 [DataOverHttps](INFO): Sending 289 bytes from file Logs/20200911T171503/Express0014.lzma
2020-09-11T17:43:07.345Z,1599846187.345 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0014.lzma.bak
2020-09-11T17:43:07.345Z,1599846187.345 [DataOverHttps](INFO): SBD MOMSN=12648227
2020-09-11T17:43:09.080Z,1599846189.080 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T17:43:09.080Z,1599846189.080 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T17:43:09.080Z,1599846189.080 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T17:43:14.321Z,1599846194.321 [NAL9602](INFO): SBD MO Status=2, MOMSN=9603, MT Status=2, MTMSN=0
2020-09-11T17:43:14.322Z,1599846194.322 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T17:44:22.594Z,1599846262.594 [NAL9602](INFO): SBD MO Status=2, MOMSN=9603, MT Status=2, MTMSN=0
2020-09-11T17:44:22.594Z,1599846262.594 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T17:46:15.718Z,1599846375.718 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2020-09-11T17:46:15.734Z,1599846375.734 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2020-09-11T17:47:44.192Z,1599846464.192 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T17:48:09.654Z,1599846489.654 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T17:48:09.654Z,1599846489.654 [Default:CheckIn:C.Wait] Stopped
2020-09-11T17:48:09.654Z,1599846489.654 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T17:48:09.654Z,1599846489.654 [Default:CheckIn:D] Running Loop=1
2020-09-11T17:48:10.066Z,1599846490.066 [Default:CheckIn:D] Stopped
2020-09-11T17:48:10.066Z,1599846490.066 [Default:CheckIn:E] Running Loop=1
2020-09-11T17:48:10.462Z,1599846490.462 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.741801 min 
2020-09-11T17:48:10.462Z,1599846490.462 [Default:CheckIn:E] Stopped
2020-09-11T17:48:10.462Z,1599846490.462 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T17:48:10.462Z,1599846490.462 [Default:CheckIn] Stopped
2020-09-11T17:48:10.462Z,1599846490.462 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T17:48:10.463Z,1599846490.463 [Default:CheckIn](INFO): Running loop #5
2020-09-11T17:48:10.463Z,1599846490.463 [Default:CheckIn] Running Loop=5
2020-09-11T17:48:10.463Z,1599846490.463 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T17:48:10.463Z,1599846490.463 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T17:48:12.478Z,1599846492.478 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174811.00,A,3648.15889,N,12147.27982,W,1.808,149.28,110920,,,A*79
2020-09-11T17:48:12.480Z,1599846492.480 [NAL9602](INFO): GPS fix at 20200911T174811: (36.802648, -121.787997)
2020-09-11T17:48:12.490Z,1599846492.490 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T17:48:12.490Z,1599846492.490 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T17:48:20.123Z,1599846500.123 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20200911T171503/Courier0016.lzma
2020-09-11T17:48:21.125Z,1599846501.125 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0016.lzma.bak
2020-09-11T17:48:21.125Z,1599846501.125 [DataOverHttps](INFO): SBD MOMSN=12648230
2020-09-11T17:48:36.991Z,1599846516.991 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20200911T171503/Express0017.lzma
2020-09-11T17:48:38.323Z,1599846518.323 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0017.lzma.bak
2020-09-11T17:48:38.323Z,1599846518.323 [DataOverHttps](INFO): SBD MOMSN=12648233
2020-09-11T17:48:39.547Z,1599846519.547 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T17:48:39.547Z,1599846519.547 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T17:48:39.548Z,1599846519.548 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T17:48:44.389Z,1599846524.389 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T17:53:40.146Z,1599846820.146 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T17:53:40.146Z,1599846820.146 [Default:CheckIn:C.Wait] Stopped
2020-09-11T17:53:40.146Z,1599846820.146 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T17:53:40.146Z,1599846820.146 [Default:CheckIn:D] Running Loop=1
2020-09-11T17:53:40.551Z,1599846820.551 [Default:CheckIn:D] Stopped
2020-09-11T17:53:40.551Z,1599846820.551 [Default:CheckIn:E] Running Loop=1
2020-09-11T17:53:40.967Z,1599846820.967 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.249886 min 
2020-09-11T17:53:40.967Z,1599846820.967 [Default:CheckIn:E] Stopped
2020-09-11T17:53:40.967Z,1599846820.967 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T17:53:40.967Z,1599846820.967 [Default:CheckIn] Stopped
2020-09-11T17:53:40.967Z,1599846820.967 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T17:53:40.967Z,1599846820.967 [Default:CheckIn](INFO): Running loop #6
2020-09-11T17:53:40.968Z,1599846820.968 [Default:CheckIn] Running Loop=6
2020-09-11T17:53:40.968Z,1599846820.968 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T17:53:40.968Z,1599846820.968 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T17:53:42.966Z,1599846822.966 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175342.00,A,3648.16368,N,12147.28230,W,0.117,149.28,110920,,,A*79
2020-09-11T17:53:42.968Z,1599846822.968 [NAL9602](INFO): GPS fix at 20200911T175342: (36.802728, -121.788038)
2020-09-11T17:53:42.999Z,1599846822.999 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T17:53:42.999Z,1599846822.999 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T17:53:49.902Z,1599846829.902 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0019.lzma
2020-09-11T17:53:50.905Z,1599846830.905 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0019.lzma.bak
2020-09-11T17:53:50.905Z,1599846830.905 [DataOverHttps](INFO): SBD MOMSN=12648237
2020-09-11T17:54:06.795Z,1599846846.795 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20200911T171503/Express0020.lzma
2020-09-11T17:54:07.797Z,1599846847.797 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0020.lzma.bak
2020-09-11T17:54:07.797Z,1599846847.797 [DataOverHttps](INFO): SBD MOMSN=12648240
2020-09-11T17:54:09.654Z,1599846849.654 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T17:54:09.654Z,1599846849.654 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T17:54:09.654Z,1599846849.654 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T17:54:13.690Z,1599846853.690 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-09-11T17:54:13.763Z,1599846853.763 [NAL9602](FAULT): received: 
+CSQ:0

OK03, 2, 0, 0, 0

OK
2020-09-11T17:54:13.763Z,1599846853.763 [NAL9602] Data Fault, FailCount= 1
2020-09-11T17:54:13.763Z,1599846853.763 [NAL9602](ERROR): Data Fault
2020-09-11T17:54:13.783Z,1599846853.783 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T17:54:14.093Z,1599846854.093 [NAL9602](INFO): Powering down
2020-09-11T17:54:14.919Z,1599846854.919 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T17:54:14.919Z,1599846854.919 [NAL9602] No Fault, FailCount= 1
2020-09-11T17:54:44.389Z,1599846884.389 [NAL9602](INFO): Powering up NAL9602
2020-09-11T17:54:55.300Z,1599846895.300 [NAL9602](INFO): NAL9602 initialized
2020-09-11T17:55:26.404Z,1599846926.404 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T17:59:10.234Z,1599847150.234 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T17:59:10.234Z,1599847150.234 [Default:CheckIn:C.Wait] Stopped
2020-09-11T17:59:10.234Z,1599847150.234 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T17:59:10.234Z,1599847150.234 [Default:CheckIn:D] Running Loop=1
2020-09-11T17:59:10.638Z,1599847150.638 [Default:CheckIn:D] Stopped
2020-09-11T17:59:10.638Z,1599847150.638 [Default:CheckIn:E] Running Loop=1
2020-09-11T17:59:11.042Z,1599847151.042 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.751326 min 
2020-09-11T17:59:11.042Z,1599847151.042 [Default:CheckIn:E] Stopped
2020-09-11T17:59:11.042Z,1599847151.042 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T17:59:11.042Z,1599847151.042 [Default:CheckIn] Stopped
2020-09-11T17:59:11.042Z,1599847151.042 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T17:59:11.043Z,1599847151.043 [Default:CheckIn](INFO): Running loop #7
2020-09-11T17:59:11.043Z,1599847151.043 [Default:CheckIn] Running Loop=7
2020-09-11T17:59:11.043Z,1599847151.043 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T17:59:11.043Z,1599847151.043 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T17:59:15.066Z,1599847155.066 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T18:00:17.282Z,1599847217.282 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2020-09-11T18:00:17.282Z,1599847217.282 [DropWeight] Hardware Fault, FailCount= 1
2020-09-11T18:00:17.282Z,1599847217.282 [DropWeight](ERROR): Hardware Fault
2020-09-11T18:00:17.300Z,1599847217.300 [CBIT](INFO): Critical error at 20200911T180017
2020-09-11T18:00:17.302Z,1599847217.302 [CBIT](ERROR): Hardware Fault in component: DropWeight
2020-09-11T18:00:17.302Z,1599847217.302 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2020-09-11T18:00:17.722Z,1599847217.722 [CBIT](INFO): Critical error at 20200911T180017
2020-09-11T18:04:11.222Z,1599847451.222 [Default:CheckIn:Read_GPS](INFO): Timed out from 2020-09-11T17:59:11.0Z
2020-09-11T18:04:11.222Z,1599847451.222 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:04:11.222Z,1599847451.222 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:04:18.382Z,1599847458.382 [DataOverHttps](INFO): Sending 114 bytes from file Logs/20200911T171503/Courier0022.lzma
2020-09-11T18:04:19.385Z,1599847459.385 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0022.lzma.bak
2020-09-11T18:04:19.385Z,1599847459.385 [DataOverHttps](INFO): SBD MOMSN=12648243
2020-09-11T18:04:35.164Z,1599847475.164 [DataOverHttps](INFO): Sending 257 bytes from file Logs/20200911T171503/Express0023.lzma
2020-09-11T18:04:36.165Z,1599847476.165 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0023.lzma.bak
2020-09-11T18:04:36.165Z,1599847476.165 [DataOverHttps](INFO): SBD MOMSN=12648247
2020-09-11T18:04:37.874Z,1599847477.874 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:04:37.874Z,1599847477.874 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:04:37.874Z,1599847477.874 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:04:42.308Z,1599847482.308 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T18:09:38.458Z,1599847778.458 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:09:38.458Z,1599847778.458 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:09:38.458Z,1599847778.458 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:09:38.458Z,1599847778.458 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:09:38.858Z,1599847778.858 [Default:CheckIn:D] Stopped
2020-09-11T18:09:38.858Z,1599847778.858 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:09:39.262Z,1599847779.262 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.221663 min 
2020-09-11T18:09:39.262Z,1599847779.262 [Default:CheckIn:E] Stopped
2020-09-11T18:09:39.262Z,1599847779.262 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:09:39.263Z,1599847779.263 [Default:CheckIn] Stopped
2020-09-11T18:09:39.263Z,1599847779.263 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:09:39.263Z,1599847779.263 [Default:CheckIn](INFO): Running loop #8
2020-09-11T18:09:39.263Z,1599847779.263 [Default:CheckIn] Running Loop=8
2020-09-11T18:09:39.263Z,1599847779.263 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:09:39.263Z,1599847779.263 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:09:40.872Z,1599847780.872 [NAL9602](FAULT): GPS failed to acquire within timeout.
2020-09-11T18:09:40.872Z,1599847780.872 [NAL9602] Data Fault, FailCount= 1
2020-09-11T18:09:40.872Z,1599847780.872 [NAL9602](ERROR): Data Fault
2020-09-11T18:09:40.891Z,1599847780.891 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T18:09:41.272Z,1599847781.272 [NAL9602](INFO): Powering down
2020-09-11T18:09:42.114Z,1599847782.114 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T18:09:42.114Z,1599847782.114 [NAL9602] No Fault, FailCount= 1
2020-09-11T18:10:11.566Z,1599847811.566 [NAL9602](INFO): Powering up NAL9602
2020-09-11T18:10:22.474Z,1599847822.474 [NAL9602](INFO): NAL9602 initialized
2020-09-11T18:14:39.439Z,1599848079.439 [Default:CheckIn:Read_GPS](INFO): Timed out from 2020-09-11T18:09:39.3Z
2020-09-11T18:14:39.439Z,1599848079.439 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:14:39.439Z,1599848079.439 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:14:46.986Z,1599848086.986 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20200911T171503/Courier0025.lzma
2020-09-11T18:14:47.989Z,1599848087.989 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0025.lzma.bak
2020-09-11T18:14:47.989Z,1599848087.989 [DataOverHttps](INFO): SBD MOMSN=12648252
2020-09-11T18:15:04.895Z,1599848104.895 [DataOverHttps](INFO): Sending 171 bytes from file Logs/20200911T171503/Express0026.lzma
2020-09-11T18:15:05.897Z,1599848105.897 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0026.lzma.bak
2020-09-11T18:15:05.897Z,1599848105.897 [DataOverHttps](INFO): SBD MOMSN=12648254
2020-09-11T18:15:07.726Z,1599848107.726 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:15:07.726Z,1599848107.726 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:15:07.726Z,1599848107.726 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:15:17.421Z,1599848117.421 [CBIT](INFO): Clearing failed state for component DropWeight
2020-09-11T18:15:17.421Z,1599848117.421 [DropWeight] No Fault, FailCount= 1
2020-09-11T18:15:25.476Z,1599848125.476 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T18:15:56.184Z,1599848156.184 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T18:20:08.307Z,1599848408.307 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:20:08.307Z,1599848408.307 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:20:08.307Z,1599848408.307 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:20:08.307Z,1599848408.307 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:20:08.694Z,1599848408.694 [Default:CheckIn:D] Stopped
2020-09-11T18:20:08.694Z,1599848408.694 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:20:09.101Z,1599848409.101 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.718937 min 
2020-09-11T18:20:09.101Z,1599848409.101 [Default:CheckIn:E] Stopped
2020-09-11T18:20:09.102Z,1599848409.102 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:20:09.102Z,1599848409.102 [Default:CheckIn] Stopped
2020-09-11T18:20:09.102Z,1599848409.102 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:20:09.102Z,1599848409.102 [Default:CheckIn](INFO): Running loop #9
2020-09-11T18:20:09.102Z,1599848409.102 [Default:CheckIn] Running Loop=9
2020-09-11T18:20:09.102Z,1599848409.102 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:20:09.102Z,1599848409.102 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:20:11.114Z,1599848411.114 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182010.00,A,3648.16634,N,12147.28886,W,0.194,296.58,110920,,,A*73
2020-09-11T18:20:11.126Z,1599848411.126 [NAL9602](INFO): GPS fix at 20200911T182010: (36.802772, -121.788148)
2020-09-11T18:20:11.136Z,1599848411.136 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:20:11.136Z,1599848411.136 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:20:18.066Z,1599848418.066 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0028.lzma
2020-09-11T18:20:19.069Z,1599848419.069 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0028.lzma.bak
2020-09-11T18:20:19.069Z,1599848419.069 [DataOverHttps](INFO): SBD MOMSN=12648258
2020-09-11T18:20:38.867Z,1599848438.867 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20200911T171503/Express0029.lzma
2020-09-11T18:20:39.869Z,1599848439.869 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0029.lzma.bak
2020-09-11T18:20:39.869Z,1599848439.869 [DataOverHttps](INFO): SBD MOMSN=12648261
2020-09-11T18:20:41.422Z,1599848441.422 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:20:41.422Z,1599848441.422 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:20:41.422Z,1599848441.422 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:20:41.816Z,1599848441.816 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-09-11T18:20:41.895Z,1599848441.895 [NAL9602](FAULT): received: 
+CSQ:0

OK03, 2, 0, 0, 0

OK
2020-09-11T18:20:41.895Z,1599848441.895 [NAL9602] Data Fault, FailCount= 2
2020-09-11T18:20:41.895Z,1599848441.895 [NAL9602](ERROR): Data Fault
2020-09-11T18:20:41.944Z,1599848441.944 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T18:20:42.229Z,1599848442.229 [NAL9602](INFO): Powering down
2020-09-11T18:20:43.079Z,1599848443.079 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T18:20:43.079Z,1599848443.079 [NAL9602] No Fault, FailCount= 2
2020-09-11T18:21:12.516Z,1599848472.516 [NAL9602](INFO): Powering up NAL9602
2020-09-11T18:21:23.428Z,1599848483.428 [NAL9602](INFO): NAL9602 initialized
2020-09-11T18:21:54.532Z,1599848514.532 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T18:25:42.010Z,1599848742.010 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:25:42.011Z,1599848742.011 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:25:42.011Z,1599848742.011 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:25:42.027Z,1599848742.027 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:25:42.453Z,1599848742.453 [Default:CheckIn:D] Stopped
2020-09-11T18:25:42.453Z,1599848742.453 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.281580 min 
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn:E] Stopped
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn] Stopped
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn](INFO): Running loop #10
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn] Running Loop=10
2020-09-11T18:25:42.860Z,1599848742.860 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:25:42.861Z,1599848742.861 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:25:46.830Z,1599848746.830 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T18:27:01.985Z,1599848821.985 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182700.00,A,3648.16489,N,12147.28105,W,0.330,0.00,110920,,,A*7F
2020-09-11T18:27:01.987Z,1599848821.987 [NAL9602](INFO): GPS fix at 20200911T182700: (36.802748, -121.788017)
2020-09-11T18:27:01.999Z,1599848821.999 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:27:01.999Z,1599848821.999 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:27:09.819Z,1599848829.819 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200911T171503/Courier0031.lzma
2020-09-11T18:27:10.821Z,1599848830.821 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0031.lzma.bak
2020-09-11T18:27:10.821Z,1599848830.821 [DataOverHttps](INFO): SBD MOMSN=12648265
2020-09-11T18:27:26.583Z,1599848846.583 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20200911T171503/Express0032.lzma
2020-09-11T18:27:27.585Z,1599848847.585 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0032.lzma.bak
2020-09-11T18:27:27.585Z,1599848847.585 [DataOverHttps](INFO): SBD MOMSN=12648268
2020-09-11T18:27:29.462Z,1599848849.462 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:27:29.462Z,1599848849.462 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:27:29.462Z,1599848849.462 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:27:34.296Z,1599848854.296 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T18:32:30.058Z,1599849150.058 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:32:30.058Z,1599849150.058 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:32:30.058Z,1599849150.058 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:32:30.058Z,1599849150.058 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:32:30.464Z,1599849150.464 [Default:CheckIn:D] Stopped
2020-09-11T18:32:30.464Z,1599849150.464 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:32:30.879Z,1599849150.879 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 73.081763 min 
2020-09-11T18:32:30.879Z,1599849150.879 [Default:CheckIn:E] Stopped
2020-09-11T18:32:30.879Z,1599849150.879 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:32:30.880Z,1599849150.880 [Default:CheckIn] Stopped
2020-09-11T18:32:30.880Z,1599849150.880 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:32:30.880Z,1599849150.880 [Default:CheckIn](INFO): Running loop #11
2020-09-11T18:32:30.880Z,1599849150.880 [Default:CheckIn] Running Loop=11
2020-09-11T18:32:30.880Z,1599849150.880 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:32:30.880Z,1599849150.880 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:32:32.878Z,1599849152.878 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183232.00,A,3648.16587,N,12147.28761,W,0.097,0.00,110920,,,A*7F
2020-09-11T18:32:32.880Z,1599849152.880 [NAL9602](INFO): GPS fix at 20200911T183232: (36.802765, -121.788127)
2020-09-11T18:32:32.890Z,1599849152.890 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:32:32.890Z,1599849152.890 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:32:39.866Z,1599849159.866 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200911T171503/Courier0034.lzma
2020-09-11T18:32:40.869Z,1599849160.869 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0034.lzma.bak
2020-09-11T18:32:40.869Z,1599849160.869 [DataOverHttps](INFO): SBD MOMSN=12648273
2020-09-11T18:32:56.663Z,1599849176.663 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20200911T171503/Express0035.lzma
2020-09-11T18:32:57.665Z,1599849177.665 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0035.lzma.bak
2020-09-11T18:32:57.665Z,1599849177.665 [DataOverHttps](INFO): SBD MOMSN=12648276
2020-09-11T18:32:59.246Z,1599849179.246 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:32:59.246Z,1599849179.246 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:32:59.246Z,1599849179.246 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:37:35.144Z,1599849455.144 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T18:37:38.403Z,1599849458.403 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-09-11T18:37:40.412Z,1599849460.412 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.251404
2020-09-11T18:37:59.798Z,1599849479.798 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:37:59.798Z,1599849479.798 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:37:59.798Z,1599849479.798 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:37:59.798Z,1599849479.798 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:38:00.212Z,1599849480.212 [Default:CheckIn:D] Stopped
2020-09-11T18:38:00.212Z,1599849480.212 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:38:00.620Z,1599849480.620 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 78.577555 min 
2020-09-11T18:38:00.620Z,1599849480.620 [Default:CheckIn:E] Stopped
2020-09-11T18:38:00.620Z,1599849480.620 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:38:00.620Z,1599849480.620 [Default:CheckIn] Stopped
2020-09-11T18:38:00.621Z,1599849480.621 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:38:00.621Z,1599849480.621 [Default:CheckIn](INFO): Running loop #12
2020-09-11T18:38:00.621Z,1599849480.621 [Default:CheckIn] Running Loop=12
2020-09-11T18:38:00.621Z,1599849480.621 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:38:00.621Z,1599849480.621 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:38:02.617Z,1599849482.617 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183801.00,A,3648.16994,N,12147.27926,W,0.311,101.84,110920,,,A*78
2020-09-11T18:38:02.619Z,1599849482.619 [NAL9602](INFO): GPS fix at 20200911T183801: (36.802832, -121.787988)
2020-09-11T18:38:02.629Z,1599849482.629 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:38:02.629Z,1599849482.629 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:38:13.551Z,1599849493.551 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-09-11T18:38:33.326Z,1599849513.326 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. 
2020-09-11T18:38:33.400Z,1599849513.400 [NAL9602](ERROR): received: 
+CSQ:0

OK03, 2, 0, 0, 0

OK
2020-09-11T18:38:33.400Z,1599849513.400 [NAL9602] Data Fault, FailCount= 1
2020-09-11T18:38:33.400Z,1599849513.400 [NAL9602](ERROR): Data Fault
2020-09-11T18:38:33.458Z,1599849513.458 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T18:38:33.724Z,1599849513.724 [NAL9602](INFO): Powering down
2020-09-11T18:38:34.554Z,1599849514.554 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T18:38:34.554Z,1599849514.554 [NAL9602] No Fault, FailCount= 1
2020-09-11T18:38:48.703Z,1599849528.703 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-09-11T18:39:04.028Z,1599849544.028 [NAL9602](INFO): Powering up NAL9602
2020-09-11T18:39:14.936Z,1599849554.936 [NAL9602](INFO): NAL9602 initialized
2020-09-11T18:39:21.451Z,1599849561.451 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002972
2020-09-11T18:39:29.046Z,1599849569.046 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0037.lzma
2020-09-11T18:39:30.049Z,1599849570.049 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0037.lzma.bak
2020-09-11T18:39:30.049Z,1599849570.049 [DataOverHttps](INFO): SBD MOMSN=12648279
2020-09-11T18:39:45.767Z,1599849585.767 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20200911T171503/Express0038.lzma
2020-09-11T18:39:46.769Z,1599849586.769 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0038.lzma.bak
2020-09-11T18:39:46.769Z,1599849586.769 [DataOverHttps](INFO): SBD MOMSN=12648283
2020-09-11T18:39:48.603Z,1599849588.603 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:39:48.603Z,1599849588.603 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:39:48.603Z,1599849588.603 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:39:52.216Z,1599849592.216 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T18:44:49.204Z,1599849889.204 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:44:49.204Z,1599849889.204 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:44:49.204Z,1599849889.204 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:44:49.204Z,1599849889.204 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:44:49.619Z,1599849889.619 [Default:CheckIn:D] Stopped
2020-09-11T18:44:49.619Z,1599849889.619 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:44:50.020Z,1599849890.020 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 85.401009 min 
2020-09-11T18:44:50.020Z,1599849890.020 [Default:CheckIn:E] Stopped
2020-09-11T18:44:50.020Z,1599849890.020 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:44:50.020Z,1599849890.020 [Default:CheckIn] Stopped
2020-09-11T18:44:50.020Z,1599849890.020 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:44:50.020Z,1599849890.020 [Default:CheckIn](INFO): Running loop #13
2020-09-11T18:44:50.020Z,1599849890.020 [Default:CheckIn] Running Loop=13
2020-09-11T18:44:50.021Z,1599849890.021 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:44:50.021Z,1599849890.021 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:44:52.026Z,1599849892.026 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184451.00,A,3648.15958,N,12147.27779,W,0.894,0.00,110920,,,A*7B
2020-09-11T18:44:52.028Z,1599849892.028 [NAL9602](INFO): GPS fix at 20200911T184451: (36.802660, -121.787963)
2020-09-11T18:44:52.038Z,1599849892.038 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:44:52.038Z,1599849892.038 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:44:59.362Z,1599849899.362 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0040.lzma
2020-09-11T18:45:00.365Z,1599849900.365 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0040.lzma.bak
2020-09-11T18:45:00.365Z,1599849900.365 [DataOverHttps](INFO): SBD MOMSN=12648287
2020-09-11T18:45:16.227Z,1599849916.227 [DataOverHttps](INFO): Sending 144 bytes from file Logs/20200911T171503/Express0041.lzma
2020-09-11T18:45:17.229Z,1599849917.229 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0041.lzma.bak
2020-09-11T18:45:17.229Z,1599849917.229 [DataOverHttps](INFO): SBD MOMSN=12648290
2020-09-11T18:45:18.688Z,1599849918.688 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2020-09-11T18:45:18.688Z,1599849918.688 [DropWeight] Hardware Fault, FailCount= 1
2020-09-11T18:45:18.688Z,1599849918.688 [DropWeight](ERROR): Hardware Fault
2020-09-11T18:45:18.717Z,1599849918.717 [CBIT](INFO): Critical error at 20200911T184518
2020-09-11T18:45:18.767Z,1599849918.767 [CBIT](ERROR): Hardware Fault in component: DropWeight
2020-09-11T18:45:18.769Z,1599849918.769 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2020-09-11T18:45:19.126Z,1599849919.126 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:45:19.126Z,1599849919.126 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:45:19.126Z,1599849919.126 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:45:19.133Z,1599849919.133 [CBIT](INFO): Critical error at 20200911T184518
2020-09-11T18:49:54.229Z,1599850194.229 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T18:50:19.703Z,1599850219.703 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:50:19.703Z,1599850219.703 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:50:19.703Z,1599850219.703 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:50:19.703Z,1599850219.703 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:50:20.097Z,1599850220.097 [Default:CheckIn:D] Stopped
2020-09-11T18:50:20.097Z,1599850220.097 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 90.908984 min 
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn:E] Stopped
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn] Stopped
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn](INFO): Running loop #14
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn] Running Loop=14
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:50:20.510Z,1599850220.510 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:50:22.509Z,1599850222.509 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185021.00,A,3648.15485,N,12147.22826,W,0.253,0.00,110920,,,A*75
2020-09-11T18:50:22.511Z,1599850222.511 [NAL9602](INFO): GPS fix at 20200911T185021: (36.802581, -121.787138)
2020-09-11T18:50:22.522Z,1599850222.522 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:50:22.522Z,1599850222.522 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:50:30.503Z,1599850230.503 [DataOverHttps](INFO): Sending 147 bytes from file Logs/20200911T171503/Courier0043.lzma
2020-09-11T18:50:31.505Z,1599850231.505 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0043.lzma.bak
2020-09-11T18:50:31.505Z,1599850231.505 [DataOverHttps](INFO): SBD MOMSN=12648293
2020-09-11T18:50:52.419Z,1599850252.419 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20200911T171503/Express0044.lzma
2020-09-11T18:50:53.421Z,1599850253.421 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0044.lzma.bak
2020-09-11T18:50:53.421Z,1599850253.421 [DataOverHttps](INFO): SBD MOMSN=12648298
2020-09-11T18:50:54.442Z,1599850254.442 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T18:50:55.242Z,1599850255.242 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:50:55.242Z,1599850255.242 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:50:55.242Z,1599850255.242 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T18:55:56.021Z,1599850556.021 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T18:55:56.022Z,1599850556.022 [Default:CheckIn:C.Wait] Stopped
2020-09-11T18:55:56.022Z,1599850556.022 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T18:55:56.022Z,1599850556.022 [Default:CheckIn:D] Running Loop=1
2020-09-11T18:55:56.440Z,1599850556.440 [Default:CheckIn:D] Stopped
2020-09-11T18:55:56.440Z,1599850556.440 [Default:CheckIn:E] Running Loop=1
2020-09-11T18:55:56.824Z,1599850556.824 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 96.514697 min 
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn:E] Stopped
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn] Stopped
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn](INFO): Running loop #15
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn] Running Loop=15
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T18:55:56.825Z,1599850556.825 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T18:55:58.842Z,1599850558.842 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185558.00,A,3648.16493,N,12147.28059,W,0.564,134.01,110920,,,A*74
2020-09-11T18:55:58.844Z,1599850558.844 [NAL9602](INFO): GPS fix at 20200911T185558: (36.802749, -121.788010)
2020-09-11T18:55:58.980Z,1599850558.980 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T18:55:58.980Z,1599850558.980 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T18:56:06.430Z,1599850566.430 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200911T171503/Courier0046.lzma
2020-09-11T18:56:07.433Z,1599850567.433 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0046.lzma.bak
2020-09-11T18:56:07.433Z,1599850567.433 [DataOverHttps](INFO): SBD MOMSN=12648302
2020-09-11T18:56:24.427Z,1599850584.427 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20200911T171503/Express0047.lzma
2020-09-11T18:56:25.429Z,1599850585.429 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0047.lzma.bak
2020-09-11T18:56:25.429Z,1599850585.429 [DataOverHttps](INFO): SBD MOMSN=12648305
2020-09-11T18:56:27.137Z,1599850587.137 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T18:56:27.137Z,1599850587.137 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T18:56:27.137Z,1599850587.137 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:00:19.075Z,1599850819.075 [CBIT](INFO): Clearing failed state for component DropWeight
2020-09-11T19:00:19.075Z,1599850819.075 [DropWeight] No Fault, FailCount= 1
2020-09-11T19:00:42.869Z,1599850842.869 [NAL9602](INFO): SBD MO Status=2, MOMSN=9603, MT Status=2, MTMSN=0
2020-09-11T19:00:42.870Z,1599850842.870 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:01:09.537Z,1599850869.537 [NAL9602](INFO): SBD MO Status=2, MOMSN=9603, MT Status=2, MTMSN=0
2020-09-11T19:01:09.537Z,1599850869.537 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:01:09.940Z,1599850869.940 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T19:01:27.727Z,1599850887.727 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:01:27.727Z,1599850887.727 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:01:27.727Z,1599850887.727 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:01:27.727Z,1599850887.727 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:01:28.131Z,1599850888.131 [Default:CheckIn:D] Stopped
2020-09-11T19:01:28.131Z,1599850888.131 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:01:28.533Z,1599850888.533 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 102.042879 min 
2020-09-11T19:01:28.533Z,1599850888.533 [Default:CheckIn:E] Stopped
2020-09-11T19:01:28.533Z,1599850888.533 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:01:28.534Z,1599850888.534 [Default:CheckIn] Stopped
2020-09-11T19:01:28.534Z,1599850888.534 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:01:28.534Z,1599850888.534 [Default:CheckIn](INFO): Running loop #16
2020-09-11T19:01:28.534Z,1599850888.534 [Default:CheckIn] Running Loop=16
2020-09-11T19:01:28.534Z,1599850888.534 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:01:28.534Z,1599850888.534 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:01:30.546Z,1599850890.546 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190129.00,A,3648.16595,N,12147.28617,W,0.233,134.01,110920,,,A*7C
2020-09-11T19:01:30.548Z,1599850890.548 [NAL9602](INFO): GPS fix at 20200911T190129: (36.802766, -121.788103)
2020-09-11T19:01:30.576Z,1599850890.576 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:01:30.577Z,1599850890.577 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:01:38.150Z,1599850898.150 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0049.lzma
2020-09-11T19:01:39.153Z,1599850899.153 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0049.lzma.bak
2020-09-11T19:01:39.153Z,1599850899.153 [DataOverHttps](INFO): SBD MOMSN=12648308
2020-09-11T19:01:55.007Z,1599850915.007 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20200911T171503/Express0050.lzma
2020-09-11T19:01:56.009Z,1599850916.009 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0050.lzma.bak
2020-09-11T19:01:56.009Z,1599850916.009 [DataOverHttps](INFO): SBD MOMSN=12648311
2020-09-11T19:01:58.043Z,1599850918.043 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:01:58.047Z,1599850918.047 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:01:58.047Z,1599850918.047 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:02:02.456Z,1599850922.456 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:06:58.630Z,1599851218.630 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:06:58.630Z,1599851218.630 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:06:58.630Z,1599851218.630 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:06:58.630Z,1599851218.630 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:06:59.025Z,1599851219.025 [Default:CheckIn:D] Stopped
2020-09-11T19:06:59.025Z,1599851219.025 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:06:59.418Z,1599851219.418 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 107.557772 min 
2020-09-11T19:06:59.418Z,1599851219.418 [Default:CheckIn:E] Stopped
2020-09-11T19:06:59.419Z,1599851219.419 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:06:59.419Z,1599851219.419 [Default:CheckIn] Stopped
2020-09-11T19:06:59.419Z,1599851219.419 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:06:59.419Z,1599851219.419 [Default:CheckIn](INFO): Running loop #17
2020-09-11T19:06:59.419Z,1599851219.419 [Default:CheckIn] Running Loop=17
2020-09-11T19:06:59.419Z,1599851219.419 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:06:59.419Z,1599851219.419 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:07:01.430Z,1599851221.430 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190700.00,A,3648.16365,N,12147.28301,W,0.525,134.01,110920,,,A*7A
2020-09-11T19:07:01.432Z,1599851221.432 [NAL9602](INFO): GPS fix at 20200911T190700: (36.802728, -121.788050)
2020-09-11T19:07:01.450Z,1599851221.450 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:07:01.450Z,1599851221.450 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:07:08.395Z,1599851228.395 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200911T171503/Courier0052.lzma
2020-09-11T19:07:09.393Z,1599851229.393 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0052.lzma.bak
2020-09-11T19:07:09.393Z,1599851229.393 [DataOverHttps](INFO): SBD MOMSN=12648315
2020-09-11T19:07:26.370Z,1599851246.370 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20200911T171503/Express0053.lzma
2020-09-11T19:07:27.373Z,1599851247.373 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0053.lzma.bak
2020-09-11T19:07:27.373Z,1599851247.373 [DataOverHttps](INFO): SBD MOMSN=12648318
2020-09-11T19:07:29.326Z,1599851249.326 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:07:29.326Z,1599851249.326 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:07:29.326Z,1599851249.326 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:07:29.705Z,1599851249.705 [NAL9602](INFO): SBD MO Status=2, MOMSN=9603, MT Status=2, MTMSN=0
2020-09-11T19:07:29.706Z,1599851249.706 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:08:11.063Z,1599851291.063 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:08:14.233Z,1599851294.233 [NAL9602](INFO): SBD MO Status=0, MOMSN=9603, MT Status=0, MTMSN=0
2020-09-11T19:08:14.234Z,1599851294.234 [NAL9602](INFO): No messages in MT queue
2020-09-11T19:08:23.924Z,1599851303.924 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:08:36.050Z,1599851316.050 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:08:44.991Z,1599851324.991 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:08:49.423Z,1599851329.423 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:09:01.934Z,1599851341.934 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:09:14.865Z,1599851354.865 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:09:27.388Z,1599851367.388 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:09:40.317Z,1599851380.317 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:09:52.437Z,1599851392.437 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:10:04.961Z,1599851404.961 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:10:17.480Z,1599851417.480 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:10:30.409Z,1599851430.409 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2020-09-11T19:12:30.014Z,1599851550.014 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:12:30.014Z,1599851550.014 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:12:30.014Z,1599851550.014 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:12:30.014Z,1599851550.014 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:12:30.406Z,1599851550.406 [Default:CheckIn:D] Stopped
2020-09-11T19:12:30.406Z,1599851550.406 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:12:30.814Z,1599851550.814 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 113.080794 min 
2020-09-11T19:12:30.814Z,1599851550.814 [Default:CheckIn:E] Stopped
2020-09-11T19:12:30.814Z,1599851550.814 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:12:30.814Z,1599851550.814 [Default:CheckIn] Stopped
2020-09-11T19:12:30.814Z,1599851550.814 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:12:30.814Z,1599851550.814 [Default:CheckIn](INFO): Running loop #18
2020-09-11T19:12:30.815Z,1599851550.815 [Default:CheckIn] Running Loop=18
2020-09-11T19:12:30.815Z,1599851550.815 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:12:30.815Z,1599851550.815 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:12:32.830Z,1599851552.830 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191232.00,A,3648.16831,N,12147.28911,W,0.117,266.09,110920,,,A*77
2020-09-11T19:12:32.832Z,1599851552.832 [NAL9602](INFO): GPS fix at 20200911T191232: (36.802805, -121.788152)
2020-09-11T19:12:32.843Z,1599851552.843 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:12:32.843Z,1599851552.843 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:12:40.122Z,1599851560.122 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200911T171503/Courier0055.lzma
2020-09-11T19:12:41.125Z,1599851561.125 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0055.lzma.bak
2020-09-11T19:12:41.125Z,1599851561.125 [DataOverHttps](INFO): SBD MOMSN=12648322
2020-09-11T19:12:59.427Z,1599851579.427 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20200911T171503/Express0056.lzma
2020-09-11T19:13:00.429Z,1599851580.429 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0056.lzma.bak
2020-09-11T19:13:00.429Z,1599851580.429 [DataOverHttps](INFO): SBD MOMSN=12648325
2020-09-11T19:13:02.362Z,1599851582.362 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:13:02.362Z,1599851582.362 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:13:02.362Z,1599851582.362 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:15:15.754Z,1599851715.754 [NAL9602](INFO): SBD MO Status=2, MOMSN=9604, MT Status=2, MTMSN=0
2020-09-11T19:15:15.754Z,1599851715.754 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:16:00.604Z,1599851760.604 [NAL9602](INFO): SBD MO Status=2, MOMSN=9604, MT Status=2, MTMSN=0
2020-09-11T19:16:00.604Z,1599851760.604 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:16:22.821Z,1599851782.821 [NAL9602](INFO): SBD MO Status=2, MOMSN=9604, MT Status=2, MTMSN=0
2020-09-11T19:16:22.822Z,1599851782.822 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:16:37.361Z,1599851797.361 [NAL9602](INFO): SBD MO Status=2, MOMSN=9604, MT Status=2, MTMSN=0
2020-09-11T19:16:37.362Z,1599851797.362 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:16:49.078Z,1599851809.078 [NAL9602](INFO): SBD MO Status=0, MOMSN=9604, MT Status=0, MTMSN=0
2020-09-11T19:16:49.078Z,1599851809.078 [NAL9602](INFO): No messages in MT queue
2020-09-11T19:17:16.952Z,1599851836.952 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 5.
2020-09-11T19:17:16.954Z,1599851836.954 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2020-09-11T19:17:19.784Z,1599851839.784 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:18:03.018Z,1599851883.018 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:18:03.018Z,1599851883.018 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:18:03.018Z,1599851883.018 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:18:03.018Z,1599851883.018 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:18:03.425Z,1599851883.425 [Default:CheckIn:D] Stopped
2020-09-11T19:18:03.426Z,1599851883.426 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:18:03.833Z,1599851883.833 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 118.631120 min 
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn:E] Stopped
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn] Stopped
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn](INFO): Running loop #19
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn] Running Loop=19
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:18:03.834Z,1599851883.834 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:18:05.838Z,1599851885.838 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191805.00,A,3648.16587,N,12147.28380,W,0.175,266.09,110920,,,A*7F
2020-09-11T19:18:05.840Z,1599851885.840 [NAL9602](INFO): GPS fix at 20200911T191805: (36.802765, -121.788063)
2020-09-11T19:18:05.850Z,1599851885.850 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:18:05.850Z,1599851885.850 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:18:13.298Z,1599851893.298 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20200911T171503/Courier0058.lzma
2020-09-11T19:18:14.121Z,1599851894.121 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0058.lzma.bak
2020-09-11T19:18:14.121Z,1599851894.121 [DataOverHttps](INFO): SBD MOMSN=12648328
2020-09-11T19:18:29.967Z,1599851909.967 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20200911T171503/Express0059.lzma
2020-09-11T19:18:30.969Z,1599851910.969 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0059.lzma.bak
2020-09-11T19:18:30.969Z,1599851910.969 [DataOverHttps](INFO): SBD MOMSN=12648331
2020-09-11T19:18:32.537Z,1599851912.537 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:18:32.537Z,1599851912.537 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:18:32.538Z,1599851912.538 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:20:25.237Z,1599852025.237 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:20:25.238Z,1599852025.238 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:20:57.192Z,1599852057.192 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:20:57.192Z,1599852057.192 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:23:08.476Z,1599852188.476 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T19:23:33.165Z,1599852213.165 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:23:33.165Z,1599852213.165 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:23:33.166Z,1599852213.166 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:23:33.166Z,1599852213.166 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:23:33.569Z,1599852213.569 [Default:CheckIn:D] Stopped
2020-09-11T19:23:33.569Z,1599852213.569 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:23:33.976Z,1599852213.976 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 124.133521 min 
2020-09-11T19:23:33.976Z,1599852213.976 [Default:CheckIn:E] Stopped
2020-09-11T19:23:33.976Z,1599852213.976 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:23:33.976Z,1599852213.976 [Default:CheckIn] Stopped
2020-09-11T19:23:33.977Z,1599852213.977 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:23:33.977Z,1599852213.977 [Default:CheckIn](INFO): Running loop #20
2020-09-11T19:23:33.977Z,1599852213.977 [Default:CheckIn] Running Loop=20
2020-09-11T19:23:33.977Z,1599852213.977 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:23:33.977Z,1599852213.977 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:23:35.986Z,1599852215.986 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192335.00,A,3648.16519,N,12147.28447,W,0.272,354.81,110920,,,A*7B
2020-09-11T19:23:35.988Z,1599852215.988 [NAL9602](INFO): GPS fix at 20200911T192335: (36.802753, -121.788074)
2020-09-11T19:23:36.017Z,1599852216.017 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:23:36.017Z,1599852216.017 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:23:43.987Z,1599852223.987 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0061.lzma
2020-09-11T19:23:44.989Z,1599852224.989 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0061.lzma.bak
2020-09-11T19:23:44.989Z,1599852224.989 [DataOverHttps](INFO): SBD MOMSN=12648335
2020-09-11T19:24:00.708Z,1599852240.708 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20200911T171503/Express0062.lzma
2020-09-11T19:24:01.709Z,1599852241.709 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0062.lzma.bak
2020-09-11T19:24:01.709Z,1599852241.709 [DataOverHttps](INFO): SBD MOMSN=12648339
2020-09-11T19:24:03.469Z,1599852243.469 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:24:03.469Z,1599852243.469 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:24:03.469Z,1599852243.469 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:24:08.300Z,1599852248.300 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:29:04.098Z,1599852544.098 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:29:04.098Z,1599852544.098 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:29:04.098Z,1599852544.098 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:29:04.098Z,1599852544.098 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:29:04.507Z,1599852544.507 [Default:CheckIn:D] Stopped
2020-09-11T19:29:04.507Z,1599852544.507 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:29:04.893Z,1599852544.893 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 129.649146 min 
2020-09-11T19:29:04.893Z,1599852544.893 [Default:CheckIn:E] Stopped
2020-09-11T19:29:04.893Z,1599852544.893 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:29:04.893Z,1599852544.893 [Default:CheckIn] Stopped
2020-09-11T19:29:04.893Z,1599852544.893 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:29:04.893Z,1599852544.893 [Default:CheckIn](INFO): Running loop #21
2020-09-11T19:29:04.893Z,1599852544.893 [Default:CheckIn] Running Loop=21
2020-09-11T19:29:04.894Z,1599852544.894 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:29:04.894Z,1599852544.894 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:29:06.910Z,1599852546.910 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192906.00,A,3648.16306,N,12147.28473,W,0.058,354.81,110920,,,A*74
2020-09-11T19:29:06.912Z,1599852546.912 [NAL9602](INFO): GPS fix at 20200911T192906: (36.802718, -121.788079)
2020-09-11T19:29:06.922Z,1599852546.922 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:29:06.922Z,1599852546.922 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:29:14.243Z,1599852554.243 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0064.lzma
2020-09-11T19:29:15.237Z,1599852555.237 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0064.lzma.bak
2020-09-11T19:29:15.237Z,1599852555.237 [DataOverHttps](INFO): SBD MOMSN=12648343
2020-09-11T19:29:31.113Z,1599852571.113 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20200911T171503/Express0065.lzma
2020-09-11T19:29:32.113Z,1599852572.113 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0065.lzma.bak
2020-09-11T19:29:32.113Z,1599852572.113 [DataOverHttps](INFO): SBD MOMSN=12648346
2020-09-11T19:29:33.986Z,1599852573.986 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:29:33.987Z,1599852573.987 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:29:33.987Z,1599852573.987 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:29:37.608Z,1599852577.608 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-09-11T19:29:37.687Z,1599852577.687 [NAL9602](FAULT): received: 
+CSQ:0

OK05, 2, 0, 0, 0

OK
2020-09-11T19:29:37.687Z,1599852577.687 [NAL9602] Data Fault, FailCount= 1
2020-09-11T19:29:37.687Z,1599852577.687 [NAL9602](ERROR): Data Fault
2020-09-11T19:29:37.758Z,1599852577.758 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T19:29:38.012Z,1599852578.012 [NAL9602](INFO): Powering down
2020-09-11T19:29:38.855Z,1599852578.855 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T19:29:38.855Z,1599852578.855 [NAL9602] No Fault, FailCount= 1
2020-09-11T19:30:08.316Z,1599852608.316 [NAL9602](INFO): Powering up NAL9602
2020-09-11T19:30:19.220Z,1599852619.220 [NAL9602](INFO): NAL9602 initialized
2020-09-11T19:30:20.436Z,1599852620.436 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2020-09-11T19:30:20.436Z,1599852620.436 [DropWeight] Hardware Fault, FailCount= 1
2020-09-11T19:30:20.436Z,1599852620.436 [DropWeight](ERROR): Hardware Fault
2020-09-11T19:30:20.453Z,1599852620.453 [CBIT](INFO): Critical error at 20200911T193020
2020-09-11T19:30:20.456Z,1599852620.456 [CBIT](ERROR): Hardware Fault in component: DropWeight
2020-09-11T19:30:20.456Z,1599852620.456 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2020-09-11T19:30:20.864Z,1599852620.864 [CBIT](INFO): Critical error at 20200911T193020
2020-09-11T19:30:50.328Z,1599852650.328 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:34:34.556Z,1599852874.556 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:34:34.556Z,1599852874.556 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:34:34.556Z,1599852874.556 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:34:34.556Z,1599852874.556 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:34:34.965Z,1599852874.965 [Default:CheckIn:D] Stopped
2020-09-11T19:34:34.966Z,1599852874.966 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:34:35.372Z,1599852875.372 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 135.156787 min 
2020-09-11T19:34:35.372Z,1599852875.372 [Default:CheckIn:E] Stopped
2020-09-11T19:34:35.372Z,1599852875.372 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:34:35.372Z,1599852875.372 [Default:CheckIn] Stopped
2020-09-11T19:34:35.372Z,1599852875.372 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:34:35.372Z,1599852875.372 [Default:CheckIn](INFO): Running loop #22
2020-09-11T19:34:35.372Z,1599852875.372 [Default:CheckIn] Running Loop=22
2020-09-11T19:34:35.373Z,1599852875.373 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:34:35.373Z,1599852875.373 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:34:38.996Z,1599852878.996 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T19:35:27.886Z,1599852927.886 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193526.00,A,3648.16352,N,12147.27929,W,0.583,0.00,110920,,,A*7F
2020-09-11T19:35:27.888Z,1599852927.888 [NAL9602](INFO): GPS fix at 20200911T193526: (36.802725, -121.787988)
2020-09-11T19:35:27.927Z,1599852927.927 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:35:27.927Z,1599852927.927 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:35:34.774Z,1599852934.774 [DataOverHttps](INFO): Sending 148 bytes from file Logs/20200911T171503/Courier0067.lzma
2020-09-11T19:35:35.777Z,1599852935.777 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0067.lzma.bak
2020-09-11T19:35:35.777Z,1599852935.777 [DataOverHttps](INFO): SBD MOMSN=12648349
2020-09-11T19:35:51.427Z,1599852951.427 [DataOverHttps](INFO): Sending 247 bytes from file Logs/20200911T171503/Express0068.lzma
2020-09-11T19:35:52.429Z,1599852952.429 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0068.lzma.bak
2020-09-11T19:35:52.429Z,1599852952.429 [DataOverHttps](INFO): SBD MOMSN=12648354
2020-09-11T19:35:54.215Z,1599852954.215 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:35:54.215Z,1599852954.215 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:35:54.215Z,1599852954.215 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:36:00.268Z,1599852960.268 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:40:54.802Z,1599853254.802 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:40:54.802Z,1599853254.802 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:40:54.802Z,1599853254.802 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:40:54.802Z,1599853254.802 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:40:55.188Z,1599853255.188 [Default:CheckIn:D] Stopped
2020-09-11T19:40:55.188Z,1599853255.188 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:40:55.598Z,1599853255.598 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 141.493831 min 
2020-09-11T19:40:55.598Z,1599853255.598 [Default:CheckIn:E] Stopped
2020-09-11T19:40:55.599Z,1599853255.599 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:40:55.599Z,1599853255.599 [Default:CheckIn] Stopped
2020-09-11T19:40:55.599Z,1599853255.599 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:40:55.599Z,1599853255.599 [Default:CheckIn](INFO): Running loop #23
2020-09-11T19:40:55.599Z,1599853255.599 [Default:CheckIn] Running Loop=23
2020-09-11T19:40:55.599Z,1599853255.599 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:40:55.599Z,1599853255.599 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:40:57.605Z,1599853257.605 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194055.00,A,3648.16546,N,12147.27174,W,0.292,0.00,110920,,,A*7D
2020-09-11T19:40:57.608Z,1599853257.608 [NAL9602](INFO): GPS fix at 20200911T194055: (36.802758, -121.787862)
2020-09-11T19:40:57.618Z,1599853257.618 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:40:57.618Z,1599853257.618 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:41:05.330Z,1599853265.330 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0070.lzma
2020-09-11T19:41:06.333Z,1599853266.333 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0070.lzma.bak
2020-09-11T19:41:06.333Z,1599853266.333 [DataOverHttps](INFO): SBD MOMSN=12648359
2020-09-11T19:41:22.179Z,1599853282.179 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20200911T171503/Express0071.lzma
2020-09-11T19:41:23.320Z,1599853283.320 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0071.lzma.bak
2020-09-11T19:41:23.321Z,1599853283.321 [DataOverHttps](INFO): SBD MOMSN=12648362
2020-09-11T19:41:25.091Z,1599853285.091 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:41:25.092Z,1599853285.092 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:41:25.092Z,1599853285.092 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:42:18.413Z,1599853338.413 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:42:18.413Z,1599853338.413 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:42:32.140Z,1599853352.140 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:42:32.140Z,1599853352.140 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:43:44.881Z,1599853424.881 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:43:44.882Z,1599853424.882 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:44:00.629Z,1599853440.629 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:44:00.630Z,1599853440.630 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:44:30.933Z,1599853470.933 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:44:30.934Z,1599853470.934 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:44:47.897Z,1599853487.897 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:44:47.897Z,1599853487.897 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:45:20.668Z,1599853520.668 [CBIT](INFO): Clearing failed state for component DropWeight
2020-09-11T19:45:20.668Z,1599853520.668 [DropWeight] No Fault, FailCount= 1
2020-09-11T19:45:33.954Z,1599853533.954 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:45:33.954Z,1599853533.954 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:45:57.791Z,1599853557.791 [NAL9602](INFO): SBD MO Status=2, MOMSN=9605, MT Status=2, MTMSN=0
2020-09-11T19:45:57.791Z,1599853557.791 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T19:46:00.217Z,1599853560.217 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T19:46:25.681Z,1599853585.681 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:46:25.681Z,1599853585.681 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:46:25.681Z,1599853585.681 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:46:25.682Z,1599853585.682 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:46:26.084Z,1599853586.084 [Default:CheckIn:D] Stopped
2020-09-11T19:46:26.084Z,1599853586.084 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:46:26.486Z,1599853586.486 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 147.008773 min 
2020-09-11T19:46:26.486Z,1599853586.486 [Default:CheckIn:E] Stopped
2020-09-11T19:46:26.486Z,1599853586.486 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:46:26.486Z,1599853586.486 [Default:CheckIn] Stopped
2020-09-11T19:46:26.486Z,1599853586.486 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:46:26.486Z,1599853586.486 [Default:CheckIn](INFO): Running loop #24
2020-09-11T19:46:26.486Z,1599853586.486 [Default:CheckIn] Running Loop=24
2020-09-11T19:46:26.487Z,1599853586.487 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:46:26.503Z,1599853586.503 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:46:30.922Z,1599853590.922 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194630.00,A,3648.16650,N,12147.27441,W,3.693,0.00,110920,,,A*79
2020-09-11T19:46:30.924Z,1599853590.924 [NAL9602](INFO): GPS fix at 20200911T194630: (36.802775, -121.787907)
2020-09-11T19:46:30.934Z,1599853590.934 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:46:30.934Z,1599853590.934 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:46:38.646Z,1599853598.646 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0073.lzma
2020-09-11T19:46:39.649Z,1599853599.649 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0073.lzma.bak
2020-09-11T19:46:39.649Z,1599853599.649 [DataOverHttps](INFO): SBD MOMSN=12648365
2020-09-11T19:46:59.011Z,1599853619.011 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20200911T171503/Express0074.lzma
2020-09-11T19:47:00.013Z,1599853620.013 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0074.lzma.bak
2020-09-11T19:47:00.013Z,1599853620.013 [DataOverHttps](INFO): SBD MOMSN=12648368
2020-09-11T19:47:01.658Z,1599853621.658 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:47:01.658Z,1599853621.658 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:47:01.658Z,1599853621.658 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:47:03.660Z,1599853623.660 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:52:02.239Z,1599853922.239 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:52:02.239Z,1599853922.239 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:52:02.239Z,1599853922.239 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:52:02.239Z,1599853922.239 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:52:02.655Z,1599853922.655 [Default:CheckIn:D] Stopped
2020-09-11T19:52:02.655Z,1599853922.655 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:52:03.040Z,1599853923.040 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 152.618278 min 
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn:E] Stopped
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn] Stopped
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn](INFO): Running loop #25
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn] Running Loop=25
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:52:03.041Z,1599853923.041 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:52:05.053Z,1599853925.053 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195204.00,A,3648.16312,N,12147.28300,W,0.311,201.78,110920,,,A*75
2020-09-11T19:52:05.055Z,1599853925.055 [NAL9602](INFO): GPS fix at 20200911T195204: (36.802719, -121.788050)
2020-09-11T19:52:05.066Z,1599853925.066 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:52:05.066Z,1599853925.066 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:52:12.762Z,1599853932.762 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200911T171503/Courier0076.lzma
2020-09-11T19:52:13.765Z,1599853933.765 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0076.lzma.bak
2020-09-11T19:52:13.765Z,1599853933.765 [DataOverHttps](INFO): SBD MOMSN=12648372
2020-09-11T19:52:30.615Z,1599853950.615 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20200911T171503/Express0077.lzma
2020-09-11T19:52:31.617Z,1599853951.617 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0077.lzma.bak
2020-09-11T19:52:31.617Z,1599853951.617 [DataOverHttps](INFO): SBD MOMSN=12648375
2020-09-11T19:52:33.346Z,1599853953.346 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:52:33.346Z,1599853953.346 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:52:33.346Z,1599853953.346 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:52:35.756Z,1599853955.756 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-09-11T19:52:35.831Z,1599853955.831 [NAL9602](FAULT): received: 
+SBDI: 2, 9605, 2, 0, 0, 0

OK
2020-09-11T19:52:35.831Z,1599853955.831 [NAL9602] Data Fault, FailCount= 1
2020-09-11T19:52:35.831Z,1599853955.831 [NAL9602](ERROR): Data Fault
2020-09-11T19:52:35.877Z,1599853955.877 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T19:52:36.160Z,1599853956.160 [NAL9602](INFO): Powering down
2020-09-11T19:52:37.027Z,1599853957.027 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T19:52:37.027Z,1599853957.027 [NAL9602] No Fault, FailCount= 1
2020-09-11T19:53:06.465Z,1599853986.465 [NAL9602](INFO): Powering up NAL9602
2020-09-11T19:53:17.368Z,1599853997.368 [NAL9602](INFO): NAL9602 initialized
2020-09-11T19:53:48.476Z,1599854028.476 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T19:57:33.936Z,1599854253.936 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T19:57:33.936Z,1599854253.936 [Default:CheckIn:C.Wait] Stopped
2020-09-11T19:57:33.936Z,1599854253.936 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T19:57:33.936Z,1599854253.936 [Default:CheckIn:D] Running Loop=1
2020-09-11T19:57:34.330Z,1599854254.330 [Default:CheckIn:D] Stopped
2020-09-11T19:57:34.330Z,1599854254.330 [Default:CheckIn:E] Running Loop=1
2020-09-11T19:57:34.734Z,1599854254.734 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 158.146191 min 
2020-09-11T19:57:34.734Z,1599854254.734 [Default:CheckIn:E] Stopped
2020-09-11T19:57:34.735Z,1599854254.735 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T19:57:34.735Z,1599854254.735 [Default:CheckIn] Stopped
2020-09-11T19:57:34.735Z,1599854254.735 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T19:57:34.735Z,1599854254.735 [Default:CheckIn](INFO): Running loop #26
2020-09-11T19:57:34.735Z,1599854254.735 [Default:CheckIn] Running Loop=26
2020-09-11T19:57:34.735Z,1599854254.735 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T19:57:34.735Z,1599854254.735 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T19:57:36.746Z,1599854256.746 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195736.00,A,3648.16157,N,12147.28626,W,0.272,0.00,110920,,,A*7B
2020-09-11T19:57:36.758Z,1599854256.758 [NAL9602](INFO): GPS fix at 20200911T195736: (36.802693, -121.788104)
2020-09-11T19:57:36.769Z,1599854256.769 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T19:57:36.769Z,1599854256.769 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T19:57:39.202Z,1599854259.202 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T19:57:43.678Z,1599854263.678 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20200911T171503/Courier0079.lzma
2020-09-11T19:57:44.681Z,1599854264.681 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0079.lzma.bak
2020-09-11T19:57:44.681Z,1599854264.681 [DataOverHttps](INFO): SBD MOMSN=12648378
2020-09-11T19:58:00.470Z,1599854280.470 [DataOverHttps](INFO): Sending 175 bytes from file Logs/20200911T171503/Express0080.lzma
2020-09-11T19:58:01.473Z,1599854281.473 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0080.lzma.bak
2020-09-11T19:58:01.473Z,1599854281.473 [DataOverHttps](INFO): SBD MOMSN=12648381
2020-09-11T19:58:03.042Z,1599854283.042 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T19:58:03.042Z,1599854283.042 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T19:58:03.042Z,1599854283.042 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T19:58:09.900Z,1599854289.900 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T20:03:03.622Z,1599854583.622 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T20:03:03.622Z,1599854583.622 [Default:CheckIn:C.Wait] Stopped
2020-09-11T20:03:03.622Z,1599854583.622 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T20:03:03.622Z,1599854583.622 [Default:CheckIn:D] Running Loop=1
2020-09-11T20:03:04.031Z,1599854584.031 [Default:CheckIn:D] Stopped
2020-09-11T20:03:04.031Z,1599854584.031 [Default:CheckIn:E] Running Loop=1
2020-09-11T20:03:04.426Z,1599854584.426 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 163.641211 min 
2020-09-11T20:03:04.426Z,1599854584.426 [Default:CheckIn:E] Stopped
2020-09-11T20:03:04.426Z,1599854584.426 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T20:03:04.427Z,1599854584.427 [Default:CheckIn] Stopped
2020-09-11T20:03:04.427Z,1599854584.427 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T20:03:04.427Z,1599854584.427 [Default:CheckIn](INFO): Running loop #27
2020-09-11T20:03:04.427Z,1599854584.427 [Default:CheckIn] Running Loop=27
2020-09-11T20:03:04.427Z,1599854584.427 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T20:03:04.427Z,1599854584.427 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T20:03:06.442Z,1599854586.442 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200305.00,A,3648.16821,N,12147.28415,W,0.428,0.00,110920,,,A*73
2020-09-11T20:03:06.444Z,1599854586.444 [NAL9602](INFO): GPS fix at 20200911T200305: (36.802804, -121.788069)
2020-09-11T20:03:06.454Z,1599854586.454 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T20:03:06.454Z,1599854586.454 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T20:03:13.571Z,1599854593.571 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0082.lzma
2020-09-11T20:03:14.573Z,1599854594.573 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0082.lzma.bak
2020-09-11T20:03:14.573Z,1599854594.573 [DataOverHttps](INFO): SBD MOMSN=12648385
2020-09-11T20:03:27.041Z,1599854607.041 [NAL9602](INFO): SBD MO Status=0, MOMSN=9605, MT Status=0, MTMSN=0
2020-09-11T20:03:27.042Z,1599854607.042 [NAL9602](INFO): No messages in MT queue
2020-09-11T20:03:30.371Z,1599854610.371 [DataOverHttps](INFO): Sending 209 bytes from file Logs/20200911T171503/Express0083.lzma
2020-09-11T20:03:31.373Z,1599854611.373 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0083.lzma.bak
2020-09-11T20:03:31.373Z,1599854611.373 [DataOverHttps](INFO): SBD MOMSN=12648388
2020-09-11T20:03:33.126Z,1599854613.126 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T20:03:33.126Z,1599854613.126 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T20:03:33.126Z,1599854613.126 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T20:03:57.744Z,1599854637.744 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T20:08:33.694Z,1599854913.694 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T20:08:33.694Z,1599854913.694 [Default:CheckIn:C.Wait] Stopped
2020-09-11T20:08:33.694Z,1599854913.694 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T20:08:33.694Z,1599854913.694 [Default:CheckIn:D] Running Loop=1
2020-09-11T20:08:34.098Z,1599854914.098 [Default:CheckIn:D] Stopped
2020-09-11T20:08:34.098Z,1599854914.098 [Default:CheckIn:E] Running Loop=1
2020-09-11T20:08:34.498Z,1599854914.498 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 169.142318 min 
2020-09-11T20:08:34.498Z,1599854914.498 [Default:CheckIn:E] Stopped
2020-09-11T20:08:34.499Z,1599854914.499 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T20:08:34.499Z,1599854914.499 [Default:CheckIn] Stopped
2020-09-11T20:08:34.499Z,1599854914.499 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T20:08:34.499Z,1599854914.499 [Default:CheckIn](INFO): Running loop #28
2020-09-11T20:08:34.499Z,1599854914.499 [Default:CheckIn] Running Loop=28
2020-09-11T20:08:34.499Z,1599854914.499 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T20:08:34.499Z,1599854914.499 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T20:08:36.514Z,1599854916.514 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200835.00,A,3648.16447,N,12147.28539,W,0.019,70.15,110920,,,A*4D
2020-09-11T20:08:36.525Z,1599854916.525 [NAL9602](INFO): GPS fix at 20200911T200835: (36.802741, -121.788090)
2020-09-11T20:08:36.536Z,1599854916.536 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T20:08:36.536Z,1599854916.536 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T20:08:44.186Z,1599854924.186 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0085.lzma
2020-09-11T20:08:45.189Z,1599854925.189 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0085.lzma.bak
2020-09-11T20:08:45.189Z,1599854925.189 [DataOverHttps](INFO): SBD MOMSN=12648393
2020-09-11T20:09:01.086Z,1599854941.086 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20200911T171503/Express0086.lzma
2020-09-11T20:09:02.089Z,1599854942.089 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0086.lzma.bak
2020-09-11T20:09:02.090Z,1599854942.090 [DataOverHttps](INFO): SBD MOMSN=12648396
2020-09-11T20:09:03.999Z,1599854943.999 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T20:09:03.999Z,1599854943.999 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T20:09:03.999Z,1599854943.999 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T20:12:42.553Z,1599855162.553 [NAL9602](INFO): SBD MO Status=2, MOMSN=9606, MT Status=2, MTMSN=0
2020-09-11T20:12:42.554Z,1599855162.554 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T20:12:55.486Z,1599855175.486 [NAL9602](INFO): SBD MO Status=2, MOMSN=9606, MT Status=2, MTMSN=0
2020-09-11T20:12:55.486Z,1599855175.486 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-09-11T20:13:38.304Z,1599855218.304 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T20:14:04.577Z,1599855244.577 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T20:14:04.578Z,1599855244.578 [Default:CheckIn:C.Wait] Stopped
2020-09-11T20:14:04.578Z,1599855244.578 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T20:14:04.578Z,1599855244.578 [Default:CheckIn:D] Running Loop=1
2020-09-11T20:14:04.985Z,1599855244.985 [Default:CheckIn:D] Stopped
2020-09-11T20:14:04.985Z,1599855244.985 [Default:CheckIn:E] Running Loop=1
2020-09-11T20:14:05.381Z,1599855245.381 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 174.657113 min 
2020-09-11T20:14:05.381Z,1599855245.381 [Default:CheckIn:E] Stopped
2020-09-11T20:14:05.381Z,1599855245.381 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T20:14:05.381Z,1599855245.381 [Default:CheckIn] Stopped
2020-09-11T20:14:05.381Z,1599855245.381 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T20:14:05.382Z,1599855245.382 [Default:CheckIn](INFO): Running loop #29
2020-09-11T20:14:05.382Z,1599855245.382 [Default:CheckIn] Running Loop=29
2020-09-11T20:14:05.382Z,1599855245.382 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T20:14:05.382Z,1599855245.382 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T20:14:07.398Z,1599855247.398 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201406.00,A,3648.16388,N,12147.27813,W,0.117,70.15,110920,,,A*41
2020-09-11T20:14:07.400Z,1599855247.400 [NAL9602](INFO): GPS fix at 20200911T201406: (36.802731, -121.787969)
2020-09-11T20:14:07.411Z,1599855247.411 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T20:14:07.411Z,1599855247.411 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T20:14:14.442Z,1599855254.442 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0088.lzma
2020-09-11T20:14:15.445Z,1599855255.445 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0088.lzma.bak
2020-09-11T20:14:15.445Z,1599855255.445 [DataOverHttps](INFO): SBD MOMSN=12648399
2020-09-11T20:14:32.163Z,1599855272.163 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20200911T171503/Express0089.lzma
2020-09-11T20:14:33.165Z,1599855273.165 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0089.lzma.bak
2020-09-11T20:14:33.165Z,1599855273.165 [DataOverHttps](INFO): SBD MOMSN=12648402
2020-09-11T20:14:34.901Z,1599855274.901 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T20:14:34.901Z,1599855274.901 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T20:14:34.901Z,1599855274.901 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T20:14:39.324Z,1599855279.324 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T20:15:22.152Z,1599855322.152 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2020-09-11T20:15:22.152Z,1599855322.152 [DropWeight] Hardware Fault, FailCount= 1
2020-09-11T20:15:22.152Z,1599855322.152 [DropWeight](ERROR): Hardware Fault
2020-09-11T20:15:22.169Z,1599855322.169 [CBIT](INFO): Critical error at 20200911T201522
2020-09-11T20:15:22.171Z,1599855322.171 [CBIT](ERROR): Hardware Fault in component: DropWeight
2020-09-11T20:15:22.172Z,1599855322.172 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2020-09-11T20:15:22.575Z,1599855322.575 [CBIT](INFO): Critical error at 20200911T201522
2020-09-11T20:19:35.477Z,1599855575.477 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T20:19:35.477Z,1599855575.477 [Default:CheckIn:C.Wait] Stopped
2020-09-11T20:19:35.477Z,1599855575.477 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T20:19:35.478Z,1599855575.478 [Default:CheckIn:D] Running Loop=1
2020-09-11T20:19:35.870Z,1599855575.870 [Default:CheckIn:D] Stopped
2020-09-11T20:19:35.870Z,1599855575.870 [Default:CheckIn:E] Running Loop=1
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 180.171859 min 
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn:E] Stopped
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn] Stopped
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn](INFO): Running loop #30
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn] Running Loop=30
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T20:19:36.273Z,1599855576.273 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T20:19:38.287Z,1599855578.287 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201937.00,A,3648.16816,N,12147.28016,W,0.097,164.45,110920,,,A*78
2020-09-11T20:19:38.289Z,1599855578.289 [NAL9602](INFO): GPS fix at 20200911T201937: (36.802803, -121.788003)
2020-09-11T20:19:38.305Z,1599855578.305 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T20:19:38.305Z,1599855578.305 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T20:19:46.130Z,1599855586.130 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20200911T171503/Courier0091.lzma
2020-09-11T20:19:47.133Z,1599855587.133 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0091.lzma.bak
2020-09-11T20:19:47.133Z,1599855587.133 [DataOverHttps](INFO): SBD MOMSN=12648406
2020-09-11T20:20:03.055Z,1599855603.055 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20200911T171503/Express0092.lzma
2020-09-11T20:20:04.058Z,1599855604.058 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0092.lzma.bak
2020-09-11T20:20:04.058Z,1599855604.058 [DataOverHttps](INFO): SBD MOMSN=12648411
2020-09-11T20:20:05.777Z,1599855605.777 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T20:20:05.777Z,1599855605.777 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T20:20:05.778Z,1599855605.778 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T20:20:08.992Z,1599855608.992 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-09-11T20:20:09.071Z,1599855609.071 [NAL9602](FAULT): received: 
+CSQ:1

OK06, 2, 0, 0, 0

OK
2020-09-11T20:20:09.071Z,1599855609.071 [NAL9602] Data Fault, FailCount= 1
2020-09-11T20:20:09.071Z,1599855609.071 [NAL9602](ERROR): Data Fault
2020-09-11T20:20:09.136Z,1599855609.136 [CBIT](ERROR): Data Fault in component: NAL9602
2020-09-11T20:20:09.392Z,1599855609.392 [NAL9602](INFO): Powering down
2020-09-11T20:20:10.251Z,1599855610.251 [CBIT](INFO): Clearing failed state for component NAL9602
2020-09-11T20:20:10.251Z,1599855610.251 [NAL9602] No Fault, FailCount= 1
2020-09-11T20:20:39.696Z,1599855639.696 [NAL9602](INFO): Powering up NAL9602
2020-09-11T20:20:50.608Z,1599855650.608 [NAL9602](INFO): NAL9602 initialized
2020-09-11T20:21:21.712Z,1599855681.712 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T20:24:34.894Z,1599855874.894 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2020-09-11T20:25:06.366Z,1599855906.366 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-09-11T20:25:06.366Z,1599855906.366 [Default:CheckIn:C.Wait] Stopped
2020-09-11T20:25:06.366Z,1599855906.366 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T20:25:06.366Z,1599855906.366 [Default:CheckIn:D] Running Loop=1
2020-09-11T20:25:06.782Z,1599855906.782 [Default:CheckIn:D] Stopped
2020-09-11T20:25:06.782Z,1599855906.782 [Default:CheckIn:E] Running Loop=1
2020-09-11T20:25:07.152Z,1599855907.152 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 185.687077 min 
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn:E] Stopped
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn] Stopped
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn](INFO): Running loop #31
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn] Running Loop=31
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-09-11T20:25:07.153Z,1599855907.153 [Default:CheckIn:Read_GPS] Running Loop=1
2020-09-11T20:25:11.182Z,1599855911.182 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-09-11T20:26:50.974Z,1599856010.974 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202649.00,A,3648.15347,N,12147.28703,W,0.078,0.00,110920,,,A*71
2020-09-11T20:26:50.977Z,1599856010.977 [NAL9602](INFO): GPS fix at 20200911T202649: (36.802558, -121.788117)
2020-09-11T20:26:50.988Z,1599856010.988 [Default:CheckIn:Read_GPS] Stopped
2020-09-11T20:26:50.988Z,1599856010.988 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-09-11T20:26:58.382Z,1599856018.382 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200911T171503/Courier0094.lzma
2020-09-11T20:26:59.385Z,1599856019.385 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Courier0094.lzma.bak
2020-09-11T20:26:59.385Z,1599856019.385 [DataOverHttps](INFO): SBD MOMSN=12648414
2020-09-11T20:27:15.387Z,1599856035.387 [DataOverHttps](INFO): Sending 246 bytes from file Logs/20200911T171503/Express0095.lzma
2020-09-11T20:27:16.389Z,1599856036.389 [DataOverHttps](INFO): Moved sent file to Logs/20200911T171503/Express0095.lzma.bak
2020-09-11T20:27:16.389Z,1599856036.389 [DataOverHttps](INFO): SBD MOMSN=12648417
2020-09-11T20:27:18.057Z,1599856038.057 [Default:CheckIn:Read_Iridium] Stopped
2020-09-11T20:27:18.057Z,1599856038.057 [Default:CheckIn:C.Wait] Running Loop=1
2020-09-11T20:27:18.057Z,1599856038.057 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-09-11T20:27:23.296Z,1599856043.296 [NAL9602](INFO): Not Powering down - fast GPS
2020-09-11T20:30:22.339Z,1599856222.339 [CBIT](INFO): Clearing failed state for component DropWeight
2020-09-11T20:30:22.339Z,1599856222.339 [DropWeight] No Fault, FailCount= 1
2020-09-11T20:30:50.165Z,1599856250.165 [CommandLine](IMPORTANT): got command restart application
2020-09-11T20:30:51.184Z,1599856251.184 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:51.184Z,1599856251.184 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:51.279Z,1599856251.279 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2020-09-11T20:30:51.279Z,1599856251.279 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:51.280Z,1599856251.280 [CommandLine](INFO): Join timeout helper Thread ID is 3986
2020-09-11T20:30:51.280Z,1599856251.280 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2020-09-11T20:30:51.280Z,1599856251.280 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:51.281Z,1599856251.281 [NavChartDb](INFO): Join timeout helper Thread ID is 3987
2020-09-11T20:30:51.311Z,1599856251.311 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:51.312Z,1599856251.312 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:51.319Z,1599856251.319 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2020-09-11T20:30:51.319Z,1599856251.319 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:51.319Z,1599856251.319 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3988
2020-09-11T20:30:51.771Z,1599856251.771 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:51.772Z,1599856251.772 [WetLabsBB2FL](INFO): Powering down
2020-09-11T20:30:51.772Z,1599856251.772 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:51.779Z,1599856251.779 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2020-09-11T20:30:51.779Z,1599856251.779 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:51.779Z,1599856251.779 [CTD_Seabird](INFO): Join timeout helper Thread ID is 3989
2020-09-11T20:30:52.315Z,1599856252.315 [CTD_Seabird](INFO): Powering down
2020-09-11T20:30:52.331Z,1599856252.331 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:52.331Z,1599856252.331 [CTD_Seabird](INFO): Powering down
2020-09-11T20:30:52.343Z,1599856252.343 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:52.359Z,1599856252.359 [ComponentRegistry](INFO): Shutting down BackSeatDriver ThreadHandler
2020-09-11T20:30:52.359Z,1599856252.359 [BackSeatDriver ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:52.359Z,1599856252.359 [BackSeatDriver](INFO): Join timeout helper Thread ID is 3990
2020-09-11T20:30:52.707Z,1599856252.707 [BackSeatDriver ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:52.707Z,1599856252.707 [BackSeatDriver ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:52.724Z,1599856252.724 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2020-09-11T20:30:52.724Z,1599856252.724 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:52.724Z,1599856252.724 [Radio_Surface](INFO): Join timeout helper Thread ID is 3991
2020-09-11T20:30:53.111Z,1599856253.111 [Radio_Surface](INFO): Powering down
2020-09-11T20:30:53.112Z,1599856253.112 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:53.112Z,1599856253.112 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:53.128Z,1599856253.128 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2020-09-11T20:30:53.128Z,1599856253.128 [Onboard ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:53.128Z,1599856253.128 [Onboard](INFO): Join timeout helper Thread ID is 3992
2020-09-11T20:30:54.043Z,1599856254.043 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:54.043Z,1599856254.043 [Onboard ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.056Z,1599856254.056 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2020-09-11T20:30:54.056Z,1599856254.056 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.056Z,1599856254.056 [DataOverHttps](INFO): Join timeout helper Thread ID is 3993
2020-09-11T20:30:54.199Z,1599856254.199 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:54.200Z,1599856254.200 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.228Z,1599856254.228 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2020-09-11T20:30:54.228Z,1599856254.228 [logger ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.228Z,1599856254.228 [logger](INFO): Join timeout helper Thread ID is 3994
2020-09-11T20:30:54.239Z,1599856254.239 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:54.239Z,1599856254.239 [logger ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.240Z,1599856254.240 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2020-09-11T20:30:54.241Z,1599856254.241 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.241Z,1599856254.241 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2020-09-11T20:30:54.241Z,1599856254.241 [controlThread ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.241Z,1599856254.241 [controlThread](INFO): Join timeout helper Thread ID is 3995
2020-09-11T20:30:54.248Z,1599856254.248 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2020-09-11T20:30:54.248Z,1599856254.248 [controlThread](DEBUG): Uninitializing ControlThread
2020-09-11T20:30:54.249Z,1599856254.249 [AHRS_M2](INFO): Powering down
2020-09-11T20:30:54.320Z,1599856254.320 [NAL9602](INFO): Powering down
2020-09-11T20:30:54.321Z,1599856254.321 [DAT](INFO): Powering down
2020-09-11T20:30:54.607Z,1599856254.607 [AMEcho](INFO): Powering down
2020-09-11T20:30:54.608Z,1599856254.608 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2020-09-11T20:30:54.609Z,1599856254.609 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2020-09-11T20:30:54.610Z,1599856254.610 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2020-09-11T20:30:54.610Z,1599856254.610 [MissionManager](INFO): Uninitializing Mission Default
2020-09-11T20:30:54.610Z,1599856254.610 [Default] Stopped
2020-09-11T20:30:54.610Z,1599856254.610 [Default](DEBUG): Aggregate::uninitialize Default
2020-09-11T20:30:54.610Z,1599856254.610 [Default:B.GoToSurface] Stopped
2020-09-11T20:30:54.610Z,1599856254.610 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-09-11T20:30:54.610Z,1599856254.610 [Default:CheckIn] Stopped
2020-09-11T20:30:54.611Z,1599856254.611 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-09-11T20:30:54.611Z,1599856254.611 [Default:CheckIn:C.Wait] Stopped
2020-09-11T20:30:54.611Z,1599856254.611 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-09-11T20:30:54.613Z,1599856254.613 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2020-09-11T20:30:54.613Z,1599856254.613 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2020-09-11T20:30:54.614Z,1599856254.614 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2020-09-11T20:30:54.614Z,1599856254.614 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2020-09-11T20:30:54.614Z,1599856254.614 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2020-09-11T20:30:54.614Z,1599856254.614 [BuoyancyServo](INFO): Powering down
2020-09-11T20:30:54.627Z,1599856254.627 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2020-09-11T20:30:54.627Z,1599856254.627 [ElevatorServo](INFO): Powering down
2020-09-11T20:30:54.628Z,1599856254.628 [MassServo](DEBUG): Uninitialize Mass Servo.
2020-09-11T20:30:54.628Z,1599856254.628 [MassServo](INFO): Powering down
2020-09-11T20:30:54.629Z,1599856254.629 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2020-09-11T20:30:54.629Z,1599856254.629 [RudderServo](INFO): Powering down
2020-09-11T20:30:54.630Z,1599856254.630 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2020-09-11T20:30:54.630Z,1599856254.630 [ThrusterServo](INFO): Powering down
2020-09-11T20:30:54.631Z,1599856254.631 [SBIT](DEBUG): Uninitialize SBIT Component.
2020-09-11T20:30:54.631Z,1599856254.631 [IBIT](DEBUG): Uninitialize IBIT Component.
2020-09-11T20:30:54.631Z,1599856254.631 [CBIT](DEBUG): Uninitialize CBIT Component.
2020-09-11T20:30:54.631Z,1599856254.631 [CBIT](DEBUG): Powering off loads.
2020-09-11T20:30:54.643Z,1599856254.643 [CBIT](DEBUG): Disabling WDT.
2020-09-11T20:30:54.655Z,1599856254.655 [CBIT](DEBUG): Opening all GF detection circuits.
2020-09-11T20:30:54.656Z,1599856254.656 [controlThread ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.757Z,1599856254.757 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.759Z,1599856254.759 [Onboard ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.765Z,1599856254.765 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.829Z,1599856254.829 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.832Z,1599856254.832 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.836Z,1599856254.836 [BackSeatDriver ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.845Z,1599856254.845 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-09-11T20:30:54.922Z,1599856254.922 [logger ThreadHandler](INFO): Thread cancelled.