2019-07-23T22:07:07.085Z,1563919627.085 [Supervisor](DEBUG): Initializing supervisor.
2019-07-23T22:07:07.087Z,1563919627.087 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-23T22:07:07.088Z,1563919627.088 [SyncHandler](INFO): Protected caller Thread ID is 957
2019-07-23T22:07:07.088Z,1563919627.088 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-23T22:07:07.089Z,1563919627.089 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-23T22:07:07.090Z,1563919627.090 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 958
2019-07-23T22:07:07.092Z,1563919627.092 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-23T22:07:07.104Z,1563919627.104 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-23T22:07:07.105Z,1563919627.105 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-23T22:07:07.105Z,1563919627.105 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 959
2019-07-23T22:07:07.106Z,1563919627.106 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-23T22:07:07.107Z,1563919627.107 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-23T22:07:07.107Z,1563919627.107 [logger ThreadHandler](INFO): Protected caller Thread ID is 960
2019-07-23T22:07:07.109Z,1563919627.109 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-23T22:07:07.110Z,1563919627.110 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-23T22:07:07.111Z,1563919627.111 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-23T22:07:07.206Z,1563919627.206 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-23T22:07:07.207Z,1563919627.207 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-23T22:07:07.409Z,1563919627.409 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-23T22:07:07.409Z,1563919627.409 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-23T22:07:07.546Z,1563919627.546 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-23T22:07:07.546Z,1563919627.546 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-23T22:07:08.112Z,1563919628.112 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-23T22:07:08.113Z,1563919628.113 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-23T22:07:08.570Z,1563919628.570 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-23T22:07:08.570Z,1563919628.570 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-23T22:07:09.051Z,1563919629.051 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-23T22:07:09.052Z,1563919629.052 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-23T22:07:09.358Z,1563919629.358 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-23T22:07:09.359Z,1563919629.359 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-23T22:07:09.692Z,1563919629.692 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-23T22:07:09.693Z,1563919629.693 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-23T22:07:10.082Z,1563919630.082 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-23T22:07:10.083Z,1563919630.083 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-23T22:07:10.236Z,1563919630.236 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-23T22:07:10.236Z,1563919630.236 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-23T22:07:10.341Z,1563919630.341 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-23T22:07:10.342Z,1563919630.342 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-23T22:07:10.423Z,1563919630.423 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-23T22:07:10.525Z,1563919630.525 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-23T22:07:10.525Z,1563919630.525 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-23T22:07:10.723Z,1563919630.723 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-23T22:07:10.724Z,1563919630.724 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-23T22:07:10.938Z,1563919630.938 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-23T22:07:10.940Z,1563919630.940 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2019-07-23T22:07:10.941Z,1563919630.941 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2019-07-23T22:07:11.024Z,1563919631.024 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2019-07-23T22:07:11.256Z,1563919631.256 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-23T22:07:11.257Z,1563919631.257 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2019-07-23T22:07:11.351Z,1563919631.351 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2019-07-23T22:07:11.516Z,1563919631.516 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2019-07-23T22:07:11.719Z,1563919631.719 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2019-07-23T22:07:11.804Z,1563919631.804 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2019-07-23T22:07:11.904Z,1563919631.904 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2019-07-23T22:07:11.997Z,1563919631.997 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2019-07-23T22:07:12.193Z,1563919632.193 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2019-07-23T22:07:12.552Z,1563919632.552 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2019-07-23T22:07:12.786Z,1563919632.786 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-07-23T22:07:12.791Z,1563919632.791 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-23T22:07:12.895Z,1563919632.895 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-23T22:07:12.896Z,1563919632.896 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-23T22:07:13.035Z,1563919633.035 [BuoyancyServo] Loaded
2019-07-23T22:07:13.035Z,1563919633.035 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-23T22:07:13.051Z,1563919633.051 [ElevatorServo] Loaded
2019-07-23T22:07:13.051Z,1563919633.051 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-23T22:07:13.066Z,1563919633.066 [MassServo] Loaded
2019-07-23T22:07:13.067Z,1563919633.067 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-23T22:07:13.082Z,1563919633.082 [RudderServo] Loaded
2019-07-23T22:07:13.083Z,1563919633.083 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-23T22:07:13.098Z,1563919633.098 [ThrusterServo] Loaded
2019-07-23T22:07:13.098Z,1563919633.098 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-23T22:07:13.098Z,1563919633.098 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-23T22:07:13.099Z,1563919633.099 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-23T22:07:13.243Z,1563919633.243 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-23T22:07:13.274Z,1563919633.274 [SBIT] Loaded
2019-07-23T22:07:13.274Z,1563919633.274 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-23T22:07:13.275Z,1563919633.275 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-23T22:07:13.304Z,1563919633.304 [IBIT] Loaded
2019-07-23T22:07:13.304Z,1563919633.304 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-23T22:07:13.307Z,1563919633.307 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-23T22:07:13.711Z,1563919633.711 [CBIT] Loaded
2019-07-23T22:07:13.711Z,1563919633.711 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-23T22:07:13.712Z,1563919633.712 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-23T22:07:13.712Z,1563919633.712 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-23T22:07:13.905Z,1563919633.905 [Aanderaa_O2] Loaded
2019-07-23T22:07:13.905Z,1563919633.905 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-07-23T22:07:13.915Z,1563919633.915 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-07-23T22:07:13.920Z,1563919633.920 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-07-23T22:07:13.922Z,1563919633.922 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-07-23T22:07:13.927Z,1563919633.927 [CTD_Seabird](INFO): created writer for : depth
2019-07-23T22:07:13.927Z,1563919633.927 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-07-23T22:07:13.933Z,1563919633.933 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-07-23T22:07:13.934Z,1563919633.934 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-07-23T22:07:13.939Z,1563919633.939 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-07-23T22:07:13.939Z,1563919633.939 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-07-23T22:07:13.945Z,1563919633.945 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-07-23T22:07:13.946Z,1563919633.946 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-07-23T22:07:13.951Z,1563919633.951 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-07-23T22:07:13.952Z,1563919633.952 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-07-23T22:07:13.957Z,1563919633.957 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-07-23T22:07:13.984Z,1563919633.984 [CTD_Seabird] Loaded
2019-07-23T22:07:13.984Z,1563919633.984 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-07-23T22:07:13.986Z,1563919633.986 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066A4E0
2019-07-23T22:07:13.986Z,1563919633.986 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1039
2019-07-23T22:07:14.017Z,1563919634.017 [ESPComponent] Loaded
2019-07-23T22:07:14.017Z,1563919634.017 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-07-23T22:07:14.031Z,1563919634.031 [PAR_Licor] Loaded
2019-07-23T22:07:14.032Z,1563919634.032 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-07-23T22:07:14.081Z,1563919634.081 [WetLabsBB2FL] Loaded
2019-07-23T22:07:14.082Z,1563919634.082 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-07-23T22:07:14.083Z,1563919634.083 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069A4E0
2019-07-23T22:07:14.083Z,1563919634.083 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1040
2019-07-23T22:07:14.084Z,1563919634.084 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-23T22:07:14.084Z,1563919634.084 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-23T22:07:14.127Z,1563919634.127 [DepthRateCalculator] Loaded
2019-07-23T22:07:14.127Z,1563919634.127 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-23T22:07:14.133Z,1563919634.133 [PitchRateCalculator] Loaded
2019-07-23T22:07:14.133Z,1563919634.133 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-23T22:07:14.150Z,1563919634.150 [SpeedCalculator] Loaded
2019-07-23T22:07:14.150Z,1563919634.150 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-23T22:07:14.171Z,1563919634.171 [TempGradientCalculator] Loaded
2019-07-23T22:07:14.172Z,1563919634.172 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-23T22:07:14.178Z,1563919634.178 [YawRateCalculator] Loaded
2019-07-23T22:07:14.178Z,1563919634.178 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-23T22:07:14.212Z,1563919634.212 [ElevatorOffsetCalculator] Loaded
2019-07-23T22:07:14.212Z,1563919634.212 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-23T22:07:14.213Z,1563919634.213 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-23T22:07:14.213Z,1563919634.213 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-23T22:07:14.246Z,1563919634.246 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-23T22:07:14.246Z,1563919634.246 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-23T22:07:14.353Z,1563919634.353 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-23T22:07:14.353Z,1563919634.353 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-23T22:07:14.375Z,1563919634.375 [NavChart] Loaded
2019-07-23T22:07:14.376Z,1563919634.376 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-23T22:07:14.380Z,1563919634.380 [UniversalFixResidualReporter] Loaded
2019-07-23T22:07:14.380Z,1563919634.380 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-23T22:07:14.380Z,1563919634.380 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-23T22:07:14.381Z,1563919634.381 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-23T22:07:14.749Z,1563919634.749 [AHRS_M2] Loaded
2019-07-23T22:07:14.750Z,1563919634.750 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-07-23T22:07:14.825Z,1563919634.825 [DataOverHttps] Loaded
2019-07-23T22:07:14.826Z,1563919634.826 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-23T22:07:14.827Z,1563919634.827 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409734E0
2019-07-23T22:07:14.827Z,1563919634.827 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1041
2019-07-23T22:07:14.841Z,1563919634.841 [Depth_Keller] Loaded
2019-07-23T22:07:14.841Z,1563919634.841 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-23T22:07:14.846Z,1563919634.846 [DropWeight] Loaded
2019-07-23T22:07:14.846Z,1563919634.846 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-07-23T22:07:14.983Z,1563919634.983 [DVL_micro] Loaded
2019-07-23T22:07:14.983Z,1563919634.983 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2019-07-23T22:07:15.078Z,1563919635.078 [NAL9602] Loaded
2019-07-23T22:07:15.078Z,1563919635.078 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-23T22:07:15.083Z,1563919635.083 [Onboard] Loaded
2019-07-23T22:07:15.084Z,1563919635.084 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-23T22:07:15.087Z,1563919635.087 [Radio_Surface] Loaded
2019-07-23T22:07:15.087Z,1563919635.087 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-23T22:07:15.088Z,1563919635.088 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A34E0
2019-07-23T22:07:15.089Z,1563919635.089 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1042
2019-07-23T22:07:15.221Z,1563919635.221 [DAT] Loaded
2019-07-23T22:07:15.222Z,1563919635.222 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-07-23T22:07:16.565Z,1563919636.565 [BPC1] Loaded
2019-07-23T22:07:16.566Z,1563919636.566 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-23T22:07:16.566Z,1563919636.566 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-23T22:07:16.567Z,1563919636.567 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-23T22:07:16.640Z,1563919636.640 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-23T22:07:16.640Z,1563919636.640 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-23T22:07:16.713Z,1563919636.713 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-23T22:07:16.799Z,1563919636.799 [VerticalControl] Loaded
2019-07-23T22:07:16.799Z,1563919636.799 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-23T22:07:16.800Z,1563919636.800 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-23T22:07:16.859Z,1563919636.859 [HorizontalControl] Loaded
2019-07-23T22:07:16.859Z,1563919636.859 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-23T22:07:16.860Z,1563919636.860 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-23T22:07:16.862Z,1563919636.862 [SpeedControl] Loaded
2019-07-23T22:07:16.862Z,1563919636.862 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-23T22:07:16.863Z,1563919636.863 [LoopControl](DEBUG): Construct LoopControl.
2019-07-23T22:07:16.863Z,1563919636.863 [LoopControl] Loaded
2019-07-23T22:07:16.864Z,1563919636.864 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-23T22:07:16.864Z,1563919636.864 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-23T22:07:16.865Z,1563919636.865 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-23T22:07:16.878Z,1563919636.878 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-23T22:07:16.878Z,1563919636.878 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-23T22:07:17.189Z,1563919637.189 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-23T22:07:17.205Z,1563919637.205 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-23T22:07:17.206Z,1563919637.206 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-23T22:07:17.215Z,1563919637.215 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-23T22:07:17.216Z,1563919637.216 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADE4E0
2019-07-23T22:07:17.217Z,1563919637.217 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1043
2019-07-23T22:07:17.221Z,1563919637.221 [Supervisor](INFO): Main Thread ID is 803
2019-07-23T22:07:17.222Z,1563919637.222 [Supervisor](DEBUG): Running supervisor.
2019-07-23T22:07:17.222Z,1563919637.222 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1044
2019-07-23T22:07:17.224Z,1563919637.224 [controlThread ThreadHandler](INFO): Handler Thread ID is 1045
2019-07-23T22:07:17.225Z,1563919637.225 [controlThread](DEBUG): Initializing ControlThread
2019-07-23T22:07:17.227Z,1563919637.227 [SBIT](INFO): Initialize SBIT Component.
2019-07-23T22:07:17.227Z,1563919637.227 [SBIT](IMPORTANT): git: 2019-07-23
2019-07-23T22:07:17.227Z,1563919637.227 [SBIT](INFO): git hash: 66f82fd8c0ed4c5b011038c11738fd4b7b507f51
2019-07-23T22:07:17.228Z,1563919637.228 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-23T22:07:17.229Z,1563919637.229 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-07-23T22:07:17.230Z,1563919637.230 [SBIT](INFO): Beginning SBIT in 125.000000 seconds.
2019-07-23T22:07:17.231Z,1563919637.231 [IBIT](INFO): Initialize IBIT Component.
2019-07-23T22:07:17.231Z,1563919637.231 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-23T22:07:17.232Z,1563919637.232 [logger ThreadHandler](INFO): Handler Thread ID is 1046
2019-07-23T22:07:17.245Z,1563919637.245 [CBIT](DEBUG): Initialized mux pins.
2019-07-23T22:07:17.245Z,1563919637.245 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-23T22:07:17.253Z,1563919637.253 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1047
2019-07-23T22:07:17.254Z,1563919637.254 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-07-23T22:07:17.257Z,1563919637.257 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-07-23T22:07:17.259Z,1563919637.259 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1049
2019-07-23T22:07:17.260Z,1563919637.260 [WetLabsBB2FL](INFO): Powering down
2019-07-23T22:07:17.269Z,1563919637.269 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-23T22:07:17.269Z,1563919637.269 [CBIT](DEBUG): Initializing heartbeat.
2019-07-23T22:07:17.289Z,1563919637.289 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1050
2019-07-23T22:07:17.290Z,1563919637.290 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-23T22:07:17.301Z,1563919637.301 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1051
2019-07-23T22:07:17.317Z,1563919637.317 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1052
2019-07-23T22:07:17.320Z,1563919637.320 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-23T22:07:17.320Z,1563919637.320 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-23T22:07:17.321Z,1563919637.321 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-23T22:07:17.321Z,1563919637.321 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-23T22:07:17.321Z,1563919637.321 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-23T22:07:17.321Z,1563919637.321 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-23T22:07:17.322Z,1563919637.322 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-23T22:07:17.322Z,1563919637.322 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-23T22:07:17.322Z,1563919637.322 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-23T22:07:17.322Z,1563919637.322 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-23T22:07:17.322Z,1563919637.322 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-23T22:07:17.323Z,1563919637.323 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-23T22:07:17.323Z,1563919637.323 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-23T22:07:17.323Z,1563919637.323 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-23T22:07:17.323Z,1563919637.323 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-23T22:07:17.323Z,1563919637.323 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-23T22:07:17.341Z,1563919637.341 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-23T22:07:17.341Z,1563919637.341 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-23T22:07:17.377Z,1563919637.377 [CBIT](DEBUG): Backplane powered.
2019-07-23T22:07:17.381Z,1563919637.381 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-23T22:07:17.381Z,1563919637.381 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-23T22:07:17.382Z,1563919637.382 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-23T22:07:17.382Z,1563919637.382 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-23T22:07:17.383Z,1563919637.383 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-23T22:07:17.383Z,1563919637.383 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-23T22:07:17.384Z,1563919637.384 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-23T22:07:17.384Z,1563919637.384 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-23T22:07:17.396Z,1563919637.396 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-23T22:07:17.405Z,1563919637.405 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-23T22:07:17.406Z,1563919637.406 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-23T22:07:17.407Z,1563919637.407 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-23T22:07:17.407Z,1563919637.407 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-23T22:07:17.442Z,1563919637.442 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-23T22:07:17.489Z,1563919637.489 [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>


2019-07-23T22:07:17.490Z,1563919637.490 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-23T22:07:17.568Z,1563919637.568 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-23T22:07:17.569Z,1563919637.569 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-23T22:07:17.570Z,1563919637.570 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-23T22:07:17.625Z,1563919637.625 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-23T22:07:17.628Z,1563919637.628 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-23T22:07:17.644Z,1563919637.644 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-23T22:07:17.672Z,1563919637.672 [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>


2019-07-23T22:07:17.677Z,1563919637.677 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,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,
2019-07-23T22:07:17.705Z,1563919637.705 [Radio_Surface](INFO): Powering up
2019-07-23T22:07:17.710Z,1563919637.710 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-07-23T22:07:17.865Z,1563919637.865 [DVL_micro](INFO): Initializing
2019-07-23T22:07:17.890Z,1563919637.890 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-07-23T22:07:17.891Z,1563919637.891 [DAT](INFO): Powering up
2019-07-23T22:07:17.891Z,1563919637.891 [DAT](DEBUG): Initializing DAT.
2019-07-23T22:07:17.930Z,1563919637.930 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-07-23T22:07:17.990Z,1563919637.990 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-23T22:07:18.001Z,1563919638.001 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-23T22:07:18.002Z,1563919638.002 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-23T22:07:18.013Z,1563919638.013 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-23T22:07:18.014Z,1563919638.014 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-23T22:07:18.025Z,1563919638.025 [MassServo](DEBUG): Initializing MassServo.
2019-07-23T22:07:18.026Z,1563919638.026 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-23T22:07:18.037Z,1563919638.037 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-23T22:07:18.038Z,1563919638.038 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-23T22:07:18.047Z,1563919638.047 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-23T22:07:18.131Z,1563919638.131 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-07-23T22:07:18.131Z,1563919638.131 [DropWeight] Hardware Fault, FailCount= 1
2019-07-23T22:07:18.131Z,1563919638.131 [DropWeight](ERROR): Hardware Fault
2019-07-23T22:07:18.200Z,1563919638.200 [CommandLine](FAULT): Scheduling is paused
2019-07-23T22:07:18.201Z,1563919638.201 [CBIT](INFO): Critical error at 20190723T220718
2019-07-23T22:07:18.201Z,1563919638.201 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-07-23T22:07:18.203Z,1563919638.203 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-07-23T22:07:18.204Z,1563919638.204 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-07-23T22:07:18.849Z,1563919638.849 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-23T22:07:18.849Z,1563919638.849 [RudderServo](FAULT): Rudder failed to initialize
2019-07-23T22:07:18.849Z,1563919638.849 [RudderServo] Communications Fault, FailCount= 1
2019-07-23T22:07:18.849Z,1563919638.849 [RudderServo](ERROR): Communications Fault
2019-07-23T22:07:19.006Z,1563919639.006 [CBIT](INFO): Critical error at 20190723T220718
2019-07-23T22:07:19.008Z,1563919639.008 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-23T22:07:19.206Z,1563919639.206 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-23T22:07:19.206Z,1563919639.206 [RudderServo](INFO): Powering down
2019-07-23T22:07:19.889Z,1563919639.889 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-23T22:07:20.010Z,1563919640.010 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-23T22:07:20.014Z,1563919640.014 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-23T22:07:20.014Z,1563919640.014 [RudderServo] No Fault, FailCount= 1
2019-07-23T22:07:21.153Z,1563919641.153 [Aanderaa_O2](INFO): Powering down
2019-07-23T22:07:33.215Z,1563919653.215 [DAT](INFO): setting local address to 3
2019-07-23T22:07:33.588Z,1563919653.588 [DAT](INFO): set local address to 3
2019-07-23T22:07:45.305Z,1563919665.305 [NAL9602](INFO): Powering up NAL9602
2019-07-23T22:07:56.195Z,1563919676.195 [NAL9602](INFO): NAL9602 initialized
2019-07-23T22:07:57.013Z,1563919677.013 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:08:39.030Z,1563919719.030 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:08:39.031Z,1563919719.031 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:09:22.703Z,1563919762.703 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-23T22:09:22.708Z,1563919762.708 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-23T22:09:34.257Z,1563919774.257 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.009915
CHAN A1 (24V): -0.020192
CHAN A2 (12V): -0.005893
CHAN A3 (5V): -0.008439
CHAN B0 (3.3V): -0.002938
CHAN B1 (3.15aV): -0.002230
CHAN B2 (3.15bV): -0.001255
CHAN B3 (GND): -0.002196
OPEN: 0.012495
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-23T22:10:16.103Z,1563919816.103 [SBIT](IMPORTANT): SBIT PASSED
2019-07-23T22:10:16.150Z,1563919816.150 [CommandLine](IMPORTANT): got command configSet list
2019-07-23T22:10:16.150Z,1563919816.150 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-23T22:10:16.151Z,1563919816.151 [CommandLine](IMPORTANT): BuoyancyServo.fastPumpDepth=5 meter;

2019-07-23T22:10:16.151Z,1563919816.151 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool;

2019-07-23T22:10:16.151Z,1563919816.151 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=266 cubic_centimeter;

2019-07-23T22:10:16.151Z,1563919816.151 [CommandLine](IMPORTANT): VerticalControl.massDefault=26.5 millimeter;

2019-07-23T22:10:16.470Z,1563919816.470 [MissionManager](IMPORTANT): Started mission Startup
2019-07-23T22:10:16.470Z,1563919816.470 [Startup] Running Loop=1
2019-07-23T22:10:16.470Z,1563919816.470 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-23T22:10:16.470Z,1563919816.470 [Startup:A.GoToSurface] Running Loop=1
2019-07-23T22:10:16.470Z,1563919816.470 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-23T22:10:16.471Z,1563919816.471 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-23T22:10:16.471Z,1563919816.471 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-23T22:10:16.471Z,1563919816.471 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-23T22:10:16.472Z,1563919816.472 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-23T22:10:16.472Z,1563919816.472 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-23T22:10:16.474Z,1563919816.474 [Startup:StartupSatComms] Running Loop=1
2019-07-23T22:10:16.474Z,1563919816.474 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-23T22:10:16.474Z,1563919816.474 [Startup:StartupSatComms:A] Running Loop=1
2019-07-23T22:10:16.890Z,1563919816.890 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-23T22:10:17.692Z,1563919817.692 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-23T22:10:17.692Z,1563919817.692 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-23T22:10:17.702Z,1563919817.702 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-23T22:10:18.101Z,1563919818.101 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-23T22:10:18.101Z,1563919818.101 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-23T22:10:57.889Z,1563919857.889 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005467
2019-07-23T22:11:16.715Z,1563919876.715 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-23T22:10:16.5Z
2019-07-23T22:11:16.715Z,1563919876.715 [Startup:StartupSatComms:A] Stopped
2019-07-23T22:11:16.715Z,1563919876.715 [Startup:StartupSatComms:B] Running Loop=1
2019-07-23T22:11:17.074Z,1563919877.074 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-23T22:11:24.237Z,1563919884.237 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20190723T215718/Courier0004.lzma
2019-07-23T22:11:25.043Z,1563919885.043 [DataOverHttps](INFO): Moved sent file to Logs/20190723T215718/Courier0004.lzma.bak
2019-07-23T22:11:25.043Z,1563919885.043 [DataOverHttps](INFO): SBD MOMSN=11466557
2019-07-23T22:11:29.613Z,1563919889.613 [DVL_micro](ERROR): only read 45 of 46 data items
2019-07-23T22:11:29.614Z,1563919889.614 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 1 1 1 1 0.2 9.6 0.2 10.1 136.0 -179.6 -3482.7 360.4 0 654 0 444 0 1 0 2 0 0 0 0 0 0 0 280 0 0 0 0 0 0 3.72 -7.11 359.6 0.2 18.1 0.005 35.0 1489 90
2019-07-23T22:11:47.648Z,1563919907.648 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190723T220707/Courier0000.lzma
2019-07-23T22:11:48.454Z,1563919908.454 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Courier0000.lzma.bak
2019-07-23T22:11:48.454Z,1563919908.454 [DataOverHttps](INFO): SBD MOMSN=11466559
2019-07-23T22:12:05.901Z,1563919925.901 [DataOverHttps](INFO): Sending 510 bytes from file Logs/20190723T215718/Express0005.lzma
2019-07-23T22:12:06.706Z,1563919926.706 [DataOverHttps](INFO): Moved sent file to Logs/20190723T215718/Express0005.lzma.bak
2019-07-23T22:12:06.706Z,1563919926.706 [DataOverHttps](INFO): SBD MOMSN=11466564
2019-07-23T22:12:16.963Z,1563919936.963 [Startup:StartupSatComms:B](INFO): Timed out from 2019-07-23T22:11:16.7Z
2019-07-23T22:12:16.963Z,1563919936.963 [Startup:StartupSatComms:B] Stopped
2019-07-23T22:12:16.963Z,1563919936.963 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-23T22:12:16.963Z,1563919936.963 [Startup:StartupSatComms] Stopped
2019-07-23T22:12:16.963Z,1563919936.963 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-23T22:12:16.964Z,1563919936.964 [Startup](INFO): Completed Startup
2019-07-23T22:12:16.964Z,1563919936.964 [MissionManager](INFO): Startup is completed.
2019-07-23T22:12:16.964Z,1563919936.964 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-23T22:12:16.964Z,1563919936.964 [Startup] Stopped
2019-07-23T22:12:16.964Z,1563919936.964 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-23T22:12:16.964Z,1563919936.964 [Startup:A.GoToSurface] Stopped
2019-07-23T22:12:16.969Z,1563919936.969 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-23T22:12:17.467Z,1563919937.467 [MissionManager](IMPORTANT): Started mission Default
2019-07-23T22:12:17.467Z,1563919937.467 [Default] Running Loop=1
2019-07-23T22:12:17.467Z,1563919937.467 [Default](DEBUG): Aggregate::initialize Default
2019-07-23T22:12:17.467Z,1563919937.467 [Default:B.GoToSurface] Running Loop=1
2019-07-23T22:12:17.467Z,1563919937.467 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-23T22:12:17.467Z,1563919937.467 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-23T22:12:17.468Z,1563919937.468 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-23T22:12:17.468Z,1563919937.468 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-23T22:12:17.468Z,1563919937.468 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-23T22:12:17.469Z,1563919937.469 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-23T22:12:17.469Z,1563919937.469 [Default:A.Wait] Running Loop=1
2019-07-23T22:12:17.469Z,1563919937.469 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-23T22:12:26.545Z,1563919946.545 [DataOverHttps](INFO): Sending 775 bytes from file Logs/20190723T220707/Express0001.lzma
2019-07-23T22:12:27.350Z,1563919947.350 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Express0001.lzma.bak
2019-07-23T22:12:27.350Z,1563919947.350 [DataOverHttps](INFO): SBD MOMSN=11466582
2019-07-23T22:12:30.679Z,1563919950.679 [Default:A.Wait](INFO): Done Waiting.
2019-07-23T22:12:30.679Z,1563919950.679 [Default:A.Wait] Stopped
2019-07-23T22:12:30.679Z,1563919950.679 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-23T22:12:31.099Z,1563919951.099 [Default:CheckIn] Running Loop=1
2019-07-23T22:12:31.099Z,1563919951.099 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-23T22:12:31.099Z,1563919951.099 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-23T22:12:31.491Z,1563919951.491 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-23T22:12:59.356Z,1563919979.356 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-23T22:13:00.177Z,1563919980.177 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:02.997Z,1563919982.997 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:06.221Z,1563919986.221 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:09.065Z,1563919989.065 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:12.297Z,1563919992.297 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:15.105Z,1563919995.105 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:17.953Z,1563919997.953 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:18.801Z,1563919998.801 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-07-23T22:13:18.801Z,1563919998.801 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-23T22:13:18.831Z,1563919998.831 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-23T22:13:19.190Z,1563919999.190 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-23T22:13:19.190Z,1563919999.190 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-07-23T22:13:21.177Z,1563920001.177 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:24.005Z,1563920004.005 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:27.227Z,1563920007.227 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:30.073Z,1563920010.073 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:33.305Z,1563920013.305 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:36.117Z,1563920016.117 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:39.345Z,1563920019.345 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:42.189Z,1563920022.189 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:45.009Z,1563920025.009 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:48.241Z,1563920028.241 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:51.097Z,1563920031.097 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:54.309Z,1563920034.309 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:13:57.136Z,1563920037.136 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:00.369Z,1563920040.369 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:03.213Z,1563920043.213 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:06.441Z,1563920046.441 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:09.253Z,1563920049.253 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:12.093Z,1563920052.093 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:15.321Z,1563920055.321 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:18.129Z,1563920058.129 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:21.365Z,1563920061.365 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:24.201Z,1563920064.201 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:27.429Z,1563920067.429 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:30.257Z,1563920070.257 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:33.481Z,1563920073.481 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:36.325Z,1563920076.325 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:14:36.710Z,1563920076.710 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221434.00,A,3648.15686,N,12147.28676,W,0.136,333.87,230719,,,A*71
2019-07-23T22:14:36.714Z,1563920076.714 [NAL9602](INFO): GPS fix at 20190723T221434: (36.802614, -121.788113)
2019-07-23T22:14:36.744Z,1563920076.744 [Default:CheckIn:Read_GPS] Stopped
2019-07-23T22:14:36.744Z,1563920076.744 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-23T22:14:37.208Z,1563920077.208 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-23T22:14:49.657Z,1563920089.657 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20190723T220707/Courier0004.lzma
2019-07-23T22:14:50.462Z,1563920090.462 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Courier0004.lzma.bak
2019-07-23T22:14:50.462Z,1563920090.462 [DataOverHttps](INFO): SBD MOMSN=11466615
2019-07-23T22:15:04.734Z,1563920104.734 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:15:04.734Z,1563920104.734 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:15:04.734Z,1563920104.734 [DVL_micro](ERROR): Data Fault
2019-07-23T22:15:04.773Z,1563920104.773 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:15:05.213Z,1563920105.213 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:15:06.023Z,1563920106.023 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:15:06.023Z,1563920106.023 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:15:06.356Z,1563920106.356 [DVL_micro](INFO): Initializing
2019-07-23T22:15:08.843Z,1563920108.843 [NAL9602](INFO): Not Powering down - fast GPS
2019-07-23T22:15:09.600Z,1563920109.600 [DVL_micro](ERROR): only read 45 of 46 data items
2019-07-23T22:15:09.601Z,1563920109.601 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0008 1 1 1 1 0.2 0.4 0.2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3.57 -8. 0 18.1 0.005 35.0 1489 64
2019-07-23T22:15:12.289Z,1563920112.289 [DataOverHttps](INFO): Sending 303 bytes from file Logs/20190723T220707/Express0005.lzma
2019-07-23T22:15:13.094Z,1563920113.094 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Express0005.lzma.bak
2019-07-23T22:15:13.094Z,1563920113.094 [DataOverHttps](INFO): SBD MOMSN=11466618
2019-07-23T22:15:13.494Z,1563920113.494 [CommandLine](IMPORTANT): got command show stack
2019-07-23T22:15:13.494Z,1563920113.494 [CommandLine](IMPORTANT): Behavior Stack:

2019-07-23T22:15:13.494Z,1563920113.494 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-07-23T22:15:13.495Z,1563920113.495 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_Iridium
2019-07-23T22:15:18.472Z,1563920118.472 [DVL_micro](ERROR): only read 4 of 46 data items
2019-07-23T22:15:18.474Z,1563920118.474 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 01 1 1 0.2 0.3 0.2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 33 341.5 0 18.1 0.005 35.0 1489 64
2019-07-23T22:15:18.919Z,1563920118.919 [Default:CheckIn:Read_Iridium] Stopped
2019-07-23T22:15:18.919Z,1563920118.919 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-23T22:15:18.919Z,1563920118.919 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-23T22:15:33.456Z,1563920133.456 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-07-23T22:15:33.456Z,1563920133.456 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-07-23T22:15:33.457Z,1563920133.457 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-07-23T22:15:33.460Z,1563920133.460 [BPC1](INFO): Received data from all battery sticks.
2019-07-23T22:15:59.188Z,1563920159.188 [CommandLine](IMPORTANT): got command failComponent
2019-07-23T22:15:59.188Z,1563920159.188 [CommandLine](IMPORTANT): Failed components:
2019-07-23T22:15:59.189Z,1563920159.189 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2019-07-23T22:16:02.999Z,1563920162.999 [CommandLine](IMPORTANT): got command failComponent none DropWeight
2019-07-23T22:16:02.999Z,1563920162.999 [DropWeight] No Fault, FailCount= 1
2019-07-23T22:16:02.000Z,1563920163.000 [CommandLine](IMPORTANT): DropWeight failureMode is No Fault
2019-07-23T22:16:17.345Z,1563920177.345 [CommandLine](IMPORTANT): got command failComponent
2019-07-23T22:16:17.345Z,1563920177.345 [CommandLine](IMPORTANT): Failed components:
2019-07-23T22:16:17.345Z,1563920177.345 [CommandLine](IMPORTANT): No failed Components.
2019-07-23T22:16:45.140Z,1563920205.140 [CommandLine](IMPORTANT): got command failComponent
2019-07-23T22:16:45.140Z,1563920205.140 [CommandLine](IMPORTANT): Failed components:
2019-07-23T22:16:45.140Z,1563920205.140 [CommandLine](IMPORTANT): No failed Components.
2019-07-23T22:18:08.149Z,1563920288.149 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:18:08.149Z,1563920288.149 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:18:08.149Z,1563920288.149 [DVL_micro](ERROR): Data Fault
2019-07-23T22:18:08.189Z,1563920288.189 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:18:08.629Z,1563920288.629 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:18:09.413Z,1563920289.413 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:18:09.413Z,1563920289.413 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:18:09.780Z,1563920289.780 [DVL_micro](INFO): Initializing
2019-07-23T22:19:51.588Z,1563920391.588 [DVL_micro](ERROR): only read 44 of 46 data items
2019-07-23T22:19:51.588Z,1563920391.588 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 70 -31 926 -62 2 3 2 2 -1142.4 41.4 243.4 2 -768.2 846.5 243.4 2 -243 2 -768 846 243 2 15.93 7.01 314.3.1 0.005 35.0 1489 64
2019-07-23T22:20:19.921Z,1563920419.921 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-07-23T22:20:19.921Z,1563920419.921 [Default:CheckIn:C.Wait] Stopped
2019-07-23T22:20:19.921Z,1563920419.921 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-23T22:20:19.921Z,1563920419.921 [Default:CheckIn:D] Running Loop=1
2019-07-23T22:20:20.284Z,1563920420.284 [Default:CheckIn:D] Stopped
2019-07-23T22:20:20.284Z,1563920420.284 [Default:CheckIn:E] Running Loop=1
2019-07-23T22:20:20.716Z,1563920420.716 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.046952 min 
2019-07-23T22:20:20.716Z,1563920420.716 [Default:CheckIn:E] Stopped
2019-07-23T22:20:20.716Z,1563920420.716 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-07-23T22:20:20.716Z,1563920420.716 [Default:CheckIn] Stopped
2019-07-23T22:20:20.717Z,1563920420.717 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-23T22:20:20.717Z,1563920420.717 [Default:CheckIn](INFO): Running loop #2
2019-07-23T22:20:20.717Z,1563920420.717 [Default:CheckIn] Running Loop=2
2019-07-23T22:20:20.717Z,1563920420.717 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-23T22:20:20.717Z,1563920420.717 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-23T22:20:22.295Z,1563920422.295 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:20:52.988Z,1563920452.988 [DVL_micro](ERROR): checksum mismatch: reported68 , calculated:81
2019-07-23T22:20:52.989Z,1563920452.989 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -89 31 7 3 2 2 -1105.1 158.8 159.9 2 -608.4 936.1 159.9 2 -1105 158 159 2 -608 936 159 2 15.99 7.01 311.2 -3.0 18.2 0.005 35.0 1489 68
2019-07-23T22:21:34.596Z,1563920494.596 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:21:34.596Z,1563920494.596 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:21:39.036Z,1563920499.036 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:21:39.036Z,1563920499.036 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:21:39.036Z,1563920499.036 [DVL_micro](ERROR): Data Fault
2019-07-23T22:21:39.129Z,1563920499.129 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:21:39.513Z,1563920499.513 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:21:40.331Z,1563920500.331 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:21:40.331Z,1563920500.331 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:21:40.657Z,1563920500.657 [DVL_micro](INFO): Initializing
2019-07-23T22:23:10.752Z,1563920590.752 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:23:10.752Z,1563920590.752 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:23:44.284Z,1563920624.284 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:23:44.284Z,1563920624.284 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:23:52.768Z,1563920632.768 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:23:52.768Z,1563920632.768 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:24:10.948Z,1563920650.948 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:24:10.948Z,1563920650.948 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:24:18.623Z,1563920658.623 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:24:18.624Z,1563920658.624 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:24:26.698Z,1563920666.698 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:24:26.698Z,1563920666.698 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:24:44.474Z,1563920684.474 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:24:44.474Z,1563920684.474 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:24:44.882Z,1563920684.882 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:24:44.882Z,1563920684.882 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:24:44.882Z,1563920684.882 [DVL_micro](ERROR): Data Fault
2019-07-23T22:24:44.957Z,1563920684.957 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:24:45.353Z,1563920685.353 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:24:46.156Z,1563920686.156 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:24:46.156Z,1563920686.156 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:24:46.504Z,1563920686.504 [DVL_micro](INFO): Initializing
2019-07-23T22:25:20.436Z,1563920720.436 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:25:20.436Z,1563920720.436 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:25:20.915Z,1563920720.915 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-23T22:20:20.7Z
2019-07-23T22:25:20.915Z,1563920720.915 [Default:CheckIn:Read_GPS] Stopped
2019-07-23T22:25:20.915Z,1563920720.915 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-23T22:25:24.469Z,1563920724.469 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-23T22:25:28.472Z,1563920728.472 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20190723T220707/Courier0007.lzma
2019-07-23T22:25:29.278Z,1563920729.278 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Courier0007.lzma.bak
2019-07-23T22:25:29.278Z,1563920729.278 [DataOverHttps](INFO): SBD MOMSN=11466632
2019-07-23T22:25:44.953Z,1563920744.953 [DataOverHttps](INFO): Sending 493 bytes from file Logs/20190723T220707/Express0008.lzma
2019-07-23T22:25:45.482Z,1563920745.482 [DVL_micro](ERROR): No DVL communication! Re-initializing
2019-07-23T22:25:45.482Z,1563920745.482 [DVL_micro] Communications Fault, FailCount= 1
2019-07-23T22:25:45.482Z,1563920745.482 [DVL_micro](ERROR): Communications Fault
2019-07-23T22:25:45.514Z,1563920745.514 [CBIT](ERROR): Communications Fault in component: DVL_micro
2019-07-23T22:25:45.758Z,1563920745.758 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Express0008.lzma.bak
2019-07-23T22:25:45.758Z,1563920745.758 [DataOverHttps](INFO): SBD MOMSN=11466634
2019-07-23T22:25:45.949Z,1563920745.949 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:25:46.749Z,1563920746.749 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:25:46.749Z,1563920746.749 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:25:47.110Z,1563920747.110 [DVL_micro](INFO): Initializing
2019-07-23T22:25:50.784Z,1563920750.784 [Default:CheckIn:Read_Iridium] Stopped
2019-07-23T22:25:50.789Z,1563920750.789 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-23T22:25:50.789Z,1563920750.789 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-23T22:25:55.175Z,1563920755.175 [NAL9602](INFO): Not Powering down - fast GPS
2019-07-23T22:27:50.750Z,1563920870.750 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:27:50.750Z,1563920870.750 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:27:50.750Z,1563920870.750 [DVL_micro](ERROR): Data Fault
2019-07-23T22:27:50.782Z,1563920870.782 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:27:51.217Z,1563920871.217 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:27:51.991Z,1563920871.991 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:27:51.991Z,1563920871.991 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:27:52.362Z,1563920872.362 [DVL_micro](INFO): Initializing
2019-07-23T22:30:51.364Z,1563921051.364 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-07-23T22:30:51.364Z,1563921051.364 [Default:CheckIn:C.Wait] Stopped
2019-07-23T22:30:51.364Z,1563921051.364 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-23T22:30:51.365Z,1563921051.365 [Default:CheckIn:D] Running Loop=1
2019-07-23T22:30:51.772Z,1563921051.772 [Default:CheckIn:D] Stopped
2019-07-23T22:30:51.772Z,1563921051.772 [Default:CheckIn:E] Running Loop=1
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.571753 min 
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn:E] Stopped
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn] Stopped
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn](INFO): Running loop #3
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn] Running Loop=3
2019-07-23T22:30:52.175Z,1563921052.175 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-23T22:30:52.176Z,1563921052.176 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-23T22:30:53.769Z,1563921053.769 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-07-23T22:30:53.769Z,1563921053.769 [NAL9602] Data Fault, FailCount= 1
2019-07-23T22:30:53.769Z,1563921053.769 [NAL9602](ERROR): Data Fault
2019-07-23T22:30:53.801Z,1563921053.801 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-23T22:30:54.170Z,1563921054.170 [NAL9602](INFO): Powering down
2019-07-23T22:30:55.009Z,1563921055.009 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-23T22:30:55.009Z,1563921055.009 [NAL9602] No Fault, FailCount= 1
2019-07-23T22:30:56.592Z,1563921056.592 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:30:56.592Z,1563921056.592 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:30:56.592Z,1563921056.592 [DVL_micro](ERROR): Data Fault
2019-07-23T22:30:56.645Z,1563921056.645 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:30:57.065Z,1563921057.065 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:30:57.828Z,1563921057.828 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:30:57.828Z,1563921057.828 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:30:58.220Z,1563921058.220 [DVL_micro](INFO): Initializing
2019-07-23T22:31:24.473Z,1563921084.473 [NAL9602](INFO): Powering up NAL9602
2019-07-23T22:31:35.386Z,1563921095.386 [NAL9602](INFO): NAL9602 initialized
2019-07-23T22:31:36.213Z,1563921096.213 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:32:45.681Z,1563921165.681 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:32:45.681Z,1563921165.681 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:32:57.811Z,1563921177.811 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:32:57.811Z,1563921177.811 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:33:58.794Z,1563921238.794 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:33:58.794Z,1563921238.794 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:34:02.429Z,1563921242.429 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:34:02.429Z,1563921242.429 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:34:02.430Z,1563921242.430 [DVL_micro](ERROR): Data Fault
2019-07-23T22:34:02.462Z,1563921242.462 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:34:02.909Z,1563921242.909 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:34:03.689Z,1563921243.689 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:34:03.689Z,1563921243.689 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:34:04.053Z,1563921244.053 [DVL_micro](INFO): Initializing
2019-07-23T22:34:26.274Z,1563921266.274 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:34:26.274Z,1563921266.274 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:34:39.200Z,1563921279.200 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:34:39.200Z,1563921279.200 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:34:56.566Z,1563921296.566 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:34:56.566Z,1563921296.566 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:35:03.838Z,1563921303.838 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:35:03.838Z,1563921303.838 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:35:19.196Z,1563921319.196 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:35:19.196Z,1563921319.196 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:35:52.318Z,1563921352.318 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:35:52.318Z,1563921352.318 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:35:52.344Z,1563921352.344 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-23T22:30:52.2Z
2019-07-23T22:35:52.344Z,1563921352.344 [Default:CheckIn:Read_GPS] Stopped
2019-07-23T22:35:52.345Z,1563921352.345 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-23T22:36:00.236Z,1563921360.236 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190723T220707/Courier0010.lzma
2019-07-23T22:36:01.042Z,1563921361.042 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Courier0010.lzma.bak
2019-07-23T22:36:01.042Z,1563921361.042 [DataOverHttps](INFO): SBD MOMSN=11466665
2019-07-23T22:36:16.693Z,1563921376.693 [DataOverHttps](INFO): Sending 250 bytes from file Logs/20190723T220707/Express0011.lzma
2019-07-23T22:36:17.368Z,1563921377.368 [DVL_micro](ERROR): No DVL communication! Re-initializing
2019-07-23T22:36:17.368Z,1563921377.368 [DVL_micro] Communications Fault, FailCount= 1
2019-07-23T22:36:17.368Z,1563921377.368 [DVL_micro](ERROR): Communications Fault
2019-07-23T22:36:17.418Z,1563921377.418 [CBIT](ERROR): Communications Fault in component: DVL_micro
2019-07-23T22:36:17.498Z,1563921377.498 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Express0011.lzma.bak
2019-07-23T22:36:17.498Z,1563921377.498 [DataOverHttps](INFO): SBD MOMSN=11466667
2019-07-23T22:36:17.853Z,1563921377.853 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:36:18.644Z,1563921378.644 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:36:18.644Z,1563921378.644 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:36:18.986Z,1563921378.986 [DVL_micro](INFO): Initializing
2019-07-23T22:36:22.283Z,1563921382.283 [Default:CheckIn:Read_Iridium] Stopped
2019-07-23T22:36:22.283Z,1563921382.283 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-23T22:36:22.284Z,1563921382.284 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-23T22:36:38.394Z,1563921398.394 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-23T22:37:08.274Z,1563921428.274 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:37:08.274Z,1563921428.274 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:37:08.274Z,1563921428.274 [DVL_micro](ERROR): Data Fault
2019-07-23T22:37:08.306Z,1563921428.306 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:37:08.741Z,1563921428.741 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:37:09.081Z,1563921429.081 [NAL9602](INFO): Not Powering down - fast GPS
2019-07-23T22:37:09.523Z,1563921429.523 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:37:09.523Z,1563921429.523 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:37:09.887Z,1563921429.887 [DVL_micro](INFO): Initializing
2019-07-23T22:40:14.138Z,1563921614.138 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:40:14.138Z,1563921614.138 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:40:14.138Z,1563921614.138 [DVL_micro](ERROR): Data Fault
2019-07-23T22:40:14.195Z,1563921614.195 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:40:14.609Z,1563921614.609 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:40:15.372Z,1563921615.372 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:40:15.372Z,1563921615.372 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:40:15.749Z,1563921615.749 [DVL_micro](INFO): Initializing
2019-07-23T22:41:22.833Z,1563921682.833 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-07-23T22:41:22.833Z,1563921682.833 [Default:CheckIn:C.Wait] Stopped
2019-07-23T22:41:22.833Z,1563921682.833 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-23T22:41:22.833Z,1563921682.833 [Default:CheckIn:D] Running Loop=1
2019-07-23T22:41:23.234Z,1563921683.234 [Default:CheckIn:D] Stopped
2019-07-23T22:41:23.234Z,1563921683.234 [Default:CheckIn:E] Running Loop=1
2019-07-23T22:41:23.669Z,1563921683.669 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.096116 min 
2019-07-23T22:41:23.669Z,1563921683.669 [Default:CheckIn:E] Stopped
2019-07-23T22:41:23.669Z,1563921683.669 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-07-23T22:41:23.669Z,1563921683.669 [Default:CheckIn] Stopped
2019-07-23T22:41:23.669Z,1563921683.669 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-23T22:41:23.669Z,1563921683.669 [Default:CheckIn](INFO): Running loop #4
2019-07-23T22:41:23.669Z,1563921683.669 [Default:CheckIn] Running Loop=4
2019-07-23T22:41:23.670Z,1563921683.670 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-23T22:41:23.670Z,1563921683.670 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-23T22:41:25.241Z,1563921685.241 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:41:56.352Z,1563921716.352 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-07-23T22:41:56.425Z,1563921716.425 [NAL9602](FAULT): received: 
+CSQ:0

