2019-11-13T16:43:37.458Z,1573663417.458 [Supervisor](DEBUG): Initializing supervisor.
2019-11-13T16:43:37.461Z,1573663417.461 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-11-13T16:43:37.461Z,1573663417.461 [SyncHandler](INFO): Protected caller Thread ID is 2131
2019-11-13T16:43:37.462Z,1573663417.462 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-11-13T16:43:37.463Z,1573663417.463 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-11-13T16:43:37.463Z,1573663417.463 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2132
2019-11-13T16:43:37.466Z,1573663417.466 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-11-13T16:43:37.478Z,1573663417.478 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-11-13T16:43:37.479Z,1573663417.479 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-11-13T16:43:37.480Z,1573663417.480 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2133
2019-11-13T16:43:37.480Z,1573663417.480 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-11-13T16:43:37.481Z,1573663417.481 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-11-13T16:43:37.482Z,1573663417.482 [logger ThreadHandler](INFO): Protected caller Thread ID is 2134
2019-11-13T16:43:37.484Z,1573663417.484 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-11-13T16:43:37.484Z,1573663417.484 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-11-13T16:43:37.486Z,1573663417.486 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-11-13T16:43:37.953Z,1573663417.953 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-11-13T16:43:37.954Z,1573663417.954 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-11-13T16:43:38.050Z,1573663418.050 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-11-13T16:43:38.050Z,1573663418.050 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-11-13T16:43:38.354Z,1573663418.354 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-11-13T16:43:38.354Z,1573663418.354 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-11-13T16:43:38.493Z,1573663418.493 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-11-13T16:43:38.493Z,1573663418.493 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-11-13T16:43:38.676Z,1573663418.676 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-11-13T16:43:38.677Z,1573663418.677 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-11-13T16:43:39.179Z,1573663419.179 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-11-13T16:43:39.180Z,1573663419.180 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-11-13T16:43:39.378Z,1573663419.378 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-11-13T16:43:39.379Z,1573663419.379 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-11-13T16:43:39.518Z,1573663419.518 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-11-13T16:43:39.519Z,1573663419.519 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-11-13T16:43:39.699Z,1573663419.699 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-11-13T16:43:39.700Z,1573663419.700 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-11-13T16:43:39.794Z,1573663419.794 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-11-13T16:43:39.794Z,1573663419.794 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-11-13T16:43:40.082Z,1573663420.082 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-11-13T16:43:40.083Z,1573663420.083 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-11-13T16:43:40.162Z,1573663420.162 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-11-13T16:43:40.262Z,1573663420.262 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-11-13T16:43:40.262Z,1573663420.262 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-11-13T16:43:40.881Z,1573663420.881 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-11-13T16:43:40.881Z,1573663420.881 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-11-13T16:43:41.273Z,1573663421.273 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-11-13T16:43:41.275Z,1573663421.275 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-11-13T16:43:41.276Z,1573663421.276 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-11-13T16:43:41.472Z,1573663421.472 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-11-13T16:43:41.568Z,1573663421.568 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-11-13T16:43:41.664Z,1573663421.664 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-11-13T16:43:41.884Z,1573663421.884 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-11-13T16:43:41.885Z,1573663421.885 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-11-13T16:43:41.968Z,1573663421.968 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-11-13T16:43:42.060Z,1573663422.060 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-11-13T16:43:42.154Z,1573663422.154 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-11-13T16:43:42.270Z,1573663422.270 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-11-13T16:43:42.799Z,1573663422.799 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-11-13T16:43:43.402Z,1573663423.402 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-11-13T16:43:43.529Z,1573663423.529 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-11-13T16:43:43.529Z,1573663423.529 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-11-13T16:43:43.539Z,1573663423.539 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-11-13T16:43:43.901Z,1573663423.901 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-11-13T16:43:43.907Z,1573663423.907 [AHRS_M2](INFO): created writer for : platform_orientation
2019-11-13T16:43:43.909Z,1573663423.909 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-11-13T16:43:43.914Z,1573663423.914 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-11-13T16:43:43.915Z,1573663423.915 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-11-13T16:43:43.920Z,1573663423.920 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-11-13T16:43:43.921Z,1573663423.921 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-11-13T16:43:43.926Z,1573663423.926 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-11-13T16:43:43.995Z,1573663423.995 [AHRS_M2] Loaded
2019-11-13T16:43:43.995Z,1573663423.995 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-11-13T16:43:44.072Z,1573663424.072 [DataOverHttps] Loaded
2019-11-13T16:43:44.072Z,1573663424.072 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-11-13T16:43:44.073Z,1573663424.073 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407684E0
2019-11-13T16:43:44.074Z,1573663424.074 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2214
2019-11-13T16:43:44.087Z,1573663424.087 [Depth_Keller] Loaded
2019-11-13T16:43:44.087Z,1573663424.087 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-11-13T16:43:44.092Z,1573663424.092 [DropWeight] Loaded
2019-11-13T16:43:44.092Z,1573663424.092 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-11-13T16:43:44.153Z,1573663424.153 [DUSBL_Hydroid] Loaded
2019-11-13T16:43:44.154Z,1573663424.154 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-11-13T16:43:44.199Z,1573663424.199 [Micromodem] Loaded
2019-11-13T16:43:44.200Z,1573663424.200 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-11-13T16:43:44.293Z,1573663424.293 [NAL9602] Loaded
2019-11-13T16:43:44.294Z,1573663424.294 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-11-13T16:43:44.310Z,1573663424.310 [Onboard] Loaded
2019-11-13T16:43:44.310Z,1573663424.310 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-11-13T16:43:44.316Z,1573663424.316 [PowerOnly] Loaded
2019-11-13T16:43:44.316Z,1573663424.316 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-11-13T16:43:44.323Z,1573663424.323 [Radio_Surface] Loaded
2019-11-13T16:43:44.323Z,1573663424.323 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-11-13T16:43:44.324Z,1573663424.324 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407984E0
2019-11-13T16:43:44.324Z,1573663424.324 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2215
2019-11-13T16:43:44.367Z,1573663424.367 [RDI_Pathfinder] Loaded
2019-11-13T16:43:44.367Z,1573663424.367 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-11-13T16:43:45.807Z,1573663425.807 [BPC1] Loaded
2019-11-13T16:43:45.807Z,1573663425.807 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-11-13T16:43:45.808Z,1573663425.808 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-11-13T16:43:45.808Z,1573663425.808 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-11-13T16:43:45.831Z,1573663425.831 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-11-13T16:43:45.832Z,1573663425.832 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-11-13T16:43:45.950Z,1573663425.950 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-11-13T16:43:45.951Z,1573663425.951 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-11-13T16:43:45.970Z,1573663425.970 [NavChart] Loaded
2019-11-13T16:43:45.971Z,1573663425.971 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-11-13T16:43:45.974Z,1573663425.974 [UniversalFixResidualReporter] Loaded
2019-11-13T16:43:45.975Z,1573663425.975 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-11-13T16:43:45.975Z,1573663425.975 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-11-13T16:43:45.976Z,1573663425.976 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-11-13T16:43:46.102Z,1573663426.102 [BuoyancyServo] Loaded
2019-11-13T16:43:46.102Z,1573663426.102 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-11-13T16:43:46.117Z,1573663426.117 [ElevatorServo] Loaded
2019-11-13T16:43:46.117Z,1573663426.117 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-11-13T16:43:46.132Z,1573663426.132 [MassServo] Loaded
2019-11-13T16:43:46.132Z,1573663426.132 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-11-13T16:43:46.147Z,1573663426.147 [RudderServo] Loaded
2019-11-13T16:43:46.147Z,1573663426.147 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-11-13T16:43:46.162Z,1573663426.162 [ThrusterServo] Loaded
2019-11-13T16:43:46.162Z,1573663426.162 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-11-13T16:43:46.163Z,1573663426.163 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-11-13T16:43:46.163Z,1573663426.163 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-11-13T16:43:46.477Z,1573663426.477 [CTD_NeilBrown] Loaded
2019-11-13T16:43:46.478Z,1573663426.478 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-11-13T16:43:46.479Z,1573663426.479 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E34E0
2019-11-13T16:43:46.479Z,1573663426.479 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2216
2019-11-13T16:43:46.493Z,1573663426.493 [PAR_Licor] Loaded
2019-11-13T16:43:46.494Z,1573663426.494 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-11-13T16:43:46.537Z,1573663426.537 [WetLabsSeaOWL_UV_A] Loaded
2019-11-13T16:43:46.537Z,1573663426.537 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-11-13T16:43:46.538Z,1573663426.538 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409134E0
2019-11-13T16:43:46.539Z,1573663426.539 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 2217
2019-11-13T16:43:46.539Z,1573663426.539 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-11-13T16:43:46.540Z,1573663426.540 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-11-13T16:43:46.881Z,1573663426.881 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-11-13T16:43:46.882Z,1573663426.882 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-11-13T16:43:46.937Z,1573663426.937 [DepthRateCalculator] Loaded
2019-11-13T16:43:46.937Z,1573663426.937 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-11-13T16:43:46.943Z,1573663426.943 [PitchRateCalculator] Loaded
2019-11-13T16:43:46.943Z,1573663426.943 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-11-13T16:43:46.955Z,1573663426.955 [SpeedCalculator] Loaded
2019-11-13T16:43:46.955Z,1573663426.955 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-11-13T16:43:46.975Z,1573663426.975 [TempGradientCalculator] Loaded
2019-11-13T16:43:46.976Z,1573663426.976 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-11-13T16:43:46.981Z,1573663426.981 [YawRateCalculator] Loaded
2019-11-13T16:43:46.981Z,1573663426.981 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-11-13T16:43:47.020Z,1573663427.020 [ElevatorOffsetCalculator] Loaded
2019-11-13T16:43:47.021Z,1573663427.021 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-11-13T16:43:47.021Z,1573663427.021 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-11-13T16:43:47.022Z,1573663427.022 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-11-13T16:43:47.180Z,1573663427.180 [SBIT](DEBUG): Construct Startup Built In Test.
2019-11-13T16:43:47.201Z,1573663427.201 [SBIT] Loaded
2019-11-13T16:43:47.201Z,1573663427.201 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-11-13T16:43:47.202Z,1573663427.202 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-11-13T16:43:47.215Z,1573663427.215 [IBIT] Loaded
2019-11-13T16:43:47.215Z,1573663427.215 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-11-13T16:43:47.218Z,1573663427.218 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-11-13T16:43:47.352Z,1573663427.352 [CBIT] Loaded
2019-11-13T16:43:47.352Z,1573663427.352 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-11-13T16:43:47.352Z,1573663427.352 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-11-13T16:43:47.353Z,1573663427.353 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-11-13T16:43:47.630Z,1573663427.630 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-11-13T16:43:47.631Z,1573663427.631 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-11-13T16:43:47.753Z,1573663427.753 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-11-13T16:43:47.753Z,1573663427.753 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-11-13T16:43:47.840Z,1573663427.840 [VerticalControl](DEBUG): Construct VerticalControl.
2019-11-13T16:43:47.920Z,1573663427.920 [VerticalControl] Loaded
2019-11-13T16:43:47.921Z,1573663427.921 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-11-13T16:43:47.921Z,1573663427.921 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-11-13T16:43:47.977Z,1573663427.977 [HorizontalControl] Loaded
2019-11-13T16:43:47.977Z,1573663427.977 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-11-13T16:43:47.978Z,1573663427.978 [SpeedControl](DEBUG): Construct SpeedControl.
2019-11-13T16:43:47.979Z,1573663427.979 [SpeedControl] Loaded
2019-11-13T16:43:47.980Z,1573663427.980 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-11-13T16:43:47.980Z,1573663427.980 [LoopControl](DEBUG): Construct LoopControl.
2019-11-13T16:43:47.981Z,1573663427.981 [LoopControl] Loaded
2019-11-13T16:43:47.981Z,1573663427.981 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-11-13T16:43:47.982Z,1573663427.982 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-11-13T16:43:47.982Z,1573663427.982 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-11-13T16:43:48.030Z,1573663428.030 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-11-13T16:43:48.034Z,1573663428.034 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-11-13T16:43:48.035Z,1573663428.035 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-11-13T16:43:48.041Z,1573663428.041 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-11-13T16:43:48.042Z,1573663428.042 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AF74E0
2019-11-13T16:43:48.043Z,1573663428.043 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2218
2019-11-13T16:43:48.048Z,1573663428.048 [Supervisor](INFO): Main Thread ID is 2130
2019-11-13T16:43:48.048Z,1573663428.048 [Supervisor](DEBUG): Running supervisor.
2019-11-13T16:43:48.048Z,1573663428.048 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2219
2019-11-13T16:43:48.051Z,1573663428.051 [controlThread ThreadHandler](INFO): Handler Thread ID is 2220
2019-11-13T16:43:48.052Z,1573663428.052 [controlThread](DEBUG): Initializing ControlThread
2019-11-13T16:43:48.058Z,1573663428.058 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-11-13T16:43:48.059Z,1573663428.059 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-11-13T16:43:48.063Z,1573663428.063 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-11-13T16:43:48.064Z,1573663428.064 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-11-13T16:43:48.064Z,1573663428.064 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-11-13T16:43:48.064Z,1573663428.064 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-11-13T16:43:48.065Z,1573663428.065 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-11-13T16:43:48.065Z,1573663428.065 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-11-13T16:43:48.066Z,1573663428.066 [SBIT](INFO): Initialize SBIT Component.
2019-11-13T16:43:48.066Z,1573663428.066 [SBIT](IMPORTANT): git: 2019-11-13
2019-11-13T16:43:48.067Z,1573663428.067 [SBIT](INFO): git hash: 2b7b585d339468b8f6e14f82c7141d4679f332ef
2019-11-13T16:43:48.067Z,1573663428.067 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-11-13T16:43:48.068Z,1573663428.068 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #2 PREEMPT Wed May 15 08:34:03 PDT 2019
2019-11-13T16:43:48.070Z,1573663428.070 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-11-13T16:43:48.070Z,1573663428.070 [IBIT](INFO): Initialize IBIT Component.
2019-11-13T16:43:48.071Z,1573663428.071 [CBIT](DEBUG): Initialize CBIT Component.
2019-11-13T16:43:48.072Z,1573663428.072 [logger ThreadHandler](INFO): Handler Thread ID is 2221
2019-11-13T16:43:48.083Z,1573663428.083 [CBIT](DEBUG): Initialized mux pins.
2019-11-13T16:43:48.083Z,1573663428.083 [CBIT](DEBUG): Initializing the watchdog timer.
2019-11-13T16:43:48.092Z,1573663428.092 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2222
2019-11-13T16:43:48.093Z,1573663428.093 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-11-13T16:43:48.104Z,1573663428.104 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2223
2019-11-13T16:43:48.107Z,1573663428.107 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-11-13T16:43:48.107Z,1573663428.107 [CBIT](DEBUG): Initializing heartbeat.
2019-11-13T16:43:48.116Z,1573663428.116 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2224
2019-11-13T16:43:48.116Z,1573663428.116 [CTD_NeilBrown](INFO): Powering down
2019-11-13T16:43:48.140Z,1573663428.140 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 2225
2019-11-13T16:43:48.140Z,1573663428.140 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-11-13T16:43:48.168Z,1573663428.168 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2226
2019-11-13T16:43:48.173Z,1573663428.173 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-11-13T16:43:48.174Z,1573663428.174 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-11-13T16:43:48.174Z,1573663428.174 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-11-13T16:43:48.174Z,1573663428.174 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-11-13T16:43:48.174Z,1573663428.174 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-11-13T16:43:48.174Z,1573663428.174 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-11-13T16:43:48.175Z,1573663428.175 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-11-13T16:43:48.175Z,1573663428.175 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-11-13T16:43:48.175Z,1573663428.175 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-11-13T16:43:48.175Z,1573663428.175 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-11-13T16:43:48.176Z,1573663428.176 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-11-13T16:43:48.176Z,1573663428.176 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-11-13T16:43:48.176Z,1573663428.176 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-11-13T16:43:48.176Z,1573663428.176 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-11-13T16:43:48.176Z,1573663428.176 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-11-13T16:43:48.177Z,1573663428.177 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-11-13T16:43:48.179Z,1573663428.179 [CBIT](DEBUG): Deactivating GF circuits.
2019-11-13T16:43:48.179Z,1573663428.179 [CBIT](DEBUG): Deactivating emergency mode.
2019-11-13T16:43:48.215Z,1573663428.215 [CBIT](DEBUG): Backplane powered.
2019-11-13T16:43:48.215Z,1573663428.215 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-11-13T16:43:48.217Z,1573663428.217 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-11-13T16:43:48.218Z,1573663428.218 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-11-13T16:43:48.218Z,1573663428.218 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-11-13T16:43:48.219Z,1573663428.219 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-11-13T16:43:48.233Z,1573663428.233 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-13T16:43:48.255Z,1573663428.255 [MissionManager](DEBUG):
2019-11-13T16:43:48.256Z,1573663428.256 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-11-13T16:43:48.335Z,1573663428.335 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-11-13T16:43:48.336Z,1573663428.336 [Default:A.Wait](DEBUG): Construct Wait.
2019-11-13T16:43:48.338Z,1573663428.338 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-13T16:43:48.352Z,1573663428.352 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-11-13T16:43:48.379Z,1573663428.379 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-11-13T16:43:48.385Z,1573663428.385 [Default:E.Execute](DEBUG): Construct Execute.
2019-11-13T16:43:48.397Z,1573663428.397 [MissionManager](DEBUG):
0
Wait a moment to see if the scheduler starts a new mission before
starting to actually run Default.
13
Burn on
Dropped weight due to communications timeout.
5
Default mission has been running for
Restarting logs and Default mission.
restart logs
2019-11-13T16:43:48.413Z,1573663428.413 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-11-13T16:43:48.424Z,1573663428.424 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-11-13T16:43:48.479Z,1573663428.479 [DUSBL_Hydroid](INFO): Powering up
2019-11-13T16:43:48.480Z,1573663428.480 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-11-13T16:43:48.507Z,1573663428.507 [Radio_Surface](INFO): Powering up
2019-11-13T16:43:48.681Z,1573663428.681 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-11-13T16:43:48.687Z,1573663428.687 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-11-13T16:43:48.689Z,1573663428.689 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-11-13T16:43:48.695Z,1573663428.695 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-11-13T16:43:48.697Z,1573663428.697 [MassServo](DEBUG): Initializing EZServoServo.
2019-11-13T16:43:48.703Z,1573663428.703 [MassServo](DEBUG): Initializing MassServo.
2019-11-13T16:43:48.704Z,1573663428.704 [RudderServo](DEBUG): Initializing EZServoServo.
2019-11-13T16:43:48.711Z,1573663428.711 [RudderServo](DEBUG): Initializing RudderServo.
2019-11-13T16:43:48.712Z,1573663428.712 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-11-13T16:43:48.719Z,1573663428.719 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-11-13T16:43:48.838Z,1573663428.838 [Micromodem](INFO): Powering up
2019-11-13T16:43:48.838Z,1573663428.838 [Micromodem](DEBUG): Initializing Micromodem.
2019-11-13T16:43:49.579Z,1573663429.579 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-11-13T16:43:49.579Z,1573663429.579 [RudderServo](FAULT): Rudder failed to initialize
2019-11-13T16:43:49.579Z,1573663429.579 [RudderServo] Communications Fault, FailCount= 1
2019-11-13T16:43:49.579Z,1573663429.579 [RudderServo](ERROR): Communications Fault
2019-11-13T16:43:49.690Z,1573663429.690 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-11-13T16:43:49.860Z,1573663429.860 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-11-13T16:43:49.860Z,1573663429.860 [RudderServo](INFO): Powering down
2019-11-13T16:43:50.595Z,1573663430.595 [RudderServo](DEBUG): Initializing EZServoServo.
2019-11-13T16:43:50.712Z,1573663430.712 [RudderServo](DEBUG): Initializing RudderServo.
2019-11-13T16:43:50.716Z,1573663430.716 [CBIT](INFO): Clearing failed state for component RudderServo
2019-11-13T16:43:50.716Z,1573663430.716 [RudderServo] No Fault, FailCount= 1
2019-11-13T16:43:53.780Z,1573663433.780 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33
2019-11-13T16:43:54.191Z,1573663434.191 [Micromodem](INFO): Nmea in: $CATMG,2019-11-13T16:43:52.992049Z,RTC,RTC*50
2019-11-13T16:43:54.192Z,1573663434.192 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-11-13T16:43:52.992049Z,RTC,RTC*50
2019-11-13T16:43:54.673Z,1573663434.673 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31
2019-11-13T16:43:54.674Z,1573663434.674 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31
2019-11-13T16:43:55.077Z,1573663435.077 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33
2019-11-13T16:43:55.077Z,1573663435.077 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64
2019-11-13T16:43:55.482Z,1573663435.482 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66
2019-11-13T16:43:55.482Z,1573663435.482 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F
2019-11-13T16:43:55.889Z,1573663435.889 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D
2019-11-13T16:43:55.890Z,1573663435.890 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E
2019-11-13T16:43:56.294Z,1573663436.294 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C
2019-11-13T16:43:56.294Z,1573663436.294 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46
2019-11-13T16:43:56.693Z,1573663436.693 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44
2019-11-13T16:43:56.694Z,1573663436.694 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63
2019-11-13T16:43:57.109Z,1573663437.109 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61
2019-11-13T16:43:57.109Z,1573663437.109 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A
2019-11-13T16:43:57.477Z,1573663437.477 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38
2019-11-13T16:43:57.478Z,1573663437.478 [Micromodem](INFO): Nmea out: $CCCLK,2019,11,13,16,43,58*41
2019-11-13T16:43:57.938Z,1573663437.938 [Micromodem](INFO): Nmea in: $CACLK,2019,11,13,16,43,58*43
2019-11-13T16:43:57.951Z,1573663437.951 [Micromodem](INFO): Nmea in: $CATMS,0,2019-11-13T16:43:59Z*72
2019-11-13T16:43:57.953Z,1573663437.953 [Micromodem](INFO): Nmea in: $CATMG,2019-11-13T16:43:59.026278Z,USER_CMD,RTC*1C
2019-11-13T16:44:01.939Z,1573663441.939 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-11-13T16:44:03.550Z,1573663443.550 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004580
2019-11-13T16:44:06.365Z,1573663446.365 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-11-13T16:44:14.053Z,1573663454.053 [RDI_Pathfinder](ERROR): Failed to parse:
:0, 0.00, 0.00, 0.00, 0.00
2019-11-13T16:44:14.434Z,1573663454.434 [NAL9602](INFO): Powering up NAL9602
2019-11-13T16:44:16.510Z,1573663456.510 [SBIT](IMPORTANT): Beginning Startup BIT
2019-11-13T16:44:16.519Z,1573663456.519 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-13T16:44:25.445Z,1573663465.445 [NAL9602](INFO): NAL9602 initialized
2019-11-13T16:44:26.880Z,1573663466.880 [CommandLine](IMPORTANT): got command get DDM.loadAtStartup
2019-11-13T16:44:26.880Z,1573663466.880 [CommandLine](IMPORTANT): DDM.loadAtStartup 0 bool
2019-11-13T16:44:27.591Z,1573663467.591 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010945
CHAN A1 (24V): -0.028405
CHAN A2 (12V): -0.007532
CHAN A3 (5V): -0.002611
CHAN B0 (3.3V): 0.000372
CHAN B1 (3.15aV): 0.000095
CHAN B2 (3.15bV): 0.000249
CHAN B3 (GND): 0.002231
OPEN: 0.005277
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-13T16:44:55.545Z,1573663495.545 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-11-13T16:45:09.860Z,1573663509.860 [SBIT](IMPORTANT): SBIT PASSED
2019-11-13T16:45:09.911Z,1573663509.911 [CommandLine](IMPORTANT): got command configSet list
2019-11-13T16:45:09.912Z,1573663509.912 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): DDM.verbosity=3 count;
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=75 count;
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=40 millisecond;
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): HorizontalControl.kiHeading=0.002 reciprocal_second;
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none;
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree;
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): PowerOnly.sampleTime=90 second;
2019-11-13T16:45:09.913Z,1573663509.913 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=250 cubic_centimeter;
2019-11-13T16:45:10.204Z,1573663510.204 [MissionManager](IMPORTANT): Started mission Startup
2019-11-13T16:45:10.204Z,1573663510.204 [Startup] Running Loop=1
2019-11-13T16:45:10.205Z,1573663510.205 [Startup](DEBUG): Aggregate::initialize Startup
2019-11-13T16:45:10.205Z,1573663510.205 [Startup:A.GoToSurface] Running Loop=1
2019-11-13T16:45:10.205Z,1573663510.205 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-13T16:45:10.205Z,1573663510.205 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-13T16:45:10.206Z,1573663510.206 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-13T16:45:10.206Z,1573663510.206 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-13T16:45:10.206Z,1573663510.206 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-13T16:45:10.207Z,1573663510.207 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-13T16:45:10.208Z,1573663510.208 [Startup:StartupSatComms] Running Loop=1
2019-11-13T16:45:10.208Z,1573663510.208 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-11-13T16:45:10.209Z,1573663510.209 [Startup:StartupSatComms:A] Running Loop=1
2019-11-13T16:45:10.581Z,1573663510.581 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-11-13T16:46:10.361Z,1573663570.361 [Startup:StartupSatComms:A](INFO): Timed out from 2019-11-13T16:45:10.2Z
2019-11-13T16:46:10.362Z,1573663570.362 [Startup:StartupSatComms:A] Stopped
2019-11-13T16:46:10.362Z,1573663570.362 [Startup:StartupSatComms:B] Running Loop=1
2019-11-13T16:46:10.741Z,1573663570.741 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-13T16:46:20.172Z,1573663580.172 [DataOverHttps](INFO): Sending 762 bytes from file Logs/20191113T011203/Express0014.lzma
2019-11-13T16:46:22.177Z,1573663582.177 [DataOverHttps](INFO): Moved sent file to Logs/20191113T011203/Express0014.lzma.bak
2019-11-13T16:46:22.177Z,1573663582.177 [DataOverHttps](INFO): SBD MOMSN=11975585
2019-11-13T16:46:29.809Z,1573663589.809 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-11-13T16:46:34.397Z,1573663594.397 [CommandLine](IMPORTANT): got command burn on
2019-11-13T16:46:34.397Z,1573663594.397 [CommandLine](IMPORTANT): Activating dropweight wire
2019-11-13T16:46:42.328Z,1573663602.328 [DataOverHttps](INFO): Sending 853 bytes from file Logs/20191113T164337/Express0001.lzma
2019-11-13T16:46:44.333Z,1573663604.333 [DataOverHttps](INFO): Moved sent file to Logs/20191113T164337/Express0001.lzma.bak
2019-11-13T16:46:44.333Z,1573663604.333 [DataOverHttps](INFO): SBD MOMSN=11975629
2019-11-13T16:46:45.922Z,1573663605.922 [Startup:StartupSatComms:B] Stopped
2019-11-13T16:46:45.922Z,1573663605.922 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-11-13T16:46:45.922Z,1573663605.922 [Startup:StartupSatComms] Stopped
2019-11-13T16:46:45.922Z,1573663605.922 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-11-13T16:46:45.923Z,1573663605.923 [Startup](INFO): Completed Startup
2019-11-13T16:46:45.923Z,1573663605.923 [MissionManager](INFO): Startup is completed.
2019-11-13T16:46:45.923Z,1573663605.923 [MissionManager](INFO): Uninitializing Mission Startup
2019-11-13T16:46:45.923Z,1573663605.923 [Startup] Stopped
2019-11-13T16:46:45.924Z,1573663605.924 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-11-13T16:46:45.924Z,1573663605.924 [Startup:A.GoToSurface] Stopped
2019-11-13T16:46:45.924Z,1573663605.924 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-11-13T16:46:46.306Z,1573663606.306 [MissionManager](IMPORTANT): Started mission Default
2019-11-13T16:46:46.306Z,1573663606.306 [Default] Running Loop=1
2019-11-13T16:46:46.306Z,1573663606.306 [Default](DEBUG): Aggregate::initialize Default
2019-11-13T16:46:46.306Z,1573663606.306 [Default:B.GoToSurface] Running Loop=1
2019-11-13T16:46:46.306Z,1573663606.306 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-13T16:46:46.307Z,1573663606.307 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-13T16:46:46.307Z,1573663606.307 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-13T16:46:46.307Z,1573663606.307 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-13T16:46:46.308Z,1573663606.308 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-13T16:46:46.308Z,1573663606.308 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-13T16:46:46.308Z,1573663606.308 [Default:A.Wait] Running Loop=1
2019-11-13T16:46:46.308Z,1573663606.308 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-11-13T16:46:48.324Z,1573663608.324 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-11-13T16:46:48.324Z,1573663608.324 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-13T16:46:48.334Z,1573663608.334 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-13T16:46:48.760Z,1573663608.760 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-13T16:46:48.760Z,1573663608.760 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-11-13T16:46:53.617Z,1573663613.617 [CommandLine](IMPORTANT): got command burn off
2019-11-13T16:46:53.617Z,1573663613.617 [CommandLine](IMPORTANT): Deactivating dropweight wire
2019-11-13T16:46:59.646Z,1573663619.646 [Default:A.Wait](INFO): Done Waiting.
2019-11-13T16:46:59.646Z,1573663619.646 [Default:A.Wait] Stopped
2019-11-13T16:46:59.646Z,1573663619.646 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-11-13T16:47:00.076Z,1573663620.076 [Default:CheckIn] Running Loop=1
2019-11-13T16:47:00.076Z,1573663620.076 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-13T16:47:00.076Z,1573663620.076 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-13T16:47:00.461Z,1573663620.461 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-11-13T16:48:22.061Z,1573663702.061 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-13T16:48:22.061Z,1573663702.061 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19111309591176,35.0, -0.1, 0.0,144
2019-11-13T16:49:28.693Z,1573663768.693 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-11-13T16:49:49.348Z,1573663789.348 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-11-13T16:49:49.348Z,1573663789.348 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-13T16:49:49.381Z,1573663789.381 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-13T16:49:49.764Z,1573663789.764 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-13T16:49:49.765Z,1573663789.765 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-11-13T16:50:33.880Z,1573663833.880 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-11-13T16:51:22.303Z,1573663882.303 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-11-13T16:51:55.008Z,1573663915.008 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-11-13T16:51:55.019Z,1573663915.019 [BPC1](INFO): Received data from all battery sticks.
2019-11-13T16:52:00.249Z,1573663920.249 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-13T16:47:00.1Z
2019-11-13T16:52:00.249Z,1573663920.249 [Default:CheckIn:Read_GPS] Stopped
2019-11-13T16:52:00.249Z,1573663920.249 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-13T16:52:00.657Z,1573663920.657 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-13T16:52:10.013Z,1573663930.013 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20191113T164337/Courier0004.lzma
2019-11-13T16:52:12.009Z,1573663932.009 [DataOverHttps](INFO): Moved sent file to Logs/20191113T164337/Courier0004.lzma.bak
2019-11-13T16:52:12.009Z,1573663932.009 [DataOverHttps](INFO): SBD MOMSN=11975656
2019-11-13T16:52:31.363Z,1573663951.363 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20191113T164337/Express0005.lzma
2019-11-13T16:52:33.369Z,1573663953.369 [DataOverHttps](INFO): Moved sent file to Logs/20191113T164337/Express0005.lzma.bak
2019-11-13T16:52:33.369Z,1573663953.369 [DataOverHttps](INFO): SBD MOMSN=11975658
2019-11-13T16:52:34.983Z,1573663954.983 [Default:CheckIn:Read_Iridium] Stopped
2019-11-13T16:52:34.983Z,1573663954.983 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-13T16:52:34.983Z,1573663954.983 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-13T16:52:50.356Z,1573663970.356 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-11-13T16:52:50.356Z,1573663970.356 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-13T16:52:50.366Z,1573663970.366 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-13T16:52:50.764Z,1573663970.764 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-13T16:52:50.765Z,1573663970.765 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-11-13T16:53:43.682Z,1573664023.682 [RDI_Pathfinder](ERROR): Failed to parse:
68,-32768,-32768,V
2019-11-13T16:54:28.058Z,1573664068.058 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-11-13T16:54:28.058Z,1573664068.058 [NAL9602] Data Fault, FailCount= 1
2019-11-13T16:54:28.058Z,1573664068.058 [NAL9602](ERROR): Data Fault
2019-11-13T16:54:28.131Z,1573664068.131 [CBIT](ERROR): Data Fault in component: NAL9602
2019-11-13T16:54:28.466Z,1573664068.466 [NAL9602](INFO): Powering down
2019-11-13T16:54:29.307Z,1573664069.307 [CBIT](INFO): Clearing failed state for component NAL9602
2019-11-13T16:54:29.308Z,1573664069.308 [NAL9602] No Fault, FailCount= 1
2019-11-13T16:54:58.770Z,1573664098.770 [NAL9602](INFO): Powering up NAL9602
2019-11-13T16:55:09.678Z,1573664109.678 [NAL9602](INFO): NAL9602 initialized
2019-11-13T16:55:51.352Z,1573664151.352 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-11-13T16:55:51.352Z,1573664151.352 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-13T16:55:51.382Z,1573664151.382 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-13T16:55:51.765Z,1573664151.765 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-13T16:55:51.765Z,1573664151.765 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-11-13T16:56:18.277Z,1573664178.277 [CommandLine](IMPORTANT): got command configSet DDM.loadAtStartup 1.000000 bool persist
2019-11-13T16:56:18.278Z,1573664178.278 [CommandLine](IMPORTANT): configSet DDM.loadAtStartup requires a restart to take effect.
2019-11-13T16:57:29.458Z,1573664249.458 [DataOverHttps](IMPORTANT): SBD MTMSN=20191113T165622
2019-11-13T16:57:35.549Z,1573664255.549 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-13T16:57:35.549Z,1573664255.549 [Default:CheckIn:C.Wait] Stopped
2019-11-13T16:57:35.549Z,1573664255.549 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-13T16:57:35.549Z,1573664255.549 [Default:CheckIn:D] Running Loop=1
2019-11-13T16:57:35.961Z,1573664255.961 [Default:CheckIn:D] Stopped
2019-11-13T16:57:35.962Z,1573664255.962 [Default:CheckIn:E] Running Loop=1
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.827591 min
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn:E] Stopped
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn] Stopped
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn](INFO): Running loop #2
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn] Running Loop=2
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-13T16:57:36.396Z,1573664256.396 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-13T16:57:39.151Z,1573664259.151 [DataOverHttps](INFO): Received command:configSet DDM.loadAtStartup 1 bool persist
2019-11-13T16:57:39.339Z,1573664259.339 [CommandLine](IMPORTANT): got command configSet DDM.loadAtStartup 1.000000 bool persist
2019-11-13T16:57:39.339Z,1573664259.339 [CommandLine](IMPORTANT): configSet DDM.loadAtStartup requires a restart to take effect.
2019-11-13T16:58:25.669Z,1573664305.669 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-13T16:58:25.669Z,1573664305.669 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-32BE,-32768,-32768,-32768,V
2019-11-13T16:57:26.470Z,1573664246.470 [CommandLine](IMPORTANT): got command restart system
2019-11-13T16:57:28.534Z,1573664248.534 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-11-13T16:57:28.534Z,1573664248.534 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:28.534Z,1573664248.534 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:28.669Z,1573664248.669 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2019-11-13T16:57:28.670Z,1573664248.670 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:28.675Z,1573664248.675 [CommandLine](INFO): Join timeout helper Thread ID is 2279
2019-11-13T16:57:28.676Z,1573664248.676 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-11-13T16:57:28.676Z,1573664248.676 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:28.676Z,1573664248.676 [NavChartDb](INFO): Join timeout helper Thread ID is 2280
2019-11-13T16:57:28.726Z,1573664248.726 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:28.726Z,1573664248.726 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:28.734Z,1573664248.734 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-11-13T16:57:28.734Z,1573664248.734 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:28.734Z,1573664248.734 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 2281
2019-11-13T16:57:29.049Z,1573664249.049 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:29.050Z,1573664249.050 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-11-13T16:57:29.051Z,1573664249.051 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:29.054Z,1573664249.054 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-11-13T16:57:29.054Z,1573664249.054 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:29.054Z,1573664249.054 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2282
2019-11-13T16:57:29.142Z,1573664249.142 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:29.142Z,1573664249.142 [CTD_NeilBrown](INFO): Powering down
2019-11-13T16:57:29.153Z,1573664249.153 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:29.157Z,1573664249.157 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-11-13T16:57:29.158Z,1573664249.158 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:29.158Z,1573664249.158 [Radio_Surface](INFO): Join timeout helper Thread ID is 2283
2019-11-13T16:57:29.446Z,1573664249.446 [Radio_Surface](INFO): Powering down
2019-11-13T16:57:29.447Z,1573664249.447 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:29.447Z,1573664249.447 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:29.466Z,1573664249.466 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-11-13T16:57:29.467Z,1573664249.467 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:29.467Z,1573664249.467 [DataOverHttps](INFO): Join timeout helper Thread ID is 2284
2019-11-13T16:57:30.134Z,1573664250.134 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:30.134Z,1573664250.134 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.146Z,1573664250.146 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-11-13T16:57:30.146Z,1573664250.146 [logger ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.147Z,1573664250.147 [logger](INFO): Join timeout helper Thread ID is 2285
2019-11-13T16:57:30.182Z,1573664250.182 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:30.182Z,1573664250.182 [logger ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.190Z,1573664250.190 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-11-13T16:57:30.190Z,1573664250.190 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.190Z,1573664250.190 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-11-13T16:57:30.191Z,1573664250.191 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.191Z,1573664250.191 [controlThread](INFO): Join timeout helper Thread ID is 2286
2019-11-13T16:57:30.196Z,1573664250.196 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-11-13T16:57:30.196Z,1573664250.196 [controlThread](DEBUG): Uninitializing ControlThread
2019-11-13T16:57:30.196Z,1573664250.196 [AHRS_M2](INFO): Powering down
2019-11-13T16:57:30.270Z,1573664250.270 [DUSBL_Hydroid](INFO): Powering down
2019-11-13T16:57:30.362Z,1573664250.362 [Micromodem](INFO): Powering down
2019-11-13T16:57:30.458Z,1573664250.458 [NAL9602](INFO): Powering down
2019-11-13T16:57:30.530Z,1573664250.530 [RDI_Pathfinder](INFO): Powering down
2019-11-13T16:57:30.531Z,1573664250.531 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-11-13T16:57:30.532Z,1573664250.532 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-11-13T16:57:30.533Z,1573664250.533 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-11-13T16:57:30.533Z,1573664250.533 [MissionManager](INFO): Uninitializing Mission Default
2019-11-13T16:57:30.533Z,1573664250.533 [Default] Stopped
2019-11-13T16:57:30.533Z,1573664250.533 [Default](DEBUG): Aggregate::uninitialize Default
2019-11-13T16:57:30.533Z,1573664250.533 [Default:B.GoToSurface] Stopped
2019-11-13T16:57:30.533Z,1573664250.533 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-11-13T16:57:30.534Z,1573664250.534 [Default:CheckIn] Stopped
2019-11-13T16:57:30.534Z,1573664250.534 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-13T16:57:30.534Z,1573664250.534 [Default:CheckIn:Read_GPS] Stopped
2019-11-13T16:57:30.536Z,1573664250.536 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-11-13T16:57:30.537Z,1573664250.537 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-11-13T16:57:30.537Z,1573664250.537 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-11-13T16:57:30.537Z,1573664250.537 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-11-13T16:57:30.538Z,1573664250.538 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-11-13T16:57:30.538Z,1573664250.538 [BuoyancyServo](INFO): Powering down
2019-11-13T16:57:30.549Z,1573664250.549 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-11-13T16:57:30.550Z,1573664250.550 [ElevatorServo](INFO): Powering down
2019-11-13T16:57:30.550Z,1573664250.550 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-11-13T16:57:30.551Z,1573664250.551 [MassServo](INFO): Powering down
2019-11-13T16:57:30.551Z,1573664250.551 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-11-13T16:57:30.551Z,1573664250.551 [RudderServo](INFO): Powering down
2019-11-13T16:57:30.552Z,1573664250.552 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-11-13T16:57:30.552Z,1573664250.552 [ThrusterServo](INFO): Powering down
2019-11-13T16:57:30.553Z,1573664250.553 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-11-13T16:57:30.553Z,1573664250.553 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-11-13T16:57:30.554Z,1573664250.554 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-11-13T16:57:30.554Z,1573664250.554 [CBIT](DEBUG): Powering off loads.
2019-11-13T16:57:30.565Z,1573664250.565 [CBIT](DEBUG): Disabling WDT.
2019-11-13T16:57:30.577Z,1573664250.577 [CBIT](DEBUG): Opening all GF detection circuits.
2019-11-13T16:57:30.578Z,1573664250.578 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.637Z,1573664250.637 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.647Z,1573664250.647 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.692Z,1573664250.692 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.695Z,1573664250.695 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.758Z,1573664250.758 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-11-13T16:57:30.816Z,1573664250.816 [logger ThreadHandler](INFO): Thread cancelled.