OK935, 2, 0, 0, 0

OK
2019-07-23T22:41:56.425Z,1563921716.425 [NAL9602] Data Fault, FailCount= 2
2019-07-23T22:41:56.425Z,1563921716.425 [NAL9602](ERROR): Data Fault
2019-07-23T22:41:56.498Z,1563921716.498 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-23T22:41:56.766Z,1563921716.766 [NAL9602](INFO): Powering down
2019-07-23T22:41:57.584Z,1563921717.584 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-23T22:41:57.584Z,1563921717.584 [NAL9602] No Fault, FailCount= 2
2019-07-23T22:42:27.047Z,1563921747.047 [NAL9602](INFO): Powering up NAL9602
2019-07-23T22:42:37.983Z,1563921757.983 [NAL9602](INFO): NAL9602 initialized
2019-07-23T22:42:38.759Z,1563921758.759 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-07-23T22:42:38.759Z,1563921758.759 [NAL9602] Data Fault, FailCount= 3
2019-07-23T22:42:38.759Z,1563921758.759 [NAL9602](ERROR): Data Fault
2019-07-23T22:42:38.813Z,1563921758.813 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-23T22:42:39.177Z,1563921759.177 [NAL9602](INFO): Powering down
2019-07-23T22:42:40.045Z,1563921760.045 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-23T22:42:40.045Z,1563921760.045 [NAL9602] No Fault, FailCount= 3
2019-07-23T22:43:09.471Z,1563921789.471 [NAL9602](INFO): Powering up NAL9602
2019-07-23T22:43:19.970Z,1563921799.970 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:43:19.970Z,1563921799.970 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:43:19.970Z,1563921799.970 [DVL_micro](ERROR): Data Fault
2019-07-23T22:43:20.021Z,1563921800.021 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:43:20.437Z,1563921800.437 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:43:20.438Z,1563921800.438 [NAL9602](INFO): NAL9602 initialized
2019-07-23T22:43:21.189Z,1563921801.189 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:43:21.238Z,1563921801.238 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:43:21.238Z,1563921801.238 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:43:21.589Z,1563921801.589 [DVL_micro](INFO): Initializing
2019-07-23T22:44:14.512Z,1563921854.512 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:44:14.512Z,1563921854.512 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:44:42.388Z,1563921882.388 [DVL_micro](ERROR): only read 45 of 46 data items
2019-07-23T22:44:42.388Z,1563921882.388 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -13 2 844 45 2 3 2 2 -1143.8 -57.4 236.7 2 -1099.0 321.9 236.7 2 -1143 -57 236 2 -1099 321 236 2 2.58 -2.41 340.8 -3.0 18.8 0.005 9 68
2019-07-23T22:46:04.396Z,1563921964.396 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-07-23T22:46:04.396Z,1563921964.396 [DropWeight] Hardware Fault, FailCount= 2
2019-07-23T22:46:04.396Z,1563921964.396 [DropWeight](ERROR): Hardware Fault
2019-07-23T22:46:04.427Z,1563921964.427 [CBIT](INFO): Critical error at 20190723T224604
2019-07-23T22:46:04.430Z,1563921964.430 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-07-23T22:46:04.430Z,1563921964.430 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-07-23T22:46:04.851Z,1563921964.851 [CBIT](INFO): Critical error at 20190723T224604
2019-07-23T22:46:23.856Z,1563921983.856 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-23T22:41:23.7Z
2019-07-23T22:46:23.857Z,1563921983.857 [Default:CheckIn:Read_GPS] Stopped
2019-07-23T22:46:23.857Z,1563921983.857 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-23T22:46:25.817Z,1563921985.817 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:46:25.817Z,1563921985.817 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:46:25.817Z,1563921985.817 [DVL_micro](ERROR): Data Fault
2019-07-23T22:46:25.885Z,1563921985.885 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:46:26.281Z,1563921986.281 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:46:27.081Z,1563921987.081 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:46:27.081Z,1563921987.081 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:46:27.431Z,1563921987.431 [DVL_micro](INFO): Initializing
2019-07-23T22:46:27.438Z,1563921987.438 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-23T22:46:31.356Z,1563921991.356 [DataOverHttps](INFO): Sending 104 bytes from file Logs/20190723T220707/Courier0013.lzma
2019-07-23T22:46:32.162Z,1563921992.162 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Courier0013.lzma.bak
2019-07-23T22:46:32.162Z,1563921992.162 [DataOverHttps](INFO): SBD MOMSN=11466689
2019-07-23T22:46:49.537Z,1563922009.537 [DataOverHttps](INFO): Sending 288 bytes from file Logs/20190723T220707/Express0014.lzma
2019-07-23T22:46:50.342Z,1563922010.342 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Express0014.lzma.bak
2019-07-23T22:46:50.342Z,1563922010.342 [DataOverHttps](INFO): SBD MOMSN=11466693
2019-07-23T22:46:55.360Z,1563922015.360 [Default:CheckIn:Read_Iridium] Stopped
2019-07-23T22:46:55.360Z,1563922015.360 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-23T22:46:55.360Z,1563922015.360 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-23T22:46:58.160Z,1563922018.160 [NAL9602](INFO): Not Powering down - fast GPS
2019-07-23T22:49:24.861Z,1563922164.861 [CommandLine](IMPORTANT): got command burn on
2019-07-23T22:49:24.861Z,1563922164.861 [CommandLine](IMPORTANT): Activating dropweight wire
2019-07-23T22:49:31.700Z,1563922171.700 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:49:31.700Z,1563922171.700 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:49:31.700Z,1563922171.700 [DVL_micro](ERROR): Data Fault
2019-07-23T22:49:31.769Z,1563922171.769 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:49:32.178Z,1563922172.178 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:49:32.949Z,1563922172.949 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:49:32.949Z,1563922172.949 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:49:33.332Z,1563922173.332 [DVL_micro](INFO): Initializing
2019-07-23T22:49:42.531Z,1563922182.531 [CommandLine](IMPORTANT): got command burn off
2019-07-23T22:49:42.531Z,1563922182.531 [CommandLine](IMPORTANT): Deactivating dropweight wire
2019-07-23T22:51:55.968Z,1563922315.968 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-07-23T22:51:55.968Z,1563922315.968 [Default:CheckIn:C.Wait] Stopped
2019-07-23T22:51:55.968Z,1563922315.968 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-23T22:51:55.968Z,1563922315.968 [Default:CheckIn:D] Running Loop=1
2019-07-23T22:51:56.372Z,1563922316.372 [Default:CheckIn:D] Stopped
2019-07-23T22:51:56.372Z,1563922316.372 [Default:CheckIn:E] Running Loop=1
2019-07-23T22:51:56.773Z,1563922316.773 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.648421 min 
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn:E] Stopped
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn] Stopped
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn](INFO): Running loop #5
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn] Running Loop=5
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-23T22:51:56.774Z,1563922316.774 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-23T22:51:58.365Z,1563922318.365 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:52:29.473Z,1563922349.473 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-07-23T22:52:29.557Z,1563922349.557 [NAL9602](FAULT): received: 
+CSQ:0

OK935, 2, 0, 0, 0

OK
2019-07-23T22:52:29.557Z,1563922349.557 [NAL9602] Data Fault, FailCount= 4
2019-07-23T22:52:29.557Z,1563922349.557 [NAL9602](ERROR): Data Fault
2019-07-23T22:52:29.670Z,1563922349.670 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-23T22:52:29.864Z,1563922349.864 [NAL9602](INFO): Powering down
2019-07-23T22:52:30.730Z,1563922350.730 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-23T22:52:30.730Z,1563922350.730 [NAL9602] No Fault, FailCount= 4
2019-07-23T22:52:37.541Z,1563922357.541 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:52:37.542Z,1563922357.542 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:52:37.542Z,1563922357.542 [DVL_micro](ERROR): Data Fault
2019-07-23T22:52:37.575Z,1563922357.575 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:52:38.025Z,1563922358.025 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:52:38.824Z,1563922358.824 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:52:38.829Z,1563922358.829 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:52:39.163Z,1563922359.163 [DVL_micro](INFO): Initializing
2019-07-23T22:53:00.164Z,1563922380.164 [NAL9602](INFO): Powering up NAL9602
2019-07-23T22:53:11.074Z,1563922391.074 [NAL9602](INFO): NAL9602 initialized
2019-07-23T22:53:11.909Z,1563922391.909 [NAL9602](DEBUG): Fix Requested
2019-07-23T22:55:03.393Z,1563922503.393 [NAL9602](INFO): SBD MO Status=2, MOMSN=29935, MT Status=2, MTMSN=0
2019-07-23T22:55:03.394Z,1563922503.394 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-23T22:55:43.405Z,1563922543.405 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:55:43.405Z,1563922543.405 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:55:43.405Z,1563922543.405 [DVL_micro](ERROR): Data Fault
2019-07-23T22:55:43.457Z,1563922543.457 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:55:43.865Z,1563922543.865 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:55:44.637Z,1563922544.637 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:55:44.637Z,1563922544.637 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:55:45.010Z,1563922545.010 [DVL_micro](INFO): Initializing
2019-07-23T22:56:07.638Z,1563922567.638 [DVL_micro](ERROR): only read 45 of 46 data items
2019-07-23T22:56:07.638Z,1563922567.638 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 97 83 743 52 3 3 2 2 -862.2 41.4 262.9 2 -741.8 441.3 262.9 2 -862 41 26 441 262 2 -16.25 -2.46 332.0 -3.0 19.0 0.005 35.0 1489 74
2019-07-23T22:56:56.955Z,1563922616.955 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-23T22:51:56.8Z
2019-07-23T22:56:56.955Z,1563922616.955 [Default:CheckIn:Read_GPS] Stopped
2019-07-23T22:56:56.955Z,1563922616.955 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-23T22:57:00.154Z,1563922620.154 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-23T22:57:04.688Z,1563922624.688 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190723T220707/Courier0016.lzma
2019-07-23T22:57:05.494Z,1563922625.494 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Courier0016.lzma.bak
2019-07-23T22:57:05.495Z,1563922625.495 [DataOverHttps](INFO): SBD MOMSN=11466714
2019-07-23T22:57:22.666Z,1563922642.666 [DataOverHttps](INFO): Sending 345 bytes from file Logs/20190723T220707/Express0017.lzma
2019-07-23T22:57:23.470Z,1563922643.470 [DataOverHttps](INFO): Moved sent file to Logs/20190723T220707/Express0017.lzma.bak
2019-07-23T22:57:23.470Z,1563922643.470 [DataOverHttps](INFO): SBD MOMSN=11466716
2019-07-23T22:57:28.061Z,1563922648.061 [Default:CheckIn:Read_Iridium] Stopped
2019-07-23T22:57:28.061Z,1563922648.061 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-23T22:57:28.061Z,1563922648.061 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-23T22:57:30.854Z,1563922650.854 [NAL9602](INFO): Not Powering down - fast GPS
2019-07-23T22:58:49.230Z,1563922729.230 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T22:58:49.230Z,1563922729.230 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T22:58:49.230Z,1563922729.230 [DVL_micro](ERROR): Data Fault
2019-07-23T22:58:49.269Z,1563922729.269 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T22:58:49.709Z,1563922729.709 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T22:58:50.487Z,1563922730.487 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T22:58:50.487Z,1563922730.487 [DVL_micro] No Fault, FailCount= 1
2019-07-23T22:58:50.850Z,1563922730.850 [DVL_micro](INFO): Initializing
2019-07-23T23:01:04.613Z,1563922864.613 [CBIT](INFO): Clearing failed state for component DropWeight
2019-07-23T23:01:04.614Z,1563922864.614 [DropWeight] No Fault, FailCount= 2
2019-07-23T23:01:32.248Z,1563922892.248 [CommandLine](IMPORTANT): got command failComponent
2019-07-23T23:01:32.248Z,1563922892.248 [CommandLine](IMPORTANT): Failed components:
2019-07-23T23:01:32.248Z,1563922892.248 [CommandLine](IMPORTANT): No failed Components.
2019-07-23T23:01:55.090Z,1563922915.090 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-07-23T23:01:55.090Z,1563922915.090 [DVL_micro] Data Fault, FailCount= 1
2019-07-23T23:01:55.090Z,1563922915.090 [DVL_micro](ERROR): Data Fault
2019-07-23T23:01:55.123Z,1563922915.123 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-07-23T23:01:55.545Z,1563922915.545 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T23:01:56.314Z,1563922916.314 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-07-23T23:01:56.314Z,1563922916.314 [DVL_micro] No Fault, FailCount= 1
2019-07-23T23:01:56.696Z,1563922916.696 [DVL_micro](INFO): Initializing
2019-07-23T23:02:28.628Z,1563922948.628 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-07-23T23:02:28.628Z,1563922948.628 [Default:CheckIn:C.Wait] Stopped
2019-07-23T23:02:28.628Z,1563922948.628 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-23T23:02:28.628Z,1563922948.628 [Default:CheckIn:D] Running Loop=1
2019-07-23T23:02:29.058Z,1563922949.058 [Default:CheckIn:D] Stopped
2019-07-23T23:02:29.058Z,1563922949.058 [Default:CheckIn:E] Running Loop=1
2019-07-23T23:02:29.443Z,1563922949.443 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.193188 min 
2019-07-23T23:02:29.443Z,1563922949.443 [Default:CheckIn:E] Stopped
2019-07-23T23:02:29.443Z,1563922949.443 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-07-23T23:02:29.443Z,1563922949.443 [Default:CheckIn] Stopped
2019-07-23T23:02:29.444Z,1563922949.444 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-23T23:02:29.444Z,1563922949.444 [Default:CheckIn](INFO): Running loop #6
2019-07-23T23:02:29.444Z,1563922949.444 [Default:CheckIn] Running Loop=6
2019-07-23T23:02:29.444Z,1563922949.444 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-23T23:02:29.444Z,1563922949.444 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-23T23:02:31.024Z,1563922951.024 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-07-23T23:02:31.024Z,1563922951.024 [NAL9602] Data Fault, FailCount= 5
2019-07-23T23:02:31.025Z,1563922951.025 [NAL9602](ERROR): Data Fault
2019-07-23T23:02:31.056Z,1563922951.056 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-23T23:02:31.057Z,1563922951.057 [CBIT](CRITICAL): Data Fault in component: NAL9602
2019-07-23T23:02:31.432Z,1563922951.432 [NAL9602](INFO): Powering down
2019-07-23T23:02:31.464Z,1563922951.464 [CBIT](INFO): Critical error at 20190723T230231
2019-07-23T23:03:16.810Z,1563922996.810 [DataOverHttps](IMPORTANT): SBD MTMSN=20190723T230310
2019-07-23T23:03:21.901Z,1563923001.901 [DataOverHttps](INFO): Received command:restart app
2019-07-23T23:03:21.929Z,1563923001.929 [CommandLine](IMPORTANT): got command restart application
2019-07-23T23:03:22.933Z,1563923002.933 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:22.933Z,1563923002.933 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:22.961Z,1563923002.961 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-23T23:03:22.961Z,1563923002.961 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:22.962Z,1563923002.962 [CommandLine](INFO): Join timeout helper Thread ID is 1328
2019-07-23T23:03:22.962Z,1563923002.962 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-23T23:03:22.962Z,1563923002.962 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:22.963Z,1563923002.963 [NavChartDb](INFO): Join timeout helper Thread ID is 1329
2019-07-23T23:03:22.977Z,1563923002.977 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:22.977Z,1563923002.977 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:22.981Z,1563923002.981 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-23T23:03:22.981Z,1563923002.981 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:22.981Z,1563923002.981 [Radio_Surface](INFO): Join timeout helper Thread ID is 1330
2019-07-23T23:03:23.073Z,1563923003.073 [Radio_Surface](INFO): Powering down
2019-07-23T23:03:23.074Z,1563923003.074 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:23.074Z,1563923003.074 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.081Z,1563923003.081 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-23T23:03:23.081Z,1563923003.081 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.082Z,1563923003.082 [DataOverHttps](INFO): Join timeout helper Thread ID is 1331
2019-07-23T23:03:23.109Z,1563923003.109 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:23.109Z,1563923003.109 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.125Z,1563923003.125 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-07-23T23:03:23.125Z,1563923003.125 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.125Z,1563923003.125 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1332
2019-07-23T23:03:23.133Z,1563923003.133 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:23.134Z,1563923003.134 [WetLabsBB2FL](INFO): Powering down
2019-07-23T23:03:23.134Z,1563923003.134 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.138Z,1563923003.138 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-07-23T23:03:23.138Z,1563923003.138 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.138Z,1563923003.138 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1333
2019-07-23T23:03:23.649Z,1563923003.649 [CTD_Seabird](INFO): Powering down
2019-07-23T23:03:23.661Z,1563923003.661 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:23.662Z,1563923003.662 [CTD_Seabird](INFO): Powering down
2019-07-23T23:03:23.677Z,1563923003.677 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.678Z,1563923003.678 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-23T23:03:23.678Z,1563923003.678 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.678Z,1563923003.678 [logger](INFO): Join timeout helper Thread ID is 1334
2019-07-23T23:03:23.685Z,1563923003.685 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:23.685Z,1563923003.685 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.697Z,1563923003.697 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-23T23:03:23.698Z,1563923003.698 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.698Z,1563923003.698 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-23T23:03:23.698Z,1563923003.698 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:23.698Z,1563923003.698 [controlThread](INFO): Join timeout helper Thread ID is 1335
2019-07-23T23:03:23.929Z,1563923003.929 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-23T23:03:23.929Z,1563923003.929 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-23T23:03:23.929Z,1563923003.929 [Aanderaa_O2](INFO): Powering down
2019-07-23T23:03:23.950Z,1563923003.950 [AHRS_M2](INFO): Powering down
2019-07-23T23:03:24.093Z,1563923004.093 [DVL_micro](INFO): uninitialize:Powering down
2019-07-23T23:03:24.094Z,1563923004.094 [NAL9602](INFO): Powering down
2019-07-23T23:03:24.095Z,1563923004.095 [DAT](INFO): Powering down
2019-07-23T23:03:24.214Z,1563923004.214 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-23T23:03:24.214Z,1563923004.214 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-23T23:03:24.215Z,1563923004.215 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-23T23:03:24.215Z,1563923004.215 [MissionManager](INFO): Uninitializing Mission Default
2019-07-23T23:03:24.215Z,1563923004.215 [Default] Stopped
2019-07-23T23:03:24.216Z,1563923004.216 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-23T23:03:24.216Z,1563923004.216 [Default:B.GoToSurface] Stopped
2019-07-23T23:03:24.216Z,1563923004.216 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-23T23:03:24.216Z,1563923004.216 [Default:CheckIn] Stopped
2019-07-23T23:03:24.216Z,1563923004.216 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-23T23:03:24.216Z,1563923004.216 [Default:CheckIn:Read_GPS] Stopped
2019-07-23T23:03:24.218Z,1563923004.218 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-23T23:03:24.219Z,1563923004.219 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-23T23:03:24.219Z,1563923004.219 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-23T23:03:24.219Z,1563923004.219 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-23T23:03:24.219Z,1563923004.219 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-23T23:03:24.219Z,1563923004.219 [BuoyancyServo](INFO): Powering down
2019-07-23T23:03:24.233Z,1563923004.233 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-23T23:03:24.233Z,1563923004.233 [ElevatorServo](INFO): Powering down
2019-07-23T23:03:24.234Z,1563923004.234 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-23T23:03:24.234Z,1563923004.234 [MassServo](INFO): Powering down
2019-07-23T23:03:24.235Z,1563923004.235 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-23T23:03:24.235Z,1563923004.235 [RudderServo](INFO): Powering down
2019-07-23T23:03:24.235Z,1563923004.235 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-23T23:03:24.236Z,1563923004.236 [ThrusterServo](INFO): Powering down
2019-07-23T23:03:24.236Z,1563923004.236 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-23T23:03:24.237Z,1563923004.237 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-23T23:03:24.237Z,1563923004.237 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-23T23:03:24.237Z,1563923004.237 [CBIT](DEBUG): Powering off loads.
2019-07-23T23:03:24.249Z,1563923004.249 [CBIT](DEBUG): Disabling WDT.
2019-07-23T23:03:24.261Z,1563923004.261 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-23T23:03:24.262Z,1563923004.262 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:24.307Z,1563923004.307 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:24.312Z,1563923004.312 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:24.374Z,1563923004.374 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:24.381Z,1563923004.381 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:24.430Z,1563923004.430 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-23T23:03:24.499Z,1563923004.499 [logger ThreadHandler](INFO): Thread cancelled.