2019-05-24T17:23:06.142Z,1558718586.142 [Supervisor](DEBUG): Initializing supervisor.
2019-05-24T17:23:06.145Z,1558718586.145 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-24T17:23:06.146Z,1558718586.146 [SyncHandler](INFO): Protected caller Thread ID is 5792
2019-05-24T17:23:06.146Z,1558718586.146 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-24T17:23:06.147Z,1558718586.147 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-24T17:23:06.148Z,1558718586.148 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5793
2019-05-24T17:23:06.151Z,1558718586.151 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-24T17:23:06.163Z,1558718586.163 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-24T17:23:06.164Z,1558718586.164 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-24T17:23:06.164Z,1558718586.164 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5794
2019-05-24T17:23:06.165Z,1558718586.165 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-24T17:23:06.166Z,1558718586.166 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-24T17:23:06.166Z,1558718586.166 [logger ThreadHandler](INFO): Protected caller Thread ID is 5795
2019-05-24T17:23:06.168Z,1558718586.168 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-24T17:23:06.169Z,1558718586.169 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-24T17:23:06.170Z,1558718586.170 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-24T17:23:06.267Z,1558718586.267 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-24T17:23:06.268Z,1558718586.268 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-24T17:23:06.472Z,1558718586.472 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-24T17:23:06.473Z,1558718586.473 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-24T17:23:06.612Z,1558718586.612 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-24T17:23:06.613Z,1558718586.613 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-24T17:23:07.160Z,1558718587.160 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-24T17:23:07.160Z,1558718587.160 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-24T17:23:07.619Z,1558718587.619 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-24T17:23:07.619Z,1558718587.619 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-24T17:23:08.090Z,1558718588.090 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-24T17:23:08.091Z,1558718588.091 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-24T17:23:08.401Z,1558718588.401 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-24T17:23:08.402Z,1558718588.402 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-24T17:23:08.741Z,1558718588.741 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-24T17:23:08.742Z,1558718588.742 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-24T17:23:09.141Z,1558718589.141 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-24T17:23:09.141Z,1558718589.141 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-24T17:23:09.294Z,1558718589.294 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-24T17:23:09.295Z,1558718589.295 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-24T17:23:09.401Z,1558718589.401 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-24T17:23:09.402Z,1558718589.402 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-24T17:23:09.484Z,1558718589.484 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-24T17:23:09.587Z,1558718589.587 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-24T17:23:09.588Z,1558718589.588 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-24T17:23:09.792Z,1558718589.792 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-24T17:23:09.792Z,1558718589.792 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-24T17:23:10.002Z,1558718590.002 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-24T17:23:10.004Z,1558718590.004 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2019-05-24T17:23:10.005Z,1558718590.005 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2019-05-24T17:23:10.089Z,1558718590.089 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2019-05-24T17:23:10.336Z,1558718590.336 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-24T17:23:10.336Z,1558718590.336 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2019-05-24T17:23:10.533Z,1558718590.533 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2019-05-24T17:23:10.854Z,1558718590.854 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2019-05-24T17:23:11.309Z,1558718591.309 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2019-05-24T17:23:11.396Z,1558718591.396 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2019-05-24T17:23:11.496Z,1558718591.496 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2019-05-24T17:23:11.591Z,1558718591.591 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2019-05-24T17:23:11.747Z,1558718591.747 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2019-05-24T17:23:11.854Z,1558718591.854 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2019-05-24T17:23:11.956Z,1558718591.956 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/
2019-05-24T17:23:11.956Z,1558718591.956 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-24T17:23:11.973Z,1558718591.973 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-24T17:23:12.066Z,1558718592.066 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-24T17:23:12.067Z,1558718592.067 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-24T17:23:12.195Z,1558718592.195 [BuoyancyServo] Loaded
2019-05-24T17:23:12.195Z,1558718592.195 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-24T17:23:12.210Z,1558718592.210 [ElevatorServo] Loaded
2019-05-24T17:23:12.210Z,1558718592.210 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-24T17:23:12.225Z,1558718592.225 [MassServo] Loaded
2019-05-24T17:23:12.225Z,1558718592.225 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-24T17:23:12.239Z,1558718592.239 [RudderServo] Loaded
2019-05-24T17:23:12.240Z,1558718592.240 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-24T17:23:12.254Z,1558718592.254 [ThrusterServo] Loaded
2019-05-24T17:23:12.254Z,1558718592.254 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-24T17:23:12.254Z,1558718592.254 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-24T17:23:12.255Z,1558718592.255 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-24T17:23:12.380Z,1558718592.380 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-24T17:23:12.410Z,1558718592.410 [SBIT] Loaded
2019-05-24T17:23:12.410Z,1558718592.410 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-24T17:23:12.411Z,1558718592.411 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-24T17:23:12.438Z,1558718592.438 [IBIT] Loaded
2019-05-24T17:23:12.438Z,1558718592.438 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-24T17:23:12.441Z,1558718592.441 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-24T17:23:12.821Z,1558718592.821 [CBIT] Loaded
2019-05-24T17:23:12.821Z,1558718592.821 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-24T17:23:12.822Z,1558718592.822 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-24T17:23:12.822Z,1558718592.822 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-24T17:23:12.997Z,1558718592.997 [Aanderaa_O2] Loaded
2019-05-24T17:23:12.997Z,1558718592.997 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-05-24T17:23:13.006Z,1558718593.006 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-05-24T17:23:13.011Z,1558718593.011 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-05-24T17:23:13.013Z,1558718593.013 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-05-24T17:23:13.018Z,1558718593.018 [CTD_Seabird](INFO): created writer for : depth
2019-05-24T17:23:13.018Z,1558718593.018 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-05-24T17:23:13.023Z,1558718593.023 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-05-24T17:23:13.024Z,1558718593.024 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-05-24T17:23:13.029Z,1558718593.029 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-05-24T17:23:13.029Z,1558718593.029 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-05-24T17:23:13.035Z,1558718593.035 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-05-24T17:23:13.035Z,1558718593.035 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-05-24T17:23:13.041Z,1558718593.041 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-05-24T17:23:13.041Z,1558718593.041 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-05-24T17:23:13.046Z,1558718593.046 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-05-24T17:23:13.072Z,1558718593.072 [CTD_Seabird] Loaded
2019-05-24T17:23:13.072Z,1558718593.072 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-05-24T17:23:13.073Z,1558718593.073 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066A4E0
2019-05-24T17:23:13.074Z,1558718593.074 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 5874
2019-05-24T17:23:13.103Z,1558718593.103 [ESPComponent] Loaded
2019-05-24T17:23:13.103Z,1558718593.103 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-05-24T17:23:13.117Z,1558718593.117 [PAR_Licor] Loaded
2019-05-24T17:23:13.117Z,1558718593.117 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-05-24T17:23:13.164Z,1558718593.164 [WetLabsBB2FL] Loaded
2019-05-24T17:23:13.165Z,1558718593.165 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-05-24T17:23:13.166Z,1558718593.166 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069A4E0
2019-05-24T17:23:13.166Z,1558718593.166 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5875
2019-05-24T17:23:13.167Z,1558718593.167 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-24T17:23:13.167Z,1558718593.167 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-24T17:23:13.206Z,1558718593.206 [DepthRateCalculator] Loaded
2019-05-24T17:23:13.206Z,1558718593.206 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-24T17:23:13.212Z,1558718593.212 [PitchRateCalculator] Loaded
2019-05-24T17:23:13.212Z,1558718593.212 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-24T17:23:13.228Z,1558718593.228 [SpeedCalculator] Loaded
2019-05-24T17:23:13.228Z,1558718593.228 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-24T17:23:13.249Z,1558718593.249 [TempGradientCalculator] Loaded
2019-05-24T17:23:13.249Z,1558718593.249 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-24T17:23:13.255Z,1558718593.255 [YawRateCalculator] Loaded
2019-05-24T17:23:13.255Z,1558718593.255 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-24T17:23:13.287Z,1558718593.287 [ElevatorOffsetCalculator] Loaded
2019-05-24T17:23:13.288Z,1558718593.288 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-24T17:23:13.288Z,1558718593.288 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-24T17:23:13.289Z,1558718593.289 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-24T17:23:13.319Z,1558718593.319 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-24T17:23:13.320Z,1558718593.320 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-24T17:23:13.421Z,1558718593.421 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-24T17:23:13.421Z,1558718593.421 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-24T17:23:13.442Z,1558718593.442 [NavChart] Loaded
2019-05-24T17:23:13.442Z,1558718593.442 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-24T17:23:13.446Z,1558718593.446 [UniversalFixResidualReporter] Loaded
2019-05-24T17:23:13.447Z,1558718593.447 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-24T17:23:13.447Z,1558718593.447 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-24T17:23:13.448Z,1558718593.448 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-24T17:23:13.785Z,1558718593.785 [AHRS_M2] Loaded
2019-05-24T17:23:13.785Z,1558718593.785 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-24T17:23:13.860Z,1558718593.860 [DataOverHttps] Loaded
2019-05-24T17:23:13.860Z,1558718593.860 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-24T17:23:13.862Z,1558718593.862 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409734E0
2019-05-24T17:23:13.862Z,1558718593.862 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5876
2019-05-24T17:23:13.875Z,1558718593.875 [Depth_Keller] Loaded
2019-05-24T17:23:13.875Z,1558718593.875 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-24T17:23:13.880Z,1558718593.880 [DropWeight] Loaded
2019-05-24T17:23:13.880Z,1558718593.880 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-24T17:23:14.007Z,1558718594.007 [DVL_micro] Loaded
2019-05-24T17:23:14.007Z,1558718594.007 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2019-05-24T17:23:14.095Z,1558718594.095 [NAL9602] Loaded
2019-05-24T17:23:14.095Z,1558718594.095 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-24T17:23:14.100Z,1558718594.100 [Onboard] Loaded
2019-05-24T17:23:14.101Z,1558718594.101 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-24T17:23:14.104Z,1558718594.104 [Radio_Surface] Loaded
2019-05-24T17:23:14.104Z,1558718594.104 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-24T17:23:14.105Z,1558718594.105 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A34E0
2019-05-24T17:23:14.106Z,1558718594.106 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5877
2019-05-24T17:23:14.232Z,1558718594.232 [DAT] Loaded
2019-05-24T17:23:14.233Z,1558718594.233 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-05-24T17:23:15.734Z,1558718595.734 [BPC1] Loaded
2019-05-24T17:23:15.734Z,1558718595.734 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-24T17:23:15.734Z,1558718595.734 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-24T17:23:15.735Z,1558718595.735 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-24T17:23:15.889Z,1558718595.889 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-24T17:23:15.890Z,1558718595.890 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-24T17:23:15.994Z,1558718595.994 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-24T17:23:16.159Z,1558718596.159 [VerticalControl] Loaded
2019-05-24T17:23:16.159Z,1558718596.159 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-24T17:23:16.160Z,1558718596.160 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-24T17:23:16.216Z,1558718596.216 [HorizontalControl] Loaded
2019-05-24T17:23:16.217Z,1558718596.217 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-24T17:23:16.217Z,1558718596.217 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-24T17:23:16.219Z,1558718596.219 [SpeedControl] Loaded
2019-05-24T17:23:16.219Z,1558718596.219 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-24T17:23:16.220Z,1558718596.220 [LoopControl](DEBUG): Construct LoopControl.
2019-05-24T17:23:16.221Z,1558718596.221 [LoopControl] Loaded
2019-05-24T17:23:16.221Z,1558718596.221 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-24T17:23:16.221Z,1558718596.221 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-24T17:23:16.222Z,1558718596.222 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-24T17:23:16.235Z,1558718596.235 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-24T17:23:16.235Z,1558718596.235 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-24T17:23:16.513Z,1558718596.513 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-24T17:23:16.517Z,1558718596.517 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-24T17:23:16.518Z,1558718596.518 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-24T17:23:16.525Z,1558718596.525 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-24T17:23:16.526Z,1558718596.526 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADE4E0
2019-05-24T17:23:16.526Z,1558718596.526 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5878
2019-05-24T17:23:16.531Z,1558718596.531 [Supervisor](INFO): Main Thread ID is 5657
2019-05-24T17:23:16.531Z,1558718596.531 [Supervisor](DEBUG): Running supervisor.
2019-05-24T17:23:16.531Z,1558718596.531 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5879
2019-05-24T17:23:16.534Z,1558718596.534 [controlThread ThreadHandler](INFO): Handler Thread ID is 5880
2019-05-24T17:23:16.534Z,1558718596.534 [controlThread](DEBUG): Initializing ControlThread
2019-05-24T17:23:16.536Z,1558718596.536 [SBIT](INFO): Initialize SBIT Component.
2019-05-24T17:23:16.536Z,1558718596.536 [SBIT](IMPORTANT): git: 2019-05-20
2019-05-24T17:23:16.537Z,1558718596.537 [SBIT](INFO): git hash: 2a8aa54ec5933316883a1fda1f3ce53eb72b62ac
2019-05-24T17:23:16.537Z,1558718596.537 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-24T17:23:16.538Z,1558718596.538 [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-05-24T17:23:16.539Z,1558718596.539 [SBIT](INFO): Beginning SBIT in 48.000000 seconds.
2019-05-24T17:23:16.540Z,1558718596.540 [IBIT](INFO): Initialize IBIT Component.
2019-05-24T17:23:16.541Z,1558718596.541 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-24T17:23:16.542Z,1558718596.542 [logger ThreadHandler](INFO): Handler Thread ID is 5881
2019-05-24T17:23:16.553Z,1558718596.553 [CBIT](DEBUG): Initialized mux pins.
2019-05-24T17:23:16.553Z,1558718596.553 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-24T17:23:16.561Z,1558718596.561 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 5882
2019-05-24T17:23:16.562Z,1558718596.562 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-05-24T17:23:16.565Z,1558718596.565 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-05-24T17:23:16.567Z,1558718596.567 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5884
2019-05-24T17:23:16.568Z,1558718596.568 [WetLabsBB2FL](INFO): Powering down
2019-05-24T17:23:16.577Z,1558718596.577 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-24T17:23:16.577Z,1558718596.577 [CBIT](DEBUG): Initializing heartbeat.
2019-05-24T17:23:16.597Z,1558718596.597 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5885
2019-05-24T17:23:16.598Z,1558718596.598 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-24T17:23:16.609Z,1558718596.609 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5886
2019-05-24T17:23:16.625Z,1558718596.625 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5887
2019-05-24T17:23:16.628Z,1558718596.628 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-24T17:23:16.628Z,1558718596.628 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-24T17:23:16.629Z,1558718596.629 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-24T17:23:16.629Z,1558718596.629 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-24T17:23:16.629Z,1558718596.629 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-24T17:23:16.629Z,1558718596.629 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-24T17:23:16.629Z,1558718596.629 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-24T17:23:16.629Z,1558718596.629 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-24T17:23:16.630Z,1558718596.630 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-24T17:23:16.630Z,1558718596.630 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-24T17:23:16.630Z,1558718596.630 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-24T17:23:16.630Z,1558718596.630 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-24T17:23:16.630Z,1558718596.630 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-24T17:23:16.630Z,1558718596.630 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-24T17:23:16.631Z,1558718596.631 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-24T17:23:16.631Z,1558718596.631 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-24T17:23:16.649Z,1558718596.649 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-24T17:23:16.649Z,1558718596.649 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-24T17:23:16.685Z,1558718596.685 [CBIT](DEBUG): Backplane powered.
2019-05-24T17:23:16.689Z,1558718596.689 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-24T17:23:16.689Z,1558718596.689 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-24T17:23:16.690Z,1558718596.690 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-24T17:23:16.690Z,1558718596.690 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-24T17:23:16.691Z,1558718596.691 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-24T17:23:16.691Z,1558718596.691 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-24T17:23:16.692Z,1558718596.692 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-24T17:23:16.693Z,1558718596.693 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-24T17:23:16.711Z,1558718596.711 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-24T17:23:16.713Z,1558718596.713 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-24T17:23:16.714Z,1558718596.714 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-24T17:23:16.714Z,1558718596.714 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-24T17:23:16.715Z,1558718596.715 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-24T17:23:16.745Z,1558718596.745 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-24T17:23:16.772Z,1558718596.772 [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-05-24T17:23:16.781Z,1558718596.781 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-24T17:23:16.873Z,1558718596.873 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-24T17:23:16.874Z,1558718596.874 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-24T17:23:16.876Z,1558718596.876 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-24T17:23:16.899Z,1558718596.899 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-24T17:23:16.925Z,1558718596.925 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-24T17:23:16.931Z,1558718596.931 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-24T17:23:16.955Z,1558718596.955 [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-05-24T17:23:16.959Z,1558718596.959 [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-05-24T17:23:16.981Z,1558718596.981 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:23:17.013Z,1558718597.013 [Radio_Surface](INFO): Powering up
2019-05-24T17:23:17.149Z,1558718597.149 [DVL_micro](INFO): Initializing
2019-05-24T17:23:17.175Z,1558718597.175 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-05-24T17:23:17.175Z,1558718597.175 [DAT](INFO): Powering up
2019-05-24T17:23:17.176Z,1558718597.176 [DAT](DEBUG): Initializing DAT.
2019-05-24T17:23:17.233Z,1558718597.233 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-05-24T17:23:17.293Z,1558718597.293 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-24T17:23:17.305Z,1558718597.305 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-24T17:23:17.306Z,1558718597.306 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-24T17:23:17.317Z,1558718597.317 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-24T17:23:17.318Z,1558718597.318 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-24T17:23:17.329Z,1558718597.329 [MassServo](DEBUG): Initializing MassServo.
2019-05-24T17:23:17.330Z,1558718597.330 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-24T17:23:17.341Z,1558718597.341 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-24T17:23:17.342Z,1558718597.342 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-24T17:23:17.349Z,1558718597.349 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-24T17:23:18.193Z,1558718598.193 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-24T17:23:18.193Z,1558718598.193 [RudderServo](FAULT): Rudder failed to initialize
2019-05-24T17:23:18.193Z,1558718598.193 [RudderServo] Communications Fault, FailCount= 1
2019-05-24T17:23:18.194Z,1558718598.194 [RudderServo](ERROR): Communications Fault
2019-05-24T17:23:18.308Z,1558718598.308 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-24T17:23:18.510Z,1558718598.510 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-24T17:23:18.510Z,1558718598.510 [RudderServo](INFO): Powering down
2019-05-24T17:23:19.175Z,1558718599.175 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-24T17:23:19.294Z,1558718599.294 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-24T17:23:19.298Z,1558718599.298 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-24T17:23:19.298Z,1558718599.298 [RudderServo] No Fault, FailCount= 1
2019-05-24T17:23:20.453Z,1558718600.453 [Aanderaa_O2](INFO): Powering down
2019-05-24T17:23:20.837Z,1558718600.837 [AHRS_M2](ERROR): Format BitStream UART error: serial timeout
2019-05-24T17:23:25.685Z,1558718605.685 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:23:26.089Z,1558718606.089 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:23:32.558Z,1558718612.558 [DAT](INFO): setting local address to 3
2019-05-24T17:23:32.894Z,1558718612.894 [DAT](INFO): set local address to 3
2019-05-24T17:23:36.509Z,1558718616.509 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:23:36.509Z,1558718616.509 [AHRS_M2] Data Fault, FailCount= 1
2019-05-24T17:23:36.509Z,1558718616.509 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:23:36.630Z,1558718616.630 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:23:36.901Z,1558718616.901 [AHRS_M2](INFO): Powering down
2019-05-24T17:23:37.805Z,1558718617.805 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:23:37.805Z,1558718617.805 [AHRS_M2] No Fault, FailCount= 1
2019-05-24T17:23:38.114Z,1558718618.114 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:23:44.191Z,1558718624.191 [NAL9602](INFO): Powering up NAL9602
2019-05-24T17:23:51.457Z,1558718631.457 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:23:51.457Z,1558718631.457 [AHRS_M2] Data Fault, FailCount= 2
2019-05-24T17:23:51.457Z,1558718631.457 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:23:51.528Z,1558718631.528 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:23:51.849Z,1558718631.849 [AHRS_M2](INFO): Powering down
2019-05-24T17:23:52.761Z,1558718632.761 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:23:52.761Z,1558718632.761 [AHRS_M2] No Fault, FailCount= 2
2019-05-24T17:23:53.061Z,1558718633.061 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:23:55.087Z,1558718635.087 [NAL9602](INFO): NAL9602 initialized
2019-05-24T17:23:55.929Z,1558718635.929 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:24:05.238Z,1558718645.238 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-24T17:24:05.247Z,1558718645.247 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-24T17:24:06.405Z,1558718646.405 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:24:06.405Z,1558718646.405 [AHRS_M2] Data Fault, FailCount= 3
2019-05-24T17:24:06.405Z,1558718646.405 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:24:06.495Z,1558718646.495 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:24:06.797Z,1558718646.797 [AHRS_M2](INFO): Powering down
2019-05-24T17:24:07.841Z,1558718647.841 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:24:07.841Z,1558718647.841 [AHRS_M2] No Fault, FailCount= 3
2019-05-24T17:24:08.081Z,1558718648.081 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:24:11.641Z,1558718651.641 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:12.061Z,1558718652.061 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:12.593Z,1558718652.593 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:13.049Z,1558718653.049 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:13.497Z,1558718653.497 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:14.021Z,1558718654.021 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:14.481Z,1558718654.481 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:14.933Z,1558718654.933 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:15.437Z,1558718655.437 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:15.897Z,1558718655.897 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:16.337Z,1558718656.337 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:16.845Z,1558718656.845 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:16.937Z,1558718656.937 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.017478
CHAN A1 (24V): 0.011443
CHAN A2 (12V): 0.001058
CHAN A3 (5V): -0.005727
CHAN B0 (3.3V): -0.005701
CHAN B1 (3.15aV): -0.004183
CHAN B2 (3.15bV): -0.003530
CHAN B3 (GND): -0.007702
OPEN: 0.007253
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-24T17:24:22.404Z,1558718662.404 [AHRS_M2](ERROR): Read RFS packet UART error: serial buffer full
2019-05-24T17:24:22.784Z,1558718662.784 [AHRS_M2](ERROR): Read RFS packet UART error: serial buffer full
2019-05-24T17:24:23.171Z,1558718663.171 [AHRS_M2](ERROR): Read RFS packet UART error: serial buffer full
2019-05-24T17:24:27.301Z,1558718667.301 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:24:27.301Z,1558718667.301 [AHRS_M2] Data Fault, FailCount= 4
2019-05-24T17:24:27.301Z,1558718667.301 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:24:27.378Z,1558718667.378 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:24:27.617Z,1558718667.617 [AHRS_M2](INFO): Powering down
2019-05-24T17:24:28.527Z,1558718668.527 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:24:28.527Z,1558718668.527 [AHRS_M2] No Fault, FailCount= 4
2019-05-24T17:24:28.829Z,1558718668.829 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:24:32.165Z,1558718672.165 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:32.565Z,1558718672.565 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:32.957Z,1558718672.957 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:33.373Z,1558718673.373 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:33.777Z,1558718673.777 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:34.181Z,1558718674.181 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:34.589Z,1558718674.589 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:34.607Z,1558718674.607 [DVL_micro](ERROR): checksum mismatch: reported66 , calculated:95
2019-05-24T17:24:34.607Z,1558718674.607 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 392 295 203 291 2 3 2 2 252.2 5 2 50.3 -247.2 318.4 2 252 5 318 2 50 -247 318 2 -5.58 -1.67 280.3 -3.0 20.2 0.005 35.0 1489 66
2019-05-24T17:24:34.989Z,1558718674.989 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:35.393Z,1558718675.393 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:35.797Z,1558718675.797 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:36.193Z,1558718676.193 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:36.593Z,1558718676.593 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:37.009Z,1558718677.009 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:37.405Z,1558718677.405 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:37.821Z,1558718677.821 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:38.205Z,1558718678.205 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:38.621Z,1558718678.621 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:39.025Z,1558718679.025 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:39.433Z,1558718679.433 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:39.837Z,1558718679.837 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:40.241Z,1558718680.241 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:40.645Z,1558718680.645 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:41.049Z,1558718681.049 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:41.449Z,1558718681.449 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:41.857Z,1558718681.857 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:24:41.857Z,1558718681.857 [AHRS_M2](FAULT): Failed to initialize within timeout.
2019-05-24T17:24:41.857Z,1558718681.857 [AHRS_M2] Communications Fault, FailCount= 5
2019-05-24T17:24:41.857Z,1558718681.857 [AHRS_M2](ERROR): Communications Fault
2019-05-24T17:24:41.916Z,1558718681.916 [CBIT](ERROR): Communications Fault in component: AHRS_M2
2019-05-24T17:24:41.916Z,1558718681.916 [CBIT](CRITICAL): Communications Fault in component: AHRS_M2
2019-05-24T17:24:42.161Z,1558718682.161 [AHRS_M2](INFO): Powering down
2019-05-24T17:24:42.268Z,1558718682.268 [CommandLine](FAULT): Scheduling is paused
2019-05-24T17:24:42.268Z,1558718682.268 [CBIT](INFO): Critical error at 20190524T172441
2019-05-24T17:24:42.268Z,1558718682.268 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-05-24T17:24:58.866Z,1558718698.866 [SBIT](IMPORTANT): SBIT PASSED
2019-05-24T17:24:58.898Z,1558718698.898 [CommandLine](IMPORTANT): got command configSet list
2019-05-24T17:24:58.899Z,1558718698.899 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-24T17:24:58.900Z,1558718698.900 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=1 bool;

2019-05-24T17:24:58.900Z,1558718698.900 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup=0 bool;

2019-05-24T17:24:58.900Z,1558718698.900 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): BR_Ping1D.verbosity=1 count;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): CBIT.abortDepth=300 meter;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): CBIT.stopDepth=295 meter;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle=1 bool;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=1 bool;

2019-05-24T17:24:58.901Z,1558718698.901 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=1 bool;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): Express linearApproximation DAT.range 20.000000 meter;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): PAR_Licor.adcCal=8.765e-06 microampere_per_count;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): PAR_Licor.darkCount=0 count;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): PAR_Licor.multiplier=190.3 micromole_per_second_per_square_meter_per_microampere;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): PNI_TCM.loadAtStartup=0 bool;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool;

2019-05-24T17:24:58.902Z,1558718698.902 [CommandLine](IMPORTANT): VerticalControl.massDefault=-7 millimeter;

2019-05-24T17:24:59.286Z,1558718699.286 [MissionManager](IMPORTANT): Started mission Startup
2019-05-24T17:24:59.286Z,1558718699.286 [Startup] Running Loop=1
2019-05-24T17:24:59.286Z,1558718699.286 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-24T17:24:59.286Z,1558718699.286 [Startup:A.GoToSurface] Running Loop=1
2019-05-24T17:24:59.286Z,1558718699.286 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-24T17:24:59.287Z,1558718699.287 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-24T17:24:59.287Z,1558718699.287 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-24T17:24:59.287Z,1558718699.287 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-24T17:24:59.288Z,1558718699.288 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-24T17:24:59.288Z,1558718699.288 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-24T17:24:59.294Z,1558718699.294 [Startup:StartupSatComms] Running Loop=1
2019-05-24T17:24:59.294Z,1558718699.294 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-24T17:24:59.294Z,1558718699.294 [Startup:StartupSatComms:A] Running Loop=1
2019-05-24T17:24:59.699Z,1558718699.699 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-24T17:25:17.053Z,1558718717.053 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-24T17:25:17.053Z,1558718717.053 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-24T17:25:17.053Z,1558718717.053 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:25:17.064Z,1558718717.064 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:25:17.477Z,1558718717.477 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:25:17.477Z,1558718717.477 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-24T17:25:58.734Z,1558718758.734 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004654
2019-05-24T17:25:59.452Z,1558718759.452 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-24T17:24:59.3Z
2019-05-24T17:25:59.452Z,1558718759.452 [Startup:StartupSatComms:A] Stopped
2019-05-24T17:25:59.452Z,1558718759.452 [Startup:StartupSatComms:B] Running Loop=1
2019-05-24T17:25:59.866Z,1558718759.866 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-24T17:26:07.176Z,1558718767.176 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190522T162804/Courier0624.lzma
2019-05-24T17:26:07.983Z,1558718767.983 [DataOverHttps](INFO): Moved sent file to Logs/20190522T162804/Courier0624.lzma.bak
2019-05-24T17:26:07.983Z,1558718767.983 [DataOverHttps](INFO): SBD MOMSN=11179775
2019-05-24T17:26:21.354Z,1558718781.354 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:26:21.354Z,1558718781.354 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:26:21.354Z,1558718781.354 [DVL_micro](ERROR): Data Fault
2019-05-24T17:26:21.446Z,1558718781.446 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:26:21.829Z,1558718781.829 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:26:22.620Z,1558718782.620 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:26:22.620Z,1558718782.620 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:26:22.976Z,1558718782.976 [DVL_micro](INFO): Initializing
2019-05-24T17:26:43.668Z,1558718803.668 [DataOverHttps](INFO): Sending 122 bytes from file Logs/20190524T172108/Courier0000.lzma
2019-05-24T17:26:44.474Z,1558718804.474 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172108/Courier0000.lzma.bak
2019-05-24T17:26:44.474Z,1558718804.474 [DataOverHttps](INFO): SBD MOMSN=11179783
2019-05-24T17:26:59.766Z,1558718819.766 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-24T17:25:59.5Z
2019-05-24T17:26:59.766Z,1558718819.766 [Startup:StartupSatComms:B] Stopped
2019-05-24T17:26:59.766Z,1558718819.766 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-24T17:26:59.766Z,1558718819.766 [Startup:StartupSatComms] Stopped
2019-05-24T17:26:59.766Z,1558718819.766 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-24T17:26:59.767Z,1558718819.767 [Startup](INFO): Completed Startup
2019-05-24T17:26:59.767Z,1558718819.767 [MissionManager](INFO): Startup is completed.
2019-05-24T17:26:59.767Z,1558718819.767 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-24T17:26:59.767Z,1558718819.767 [Startup] Stopped
2019-05-24T17:26:59.767Z,1558718819.767 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-24T17:26:59.767Z,1558718819.767 [Startup:A.GoToSurface] Stopped
2019-05-24T17:26:59.767Z,1558718819.767 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-24T17:27:00.186Z,1558718820.186 [MissionManager](IMPORTANT): Started mission Default
2019-05-24T17:27:00.186Z,1558718820.186 [Default] Running Loop=1
2019-05-24T17:27:00.186Z,1558718820.186 [Default](DEBUG): Aggregate::initialize Default
2019-05-24T17:27:00.186Z,1558718820.186 [Default:B.GoToSurface] Running Loop=1
2019-05-24T17:27:00.186Z,1558718820.186 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-24T17:27:00.186Z,1558718820.186 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-24T17:27:00.187Z,1558718820.187 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-24T17:27:00.187Z,1558718820.187 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-24T17:27:00.187Z,1558718820.187 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-24T17:27:00.188Z,1558718820.188 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-24T17:27:00.188Z,1558718820.188 [Default:A.Wait] Running Loop=1
2019-05-24T17:27:00.188Z,1558718820.188 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-24T17:27:00.634Z,1558718820.634 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-05-24T17:27:08.560Z,1558718828.560 [DataOverHttps](INFO): Sending 101 bytes from file Logs/20190524T172306/Courier0000.lzma
2019-05-24T17:27:09.366Z,1558718829.366 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Courier0000.lzma.bak
2019-05-24T17:27:09.366Z,1558718829.366 [DataOverHttps](INFO): SBD MOMSN=11179788
2019-05-24T17:27:13.557Z,1558718833.557 [Default:A.Wait](INFO): Done Waiting.
2019-05-24T17:27:13.557Z,1558718833.557 [Default:A.Wait] Stopped
2019-05-24T17:27:13.557Z,1558718833.557 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-24T17:27:13.912Z,1558718833.912 [Default:CheckIn] Running Loop=1
2019-05-24T17:27:13.912Z,1558718833.912 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-24T17:27:13.912Z,1558718833.912 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-24T17:27:14.319Z,1558718834.319 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-24T17:27:17.967Z,1558718837.967 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-24T17:27:17.967Z,1558718837.967 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-05-24T17:27:17.967Z,1558718837.967 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:27:17.990Z,1558718837.990 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:27:18.354Z,1558718838.354 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:27:18.354Z,1558718838.354 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-05-24T17:28:58.123Z,1558718938.123 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-24T17:28:58.929Z,1558718938.929 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:02.965Z,1558718942.965 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:05.801Z,1558718945.801 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:09.029Z,1558718949.029 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:11.857Z,1558718951.857 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:14.685Z,1558718954.685 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:16.701Z,1558718956.701 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:18.794Z,1558718958.794 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-24T17:29:18.795Z,1558718958.795 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-05-24T17:29:18.795Z,1558718958.795 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:29:18.805Z,1558718958.805 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:29:19.162Z,1558718959.162 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:29:19.162Z,1558718959.162 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-05-24T17:29:19.937Z,1558718959.937 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:22.765Z,1558718962.765 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:25.997Z,1558718965.997 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:27.198Z,1558718967.198 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:29:27.198Z,1558718967.198 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:29:27.198Z,1558718967.198 [DVL_micro](ERROR): Data Fault
2019-05-24T17:29:27.251Z,1558718967.251 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:29:27.673Z,1558718967.673 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:29:28.436Z,1558718968.436 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:29:28.436Z,1558718968.436 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:29:28.817Z,1558718968.817 [DVL_micro](INFO): Initializing
2019-05-24T17:29:28.833Z,1558718968.833 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:32.061Z,1558718972.061 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:32.537Z,1558718972.537 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-05-24T17:29:34.885Z,1558718974.885 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:38.117Z,1558718978.117 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:40.945Z,1558718980.945 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:42.187Z,1558718982.187 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:29:42.187Z,1558718982.187 [AHRS_M2] No Fault, FailCount= 5
2019-05-24T17:29:42.541Z,1558718982.541 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:29:43.773Z,1558718983.773 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:45.869Z,1558718985.869 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:46.273Z,1558718986.273 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:46.685Z,1558718986.685 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:47.085Z,1558718987.085 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:47.109Z,1558718987.109 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:47.493Z,1558718987.493 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:47.889Z,1558718987.889 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:48.297Z,1558718988.297 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:48.697Z,1558718988.697 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:49.101Z,1558718989.101 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:49.509Z,1558718989.509 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:49.909Z,1558718989.909 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:49.933Z,1558718989.933 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:50.313Z,1558718990.313 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:50.722Z,1558718990.722 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:51.121Z,1558718991.121 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:51.525Z,1558718991.525 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:51.929Z,1558718991.929 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:52.337Z,1558718992.337 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:52.737Z,1558718992.737 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:52.761Z,1558718992.761 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:53.141Z,1558718993.141 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:53.549Z,1558718993.549 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:53.953Z,1558718993.953 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:54.357Z,1558718994.357 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:54.761Z,1558718994.761 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:54.809Z,1558718994.809 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:55.153Z,1558718995.153 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:55.569Z,1558718995.569 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:29:55.569Z,1558718995.569 [AHRS_M2](FAULT): Failed to initialize within timeout.
2019-05-24T17:29:55.569Z,1558718995.569 [AHRS_M2] Communications Fault, FailCount= 1
2019-05-24T17:29:55.569Z,1558718995.569 [AHRS_M2](ERROR): Communications Fault
2019-05-24T17:29:55.663Z,1558718995.663 [CBIT](ERROR): Communications Fault in component: AHRS_M2
2019-05-24T17:29:55.873Z,1558718995.873 [AHRS_M2](INFO): Powering down
2019-05-24T17:29:56.701Z,1558718996.701 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:29:56.735Z,1558718996.735 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:29:56.735Z,1558718996.735 [AHRS_M2] No Fault, FailCount= 1
2019-05-24T17:29:57.085Z,1558718997.085 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:29:59.125Z,1558718999.125 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:00.417Z,1558719000.417 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:30:00.813Z,1558719000.813 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:30:01.198Z,1558719001.198 [AHRS_M2](ERROR): Start data-stream UART error: serial buffer full
2019-05-24T17:30:01.756Z,1558719001.756 [AHRS_M2](ERROR): Start data-stream UART error: serial buffer full
2019-05-24T17:30:02.014Z,1558719002.014 [AHRS_M2](ERROR): Start data-stream UART error: serial buffer full
2019-05-24T17:30:02.041Z,1558719002.041 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:02.417Z,1558719002.417 [AHRS_M2](ERROR): Start data-stream UART error: serial buffer full
2019-05-24T17:30:03.154Z,1558719003.154 [AHRS_M2](ERROR): Read RFS packet UART error: serial buffer full
2019-05-24T17:30:04.794Z,1558719004.794 [AHRS_M2](ERROR): Read RFS packet UART error: serial buffer full
2019-05-24T17:30:04.926Z,1558719004.926 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:05.175Z,1558719005.175 [AHRS_M2](ERROR): Read RFS packet UART error: serial buffer full
2019-05-24T17:30:05.982Z,1558719005.982 [AHRS_M2](ERROR): Read RFS packet UART error: serial buffer full
2019-05-24T17:30:08.097Z,1558719008.097 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:10.945Z,1558719010.945 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:11.804Z,1558719011.804 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-05-24T17:30:12.857Z,1558719012.857 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:30:12.857Z,1558719012.857 [AHRS_M2] Data Fault, FailCount= 2
2019-05-24T17:30:12.857Z,1558719012.857 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:30:12.991Z,1558719012.991 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:30:13.249Z,1558719013.249 [AHRS_M2](INFO): Powering down
2019-05-24T17:30:14.089Z,1558719014.089 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:14.139Z,1558719014.139 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:30:14.139Z,1558719014.139 [AHRS_M2] No Fault, FailCount= 2
2019-05-24T17:30:14.468Z,1558719014.468 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:30:16.901Z,1558719016.901 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:17.785Z,1558719017.785 [AHRS_M2](ERROR): Start data-stream UART error: serial timeout
2019-05-24T17:30:20.153Z,1558719020.153 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:23.053Z,1558719023.053 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:25.810Z,1558719025.810 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:28.213Z,1558719028.213 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:30:28.213Z,1558719028.213 [AHRS_M2] Data Fault, FailCount= 3
2019-05-24T17:30:28.213Z,1558719028.213 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:30:28.253Z,1558719028.253 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:30:28.597Z,1558719028.597 [AHRS_M2](INFO): Powering down
2019-05-24T17:30:29.021Z,1558719029.021 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:29.464Z,1558719029.464 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:30:29.464Z,1558719029.464 [AHRS_M2] No Fault, FailCount= 3
2019-05-24T17:30:29.813Z,1558719029.813 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:30:31.849Z,1558719031.849 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:35.101Z,1558719035.101 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:37.929Z,1558719037.929 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:41.153Z,1558719041.153 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:43.153Z,1558719043.153 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:30:43.153Z,1558719043.153 [AHRS_M2] Data Fault, FailCount= 4
2019-05-24T17:30:43.153Z,1558719043.153 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:30:43.243Z,1558719043.243 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:30:43.553Z,1558719043.553 [AHRS_M2](INFO): Powering down
2019-05-24T17:30:43.973Z,1558719043.973 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:44.411Z,1558719044.411 [CBIT](INFO): Clearing failed state for component AHRS_M2
2019-05-24T17:30:44.411Z,1558719044.411 [AHRS_M2] No Fault, FailCount= 4
2019-05-24T17:30:44.757Z,1558719044.757 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:30:47.201Z,1558719047.201 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:49.666Z,1558719049.666 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-05-24T17:30:49.667Z,1558719049.667 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-05-24T17:30:49.668Z,1558719049.668 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-05-24T17:30:49.671Z,1558719049.671 [BPC1](INFO): Received data from all battery sticks.
2019-05-24T17:30:50.061Z,1558719050.061 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:52.885Z,1558719052.885 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:54.897Z,1558719054.897 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:58.101Z,1558719058.101 [AHRS_M2](FAULT): Failed to acquire valid data within timeout.
2019-05-24T17:30:58.101Z,1558719058.101 [AHRS_M2] Data Fault, FailCount= 5
2019-05-24T17:30:58.101Z,1558719058.101 [AHRS_M2](ERROR): Data Fault
2019-05-24T17:30:58.125Z,1558719058.125 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:30:58.159Z,1558719058.159 [CBIT](ERROR): Data Fault in component: AHRS_M2
2019-05-24T17:30:58.159Z,1558719058.159 [CBIT](CRITICAL): Data Fault in component: AHRS_M2
2019-05-24T17:30:58.497Z,1558719058.497 [AHRS_M2](INFO): Powering down
2019-05-24T17:30:58.636Z,1558719058.636 [CBIT](INFO): Critical error at 20190524T173058
2019-05-24T17:31:00.937Z,1558719060.937 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:04.169Z,1558719064.169 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:06.997Z,1558719066.997 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:10.229Z,1558719070.229 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:13.057Z,1558719073.057 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:15.909Z,1558719075.909 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:17.905Z,1558719077.905 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:19.940Z,1558719079.940 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-24T17:31:19.940Z,1558719079.940 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-05-24T17:31:19.940Z,1558719079.940 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:31:19.951Z,1558719079.951 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:31:20.358Z,1558719080.358 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:31:20.358Z,1558719080.358 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-05-24T17:31:21.137Z,1558719081.137 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:23.965Z,1558719083.965 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:27.197Z,1558719087.197 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:30.025Z,1558719090.025 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:33.257Z,1558719093.257 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:36.085Z,1558719096.085 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:38.913Z,1558719098.913 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:40.941Z,1558719100.941 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:42.953Z,1558719102.953 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:44.973Z,1558719104.973 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:46.103Z,1558719106.103 [CommandLine](IMPORTANT): got command get platform_orientation degree
2019-05-24T17:31:46.103Z,1558719106.103 [CommandLine](FAULT): Element has no value
2019-05-24T17:31:48.205Z,1558719108.205 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:51.049Z,1558719111.049 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:54.281Z,1558719114.281 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:31:57.093Z,1558719117.093 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:00.325Z,1558719120.325 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:03.153Z,1558719123.153 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:05.985Z,1558719125.985 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:08.001Z,1558719128.001 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:11.233Z,1558719131.233 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:14.061Z,1558719134.061 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:14.086Z,1558719134.086 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-24T17:27:13.9Z
2019-05-24T17:32:14.086Z,1558719134.086 [Default:CheckIn:Read_GPS] Stopped
2019-05-24T17:32:14.086Z,1558719134.086 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-24T17:32:14.490Z,1558719134.490 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-24T17:32:17.349Z,1558719137.349 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:18.949Z,1558719138.949 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20190524T172306/Courier0004.lzma
2019-05-24T17:32:19.763Z,1558719139.763 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Courier0004.lzma.bak
2019-05-24T17:32:19.763Z,1558719139.763 [DataOverHttps](INFO): SBD MOMSN=11179817
2019-05-24T17:32:20.221Z,1558719140.221 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:23.001Z,1558719143.001 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:25.021Z,1558719145.021 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:28.253Z,1558719148.253 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:31.081Z,1558719151.081 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:33.086Z,1558719153.086 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:32:33.086Z,1558719153.086 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:32:33.086Z,1558719153.086 [DVL_micro](ERROR): Data Fault
2019-05-24T17:32:33.158Z,1558719153.158 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:32:33.557Z,1558719153.557 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:32:34.313Z,1558719154.313 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:34.368Z,1558719154.368 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:32:34.368Z,1558719154.368 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:32:34.710Z,1558719154.710 [DVL_micro](INFO): Initializing
2019-05-24T17:32:37.141Z,1558719157.141 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:40.373Z,1558719160.373 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:43.201Z,1558719163.201 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:46.025Z,1558719166.025 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:48.049Z,1558719168.049 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:50.077Z,1558719170.077 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:50.833Z,1558719170.833 [DataOverHttps](INFO): Sending 269 bytes from file Logs/20190522T162804/Express0625.lzma
2019-05-24T17:32:51.639Z,1558719171.639 [DataOverHttps](INFO): Moved sent file to Logs/20190522T162804/Express0625.lzma.bak
2019-05-24T17:32:51.639Z,1558719171.639 [DataOverHttps](INFO): SBD MOMSN=11179823
2019-05-24T17:32:53.305Z,1558719173.305 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:55.541Z,1558719175.541 [CommandLine](IMPORTANT): got command failComponent
2019-05-24T17:32:55.542Z,1558719175.542 [CommandLine](IMPORTANT): Failed components:
2019-05-24T17:32:55.542Z,1558719175.542 [CommandLine](IMPORTANT): AHRS_M2: Data Fault
2019-05-24T17:32:56.129Z,1558719176.129 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:59.361Z,1558719179.361 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:32:59.699Z,1558719179.699 [CommandLine](IMPORTANT): got command failComponent none AHRS_M2
2019-05-24T17:32:59.699Z,1558719179.699 [AHRS_M2] No Fault, FailCount= 5
2019-05-24T17:32:59.699Z,1558719179.699 [CommandLine](IMPORTANT): AHRS_M2 failureMode is No Fault
2019-05-24T17:32:59.762Z,1558719179.761 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-24T17:33:01.697Z,1558719181.697 [CommandLine](IMPORTANT): got command failComponent
2019-05-24T17:33:01.698Z,1558719181.698 [CommandLine](IMPORTANT): Failed components:
2019-05-24T17:33:01.698Z,1558719181.698 [CommandLine](IMPORTANT): No failed Components.
2019-05-24T17:33:02.205Z,1558719182.205 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:04.208Z,1558719184.208 [AHRS_M2](INFO): Failure count cleared after critical for AHRS_M2
2019-05-24T17:33:05.041Z,1558719185.041 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:07.073Z,1558719187.073 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:09.077Z,1558719189.077 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:09.174Z,1558719189.174 [DataOverHttps](INFO): Sending 1280 bytes from file Logs/20190524T172108/Express0001.lzma
2019-05-24T17:33:09.978Z,1558719189.978 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172108/Express0001.lzma.bak
2019-05-24T17:33:09.978Z,1558719189.978 [DataOverHttps](INFO): SBD MOMSN=11179838
2019-05-24T17:33:11.113Z,1558719191.113 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:14.329Z,1558719194.329 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:17.157Z,1558719197.157 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:20.397Z,1558719200.397 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:23.253Z,1558719203.253 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:24.866Z,1558719204.866 [DataOverHttps](INFO): Sending 1236 bytes from file Logs/20190524T172306/Express0001.lzma
2019-05-24T17:33:25.670Z,1558719205.670 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Express0001.lzma.bak
2019-05-24T17:33:25.670Z,1558719205.670 [DataOverHttps](INFO): SBD MOMSN=11179886
2019-05-24T17:33:26.477Z,1558719206.477 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:29.277Z,1558719209.277 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:32.117Z,1558719212.117 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:35.337Z,1558719215.337 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:38.169Z,1558719218.169 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:41.397Z,1558719221.397 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:44.225Z,1558719224.225 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:47.457Z,1558719227.457 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:48.990Z,1558719228.990 [DataOverHttps](INFO): Sending 409 bytes from file Logs/20190524T172306/Express0005.lzma
2019-05-24T17:33:49.794Z,1558719229.794 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Express0005.lzma.bak
2019-05-24T17:33:49.794Z,1558719229.794 [DataOverHttps](INFO): SBD MOMSN=11179930
2019-05-24T17:33:50.301Z,1558719230.301 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:53.113Z,1558719233.113 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:53.562Z,1558719233.562 [Default:CheckIn:Read_Iridium] Stopped
2019-05-24T17:33:53.562Z,1558719233.562 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-24T17:33:53.562Z,1558719233.562 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-24T17:33:55.133Z,1558719235.133 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:33:57.135Z,1558719237.135 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-24T17:33:57.135Z,1558719237.135 [NAL9602] Data Fault, FailCount= 1
2019-05-24T17:33:57.135Z,1558719237.135 [NAL9602](ERROR): Data Fault
2019-05-24T17:33:57.199Z,1558719237.199 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-24T17:33:57.543Z,1558719237.543 [NAL9602](INFO): Powering down
2019-05-24T17:33:58.414Z,1558719238.414 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-24T17:33:58.414Z,1558719238.414 [NAL9602] No Fault, FailCount= 1
2019-05-24T17:34:21.005Z,1558719261.005 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-05-24T17:34:21.005Z,1558719261.005 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:34:21.015Z,1558719261.015 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:34:21.479Z,1558719261.479 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:34:21.479Z,1558719261.479 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-05-24T17:34:27.858Z,1558719267.858 [NAL9602](INFO): Powering up NAL9602
2019-05-24T17:34:38.751Z,1558719278.751 [NAL9602](INFO): NAL9602 initialized
2019-05-24T17:34:39.573Z,1558719279.573 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:41.997Z,1558719281.997 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:45.233Z,1558719285.233 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:48.053Z,1558719288.053 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:50.897Z,1558719290.897 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:52.929Z,1558719292.929 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:56.153Z,1558719296.153 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:58.961Z,1558719298.961 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:34:59.767Z,1558719299.767 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.799999 degree
2019-05-24T17:34:59.768Z,1558719299.768 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2019-05-24T17:34:59.769Z,1558719299.769 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.900002 degree
2019-05-24T17:34:59.770Z,1558719299.770 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2019-05-24T17:34:59.817Z,1558719299.817 [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,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,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-05-24T17:35:00.204Z,1558719300.204 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:00.205Z,1558719300.205 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-05-24T17:35:00.205Z,1558719300.205 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:00.215Z,1558719300.215 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:00.605Z,1558719300.605 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:00.605Z,1558719300.605 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-05-24T17:35:01.413Z,1558719301.413 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:01.413Z,1558719301.413 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2019-05-24T17:35:01.413Z,1558719301.413 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:01.424Z,1558719301.424 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:01.836Z,1558719301.836 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:01.845Z,1558719301.845 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2019-05-24T17:35:02.197Z,1558719302.197 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:35:02.666Z,1558719302.666 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:02.666Z,1558719302.666 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2019-05-24T17:35:02.666Z,1558719302.666 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:02.689Z,1558719302.689 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:03.039Z,1558719303.039 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:03.039Z,1558719303.039 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2019-05-24T17:35:03.850Z,1558719303.850 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:03.850Z,1558719303.850 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2019-05-24T17:35:03.850Z,1558719303.850 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:03.868Z,1558719303.868 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:04.263Z,1558719304.263 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:04.263Z,1558719304.263 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2019-05-24T17:35:05.046Z,1558719305.046 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:35:05.078Z,1558719305.078 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:05.078Z,1558719305.078 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2019-05-24T17:35:05.078Z,1558719305.078 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:05.097Z,1558719305.097 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:05.476Z,1558719305.476 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:05.477Z,1558719305.477 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2019-05-24T17:35:06.244Z,1558719306.244 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:06.244Z,1558719306.244 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2019-05-24T17:35:06.244Z,1558719306.244 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:06.254Z,1558719306.254 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:06.727Z,1558719306.727 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:06.727Z,1558719306.727 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2019-05-24T17:35:07.474Z,1558719307.474 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:07.474Z,1558719307.474 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2019-05-24T17:35:07.474Z,1558719307.474 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:07.488Z,1558719307.488 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:07.903Z,1558719307.903 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:07.903Z,1558719307.903 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2019-05-24T17:35:08.249Z,1558719308.249 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:35:08.694Z,1558719308.694 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:08.694Z,1558719308.694 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2019-05-24T17:35:08.694Z,1558719308.694 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:08.712Z,1558719308.712 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:09.129Z,1558719309.129 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:09.130Z,1558719309.130 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2019-05-24T17:35:09.898Z,1558719309.898 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:09.898Z,1558719309.898 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14
2019-05-24T17:35:09.898Z,1558719309.898 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:09.908Z,1558719309.908 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:10.303Z,1558719310.303 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:10.303Z,1558719310.303 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14
2019-05-24T17:35:11.097Z,1558719311.097 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:35:11.122Z,1558719311.122 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:11.122Z,1558719311.122 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15
2019-05-24T17:35:11.122Z,1558719311.122 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:11.134Z,1558719311.134 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:11.534Z,1558719311.534 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:11.535Z,1558719311.535 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15
2019-05-24T17:35:12.304Z,1558719312.304 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-05-24T17:35:12.304Z,1558719312.304 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16
2019-05-24T17:35:12.304Z,1558719312.304 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-24T17:35:12.315Z,1558719312.315 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:12.723Z,1558719312.723 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-24T17:35:12.723Z,1558719312.723 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16
2019-05-24T17:35:13.403Z,1558719313.403 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 155871936512.000000 second
2019-05-24T17:35:13.917Z,1558719313.917 [NAL9602](DEBUG): Fix Requested
2019-05-24T17:35:15.446Z,1558719315.446 [CommandLine](IMPORTANT): got command get latitude
2019-05-24T17:35:15.446Z,1558719315.446 [CommandLine](IMPORTANT): latitude 36.799999 arcdeg
2019-05-24T17:35:38.834Z,1558719338.834 [DataOverHttps](IMPORTANT): SBD MTMSN=20190524T172920
2019-05-24T17:35:38.952Z,1558719338.952 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:35:38.952Z,1558719338.952 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:35:38.952Z,1558719338.952 [DVL_micro](ERROR): Data Fault
2019-05-24T17:35:39.013Z,1558719339.013 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:35:39.417Z,1558719339.417 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:35:40.198Z,1558719340.198 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:35:40.198Z,1558719340.198 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:35:40.570Z,1558719340.570 [DVL_micro](INFO): Initializing
2019-05-24T17:35:45.818Z,1558719345.818 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-24T17:35:47.657Z,1558719347.657 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 3 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 3 meter;run 
2019-05-24T17:35:47.673Z,1558719347.673 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-05-24T17:35:47.673Z,1558719347.673 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-24T17:35:47.698Z,1558719347.698 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-24T17:35:47.701Z,1558719347.701 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-24T17:35:47.704Z,1558719347.704 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-24T17:35:47.707Z,1558719347.707 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-24T17:35:47.708Z,1558719347.708 [sample:A.AbortSample](DEBUG): Construct.
2019-05-24T17:35:47.710Z,1558719347.710 [sample:B.Pitch](DEBUG): Construct.
2019-05-24T17:35:47.747Z,1558719347.747 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-24T17:35:47.750Z,1558719347.750 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-24T17:35:47.924Z,1558719347.924 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-24T17:35:47.932Z,1558719347.932 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-24T17:35:47.943Z,1558719347.943 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-24T17:35:47.947Z,1558719347.947 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-24T17:35:47.963Z,1558719347.963 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-24T17:35:47.971Z,1558719347.971 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-24T17:35:47.974Z,1558719347.974 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-24T17:35:47.985Z,1558719347.985 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-24T17:35:47.993Z,1558719347.993 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 134.999995 cc
2019-05-24T17:35:48.005Z,1558719348.005 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-24T17:35:48.014Z,1558719348.014 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-24T17:35:48.021Z,1558719348.021 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-24T17:35:48.037Z,1558719348.037 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-24T17:35:48.058Z,1558719348.058 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-24T17:35:48.060Z,1558719348.060 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-05-24T17:35:48.060Z,1558719348.060 [MissionManager](ERROR): Slate does not contain celsius
2019-05-24T17:35:48.074Z,1558719348.074 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-24T17:35:48.083Z,1558719348.083 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-05-24T17:35:48.083Z,1558719348.083 [MissionManager](ERROR): Slate does not contain celsius
2019-05-24T17:35:48.116Z,1558719348.116 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         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/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

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

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-05-24T17:35:48.116Z,1558719348.116 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-05-24T17:35:53.755Z,1558719353.755 [CommandLine](IMPORTANT): got command set sample.Depth 3.000000 meter
2019-05-24T17:35:53.756Z,1558719353.756 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2019-05-24T17:35:53.757Z,1558719353.757 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 3.000000 meter
2019-05-24T17:35:53.758Z,1558719353.758 [CommandLine](IMPORTANT): got command run 
2019-05-24T17:35:53.760Z,1558719353.760 [CommandLine](IMPORTANT): Running 
2019-05-24T17:35:53.939Z,1558719353.939 [Default] Stopped
2019-05-24T17:35:53.939Z,1558719353.939 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-24T17:35:53.939Z,1558719353.939 [Default:B.GoToSurface] Stopped
2019-05-24T17:35:53.939Z,1558719353.939 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-24T17:35:53.939Z,1558719353.939 [Default:CheckIn] Stopped
2019-05-24T17:35:53.939Z,1558719353.939 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-24T17:35:53.939Z,1558719353.939 [Default:CheckIn:C.Wait] Stopped
2019-05-24T17:35:53.939Z,1558719353.939 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-24T17:35:53.939Z,1558719353.939 [MissionManager](IMPORTANT): Started mission sample
2019-05-24T17:35:53.940Z,1558719353.940 [sample] Running Loop=1
2019-05-24T17:35:53.940Z,1558719353.940 [sample](DEBUG): Aggregate::initialize sample
2019-05-24T17:35:53.940Z,1558719353.940 [sample:A.AbortSample] Running Loop=1
2019-05-24T17:35:53.940Z,1558719353.940 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-24T17:35:53.940Z,1558719353.940 [sample:B.Pitch] Running Loop=1
2019-05-24T17:35:53.940Z,1558719353.940 [sample:B.Pitch](DEBUG): Initialize.
2019-05-24T17:35:53.941Z,1558719353.941 [sample:C.SetSpeed] Running Loop=1
2019-05-24T17:35:53.941Z,1558719353.941 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-24T17:35:53.941Z,1558719353.941 [sample:E] Running Loop=1
2019-05-24T17:35:53.941Z,1558719353.941 [sample:E] Stopped
2019-05-24T17:35:53.942Z,1558719353.942 [sample:F] Running Loop=1
2019-05-24T17:35:53.942Z,1558719353.942 [sample:C.SetSpeed] Running Loop=1
2019-05-24T17:35:53.942Z,1558719353.942 [sample:B.Pitch] Running Loop=1
2019-05-24T17:35:53.942Z,1558719353.942 [sample:A.AbortSample] Running Loop=1
2019-05-24T17:35:54.337Z,1558719354.337 [sample:F] Stopped
2019-05-24T17:35:54.337Z,1558719354.337 [sample:SampleRepeater] Running Loop=1
2019-05-24T17:35:54.337Z,1558719354.337 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-24T17:35:54.338Z,1558719354.338 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-24T17:35:54.338Z,1558719354.338 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-24T17:35:54.729Z,1558719354.729 [sample:SampleAtDepth] Running Loop=1
2019-05-24T17:35:54.729Z,1558719354.729 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-24T17:35:54.729Z,1558719354.729 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-24T17:35:54.729Z,1558719354.729 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-24T17:35:54.729Z,1558719354.729 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-24T17:35:54.730Z,1558719354.730 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 3.000000 m 
2019-05-24T17:35:54.730Z,1558719354.730 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-24T17:35:54.730Z,1558719354.730 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-24T17:35:54.730Z,1558719354.730 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-24T17:36:04.400Z,1558719364.400 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 3.000000 meter
2019-05-24T17:36:04.401Z,1558719364.401 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-05-24T17:36:04.548Z,1558719364.548 [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,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,Maintain_Depth_Keller.depth,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-05-24T17:36:04.837Z,1558719364.837 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-24T17:36:04.837Z,1558719364.837 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-05-24T17:36:04.838Z,1558719364.838 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-24T17:36:04.838Z,1558719364.838 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-24T17:36:04.838Z,1558719364.838 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-05-24T17:36:04.838Z,1558719364.838 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-05-24T17:36:04.838Z,1558719364.838 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-24T17:36:04.838Z,1558719364.838 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-05-24T17:36:04.838Z,1558719364.838 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-05-24T17:36:05.241Z,1558719365.241 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 3.000000 m , settling for 0.050000 min 
2019-05-24T17:36:05.241Z,1558719365.241 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-05-24T17:36:05.242Z,1558719365.242 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-05-24T17:36:05.242Z,1558719365.242 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-05-24T17:36:05.242Z,1558719365.242 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-24T17:36:08.880Z,1558719368.880 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-05-24T17:36:08.880Z,1558719368.880 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-05-24T17:36:08.880Z,1558719368.880 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-24T17:36:08.880Z,1558719368.880 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-05-24T17:36:08.881Z,1558719368.881 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-24T17:36:08.881Z,1558719368.881 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-05-24T17:36:08.881Z,1558719368.881 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-05-24T17:36:08.881Z,1558719368.881 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-05-24T17:36:09.277Z,1558719369.277 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-05-24T17:36:09.277Z,1558719369.277 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-24T17:36:09.277Z,1558719369.277 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-05-24T17:36:09.277Z,1558719369.277 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-05-24T17:36:09.277Z,1558719369.277 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-05-24T17:36:09.277Z,1558719369.277 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-05-24T17:36:09.277Z,1558719369.277 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-24T17:36:09.278Z,1558719369.278 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-05-24T17:36:09.708Z,1558719369.708 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-05-24T17:36:10.447Z,1558719370.447 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::'
2019-05-24T17:36:10.493Z,1558719370.493 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::"
2019-05-24T17:36:10.851Z,1558719370.851 [ESPComponent](INFO): powering up ESP
2019-05-24T17:36:10.851Z,1558719370.851 [ESPComponent](INFO): powering up ESP secondary power supply
2019-05-24T17:36:10.869Z,1558719370.869 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.5.2:10.89.5.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2019-05-24T17:36:11.008Z,1558719371.008 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-05-24T17:36:11.325Z,1558719371.325 [ESPComponent](INFO): console:
2019-05-24T17:36:12.061Z,1558719372.061 [ESPComponent](INFO): console:

2019-05-24T17:36:12.467Z,1558719372.467 [ESPComponent](INFO): console:NAND:  256 MiB
2019-05-24T17:36:12.880Z,1558719372.880 [ESPComponent](INFO): console:
BOOTMODE: SDMMC
2019-05-24T17:36:13.275Z,1558719373.275 [ESPComponent](INFO): console:

2019-05-24T17:36:13.678Z,1558719373.678 [ESPComponent](INFO): console:

2019-05-24T17:36:14.092Z,1558719374.092 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariC (Apr 02 2019 - 18:00:17)
2019-05-24T17:36:14.486Z,1558719374.486 [ESPComponent](INFO): console:

2019-05-24T17:36:14.890Z,1558719374.890 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2019-05-24T17:36:15.295Z,1558719375.295 [ESPComponent](INFO): console:
flash params are already written into flash
2019-05-24T17:36:15.698Z,1558719375.698 [ESPComponent](INFO): console:
DRAM:  64 MB
2019-05-24T17:36:16.102Z,1558719376.102 [ESPComponent](INFO): console:
In:    serial
2019-05-24T17:36:16.506Z,1558719376.506 [ESPComponent](INFO): console:
Out:   serial
2019-05-24T17:36:16.919Z,1558719376.919 [ESPComponent](INFO): console:
Err:   serial
2019-05-24T17:36:17.314Z,1558719377.314 [ESPComponent](INFO): console:
Net:   ks8851_mll
2019-05-24T17:36:17.718Z,1558719377.718 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2019-05-24T17:36:18.122Z,1558719378.122 [ESPComponent](INFO): console:
mmc1 is available
2019-05-24T17:36:18.526Z,1558719378.526 [ESPComponent](INFO): console:
reading uImage
2019-05-24T17:36:18.930Z,1558719378.930 [ESPComponent](INFO): console:

2019-05-24T17:36:19.335Z,1558719379.335 [ESPComponent](INFO): console:
1681452 bytes read
2019-05-24T17:36:19.738Z,1558719379.738 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2019-05-24T17:36:20.142Z,1558719380.142 [ESPComponent](INFO): console:
   Image Name:   Linux-2.6.33-ea3131-mbari6
2019-05-24T17:36:20.547Z,1558719380.547 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2019-05-24T17:36:20.950Z,1558719380.950 [ESPComponent](INFO): console:
   Data Size:    1681388 Bytes =  1.6 MB
2019-05-24T17:36:21.354Z,1558719381.354 [ESPComponent](INFO): console:
   Load Address: 30008000
2019-05-24T17:36:21.758Z,1558719381.758 [ESPComponent](INFO): console:
   Entry Point:  30008000
2019-05-24T17:36:22.163Z,1558719382.163 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2019-05-24T17:36:22.566Z,1558719382.566 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2019-05-24T17:36:22.970Z,1558719382.970 [ESPComponent](INFO): console:
OK
2019-05-24T17:36:23.374Z,1558719383.374 [ESPComponent](INFO): console:

2019-05-24T17:36:23.779Z,1558719383.779 [ESPComponent](INFO): console:
Starting kernel ...
2019-05-24T17:36:24.182Z,1558719384.182 [ESPComponent](INFO): console:

2019-05-24T17:36:24.587Z,1558719384.587 [ESPComponent](INFO): console:
Uncompressing Linux... dting the kernel.
2019-05-24T17:36:24.991Z,1558719384.991 [ESPComponent](INFO): console:
[    0.00] CPU: ARM926EJ-S [41069265] revisRMv5TEJ), cr=00053177
2019-05-24T17:36:25.394Z,1558719385.394 [ESPComponent](INFO): console:
[    0.00] CPU: VIVT he, VIVT instruction cache
2019-05-24T17:36:25.798Z,1558719385.798 [ESPComponent](INFO): console:
0] Machine: NXP EA313X
2019-05-24T17:36:26.203Z,1558719386.203 [ESPComponent](INFO): console:
[    0.0y policy: ECC disabled, Data cache writeback
2019-05-24T17:36:26.607Z,1558719386.607 [ESPComponent](INFO): console:
[    0.00] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
2019-05-24T17:36:27.011Z,1558719387.011 [ESPComponent](INFO): console:
[    0.24] Mount-cache hash table entries: 512
2019-05-24T17:36:27.415Z,1558719387.415 [ESPComponent](INFO): console:
[    0.29] MBARI ESP 3G
2019-05-24T17:36:27.818Z,1558719387.818 [ESPComponent](INFO): console:
[    0.39] bio: create slab <bio-0> at 0
2019-05-24T17:36:28.223Z,1558719388.223 [ESPComponent](INFO): console:
[    0.46] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-24T17:36:28.628Z,1558719388.628 [ESPComponent](INFO): console:
[    0.48] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-24T17:36:29.031Z,1558719389.031 [ESPComponent](INFO): console:
[    0.50] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-24T17:36:29.435Z,1558719389.435 [ESPComponent](INFO): console:
[    0.52] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-24T17:36:29.840Z,1558719389.840 [ESPComponent](INFO): console:
[    0.54] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-24T17:36:30.243Z,1558719390.243 [ESPComponent](INFO): console:
[    0.56] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-24T17:36:30.647Z,1558719390.647 [ESPComponent](INFO): console:
[    0.56] NetWinder Floating Point Emulator V0.97 (double precision)
2019-05-24T17:36:31.051Z,1558719391.051 [ESPComponent](INFO): console:
[    0.58] yaffs Dec 14 2018 09:19:05 Installing. 
2019-05-24T17:36:31.454Z,1558719391.454 [ESPComponent](INFO): console:
[    0.72] m25p80 spi0.3: m25p80 found s25sl032a flash
2019-05-24T17:36:31.859Z,1558719391.859 [ESPComponent](INFO): console:
[    2.29] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
2019-05-24T17:36:32.262Z,1558719392.262 [ESPComponent](INFO): console:

2019-05-24T17:36:32.299Z,1558719392.299 [DVL_micro](ERROR): only read 45 of 46 data items
2019-05-24T17:36:32.300Z,1558719392.300 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 467 581 282 380 2 3 2 2 246 461.0 2 308.5 -194.4 461.0 2 246 268 461 2 308 -194 461 2 -62 280.4 -3.0 20.6 0.005 35.0 1489 65
2019-05-24T17:36:32.666Z,1558719392.666 [ESPComponent](INFO): console:INIT: version 2.85 booting
2019-05-24T17:36:33.070Z,1558719393.070 [ESPComponent](INFO): console:

2019-05-24T17:36:33.475Z,1558719393.475 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-05-24T17:36:33.878Z,1558719393.878 [ESPComponent](INFO): console:
ESPkoa
2019-05-24T17:36:34.282Z,1558719394.282 [ESPComponent](INFO): console:

2019-05-24T17:36:34.686Z,1558719394.686 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2019-05-24T17:36:35.090Z,1558719395.090 [ESPComponent](INFO): console:

2019-05-24T17:36:35.494Z,1558719395.494 [ESPComponent](INFO): console:Loading kernel modules
2019-05-24T17:36:35.899Z,1558719395.899 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2019-05-24T17:36:36.302Z,1558719396.302 [ESPComponent](INFO): console:
Starting hotplug events dispatcher udevd
2019-05-24T17:36:36.706Z,1558719396.706 [ESPComponent](INFO): console:
Set system clock to:  Fri May 24 10:30:09 PDT 2019
2019-05-24T17:36:37.110Z,1558719397.110 [ESPComponent](INFO): console:
Starting syslogd klogd...
2019-05-24T17:36:37.514Z,1558719397.514 [ESPComponent](INFO): console:
Bringing up interface lo ...
2019-05-24T17:36:37.918Z,1558719397.918 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2019-05-24T17:36:38.322Z,1558719398.322 [ESPComponent](INFO): console:
Packet forwarding enabled
2019-05-24T17:36:38.726Z,1558719398.726 [ESPComponent](INFO): console:
Bringing up interface ppp2 ...
2019-05-24T17:36:39.130Z,1558719399.130 [ESPComponent](INFO): console:
Starting portmap...
2019-05-24T17:36:39.534Z,1558719399.534 [ESPComponent](INFO): console:
Bringing up interface eth0 ...
2019-05-24T17:36:39.938Z,1558719399.938 [ESPComponent](INFO): console:
Network unavailable:  Local time is Fri May 24 10:30:11 PDT 2019
2019-05-24T17:36:40.342Z,1558719400.342 [ESPComponent](INFO): console:
Starting thttpd...
2019-05-24T17:36:40.747Z,1558719400.747 [ESPComponent](INFO): console:
Determining IP configuration for eth0....udhcpc (v1.11.2) started
2019-05-24T17:36:41.150Z,1558719401.150 [ESPComponent](INFO): console:
Sending discover...
2019-05-24T17:36:41.553Z,1558719401.553 [ESPComponent](INFO): console:

2019-05-24T17:36:41.958Z,1558719401.958 [ESPComponent](INFO): console:

2019-05-24T17:36:42.361Z,1558719402.361 [ESPComponent](IMPORTANT): ESP has connected as client
2019-05-24T17:36:43.230Z,1558719403.230 [ESPComponent](IMPORTANT): [sample #1] Explicit cartridge argument not given
2019-05-24T17:36:43.230Z,1558719403.230 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-05-24T17:36:43.231Z,1558719403.231 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2019-05-24T17:36:43.301Z,1558719403.301 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-05-24T17:36:43.302Z,1558719403.302 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1
2019-05-24T17:36:43.668Z,1558719403.668 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-24T17:36:43.668Z,1558719403.668 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 3.000000 m inwater with nan ug/l chlorophyll fluorescence.
2019-05-24T17:36:43.668Z,1558719403.668 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped
2019-05-24T17:36:43.668Z,1558719403.668 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-05-24T17:36:44.026Z,1558719404.026 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-05-24T17:36:44.382Z,1558719404.382 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2019-05-24T17:36:44.786Z,1558719404.786 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2019-05-24T17:36:46.402Z,1558719406.402 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2019-05-24T17:37:19.126Z,1558719439.126 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@59)
2019-05-24T17:37:20.742Z,1558719440.742 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@0.0)
2019-05-24T17:37:21.550Z,1558719441.550 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@0.0)
2019-05-24T17:37:55.401Z,1558719475.401 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-05-24T17:37:55.749Z,1558719475.749 [Radio_Surface](INFO): Powering down
2019-05-24T17:38:44.788Z,1558719524.788 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:38:44.788Z,1558719524.788 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:38:44.788Z,1558719524.788 [DVL_micro](ERROR): Data Fault
2019-05-24T17:38:44.850Z,1558719524.850 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:38:45.196Z,1558719525.196 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:38:46.074Z,1558719526.074 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:38:46.074Z,1558719526.074 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:38:46.410Z,1558719526.410 [DVL_micro](INFO): Initializing
2019-05-24T17:39:51.838Z,1558719591.838 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2019-05-24T17:39:52.242Z,1558719592.242 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2019-05-24T17:40:54.777Z,1558719654.777 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.183456
2019-05-24T17:41:50.628Z,1558719710.628 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:41:50.628Z,1558719710.628 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:41:50.628Z,1558719710.628 [DVL_micro](ERROR): Data Fault
2019-05-24T17:41:50.663Z,1558719710.663 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:41:51.038Z,1558719711.038 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:41:51.886Z,1558719711.886 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:41:51.886Z,1558719711.886 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:41:52.256Z,1558719712.256 [DVL_micro](INFO): Initializing
2019-05-24T17:44:56.474Z,1558719896.474 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:44:56.474Z,1558719896.474 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:44:56.474Z,1558719896.474 [DVL_micro](ERROR): Data Fault
2019-05-24T17:44:56.508Z,1558719896.508 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:44:56.878Z,1558719896.878 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:44:57.726Z,1558719897.726 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:44:57.727Z,1558719897.727 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:44:58.091Z,1558719898.091 [DVL_micro](INFO): Initializing
2019-05-24T17:48:02.316Z,1558720082.316 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:48:02.316Z,1558720082.316 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:48:02.316Z,1558720082.316 [DVL_micro](ERROR): Data Fault
2019-05-24T17:48:02.351Z,1558720082.351 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:48:02.728Z,1558720082.728 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:48:03.581Z,1558720083.581 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:48:03.581Z,1558720083.581 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:48:03.934Z,1558720083.934 [DVL_micro](INFO): Initializing
2019-05-24T17:51:08.148Z,1558720268.148 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:51:08.148Z,1558720268.148 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:51:08.148Z,1558720268.148 [DVL_micro](ERROR): Data Fault
2019-05-24T17:51:08.183Z,1558720268.183 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:51:08.562Z,1558720268.562 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:51:09.406Z,1558720269.406 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:51:09.406Z,1558720269.406 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:51:09.776Z,1558720269.776 [DVL_micro](INFO): Initializing
2019-05-24T17:54:13.991Z,1558720453.991 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:54:13.991Z,1558720453.991 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:54:13.991Z,1558720453.991 [DVL_micro](ERROR): Data Fault
2019-05-24T17:54:14.025Z,1558720454.025 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:54:14.398Z,1558720454.398 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:54:15.258Z,1558720455.258 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:54:15.259Z,1558720455.259 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:54:15.610Z,1558720455.610 [DVL_micro](INFO): Initializing
2019-05-24T17:57:06.910Z,1558720626.910 [DVL_micro](ERROR): only read 43 of 46 data items
2019-05-24T17:57:06.910Z,1558720626.910 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 458 429 -464 435 2 3 2 2 1230.5 -8.0 231.3 2 216.3 -1211.3 231.3 2 1230 -8 231 2 216 -1211 231 2 -5.56 -1.59 280.5 -3.0 21.4 0.005 35.0 1489 103
2019-05-24T17:57:19.829Z,1558720639.829 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T17:57:19.829Z,1558720639.829 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T17:57:19.830Z,1558720639.830 [DVL_micro](ERROR): Data Fault
2019-05-24T17:57:19.869Z,1558720639.869 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T17:57:20.239Z,1558720640.239 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T17:57:21.102Z,1558720641.102 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T17:57:21.103Z,1558720641.103 [DVL_micro] No Fault, FailCount= 1
2019-05-24T17:57:21.468Z,1558720641.468 [DVL_micro](INFO): Initializing
2019-05-24T17:59:56.597Z,1558720796.597 [DVL_micro](ERROR): only read 44 of 46 data items
2019-05-24T17:59:56.597Z,1558720796.597 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 271 497 -1645 476 2 3 2 2 2557.2 28.0 -108.2 2 493.4 -2509.2 -108.2 2 2557 28 -1082509 -108 2 -5.67 -1.64 280.5 -3.0 21.5 0.005 35.0 1489 84
2019-05-24T18:00:25.669Z,1558720825.669 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:00:25.669Z,1558720825.669 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:00:25.669Z,1558720825.669 [DVL_micro](ERROR): Data Fault
2019-05-24T18:00:25.704Z,1558720825.704 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:00:26.078Z,1558720826.078 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:00:26.930Z,1558720826.930 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:00:26.931Z,1558720826.931 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:00:27.296Z,1558720827.296 [DVL_micro](INFO): Initializing
2019-05-24T18:00:53.163Z,1558720853.163 [DVL_micro](ERROR): only read 45 of 46 data items
2019-05-24T18:00:53.163Z,1558720853.163 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 530 552 -416 543 2 3 2 2 1262.6 12.0 326.0 2 241.8 -1239.2 326.0 2 1262 12 326 239 326 2 -5.61 -1.63 280.5 -3.0 21.5 0.005 35.0 1489 101
2019-05-24T18:03:31.510Z,1558721011.510 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:03:31.510Z,1558721011.510 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:03:31.510Z,1558721011.510 [DVL_micro](ERROR): Data Fault
2019-05-24T18:03:31.545Z,1558721011.545 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:03:31.925Z,1558721011.925 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:03:32.771Z,1558721012.771 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:03:32.771Z,1558721012.771 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:03:33.130Z,1558721013.130 [DVL_micro](INFO): Initializing
2019-05-24T18:06:37.350Z,1558721197.350 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:06:37.350Z,1558721197.350 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:06:37.350Z,1558721197.350 [DVL_micro](ERROR): Data Fault
2019-05-24T18:06:37.384Z,1558721197.384 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:06:37.760Z,1558721197.760 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:06:38.610Z,1558721198.610 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:06:38.610Z,1558721198.610 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:06:38.970Z,1558721198.970 [DVL_micro](INFO): Initializing
2019-05-24T18:08:22.419Z,1558721302.419 [DVL_micro](ERROR): checksum mismatch: reported112 , calculated:105
2019-05-24T18:08:22.419Z,1558721302.419 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 1436 -626 -669 540 2 3 2 2 2809.4 -1556.2 183.6 2 -3045.8 183.6 2 2809 -1556 183 2 -1018 -3045 183 2 -5.63 -1.64 280.5 -3.0 21.7 0.005 35.0 1489 112
2019-05-24T18:09:43.189Z,1558721383.189 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:09:43.189Z,1558721383.189 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:09:43.189Z,1558721383.189 [DVL_micro](ERROR): Data Fault
2019-05-24T18:09:43.224Z,1558721383.224 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:09:43.598Z,1558721383.598 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:09:44.452Z,1558721384.452 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:09:44.452Z,1558721384.452 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:09:44.809Z,1558721384.809 [DVL_micro](INFO): Initializing
2019-05-24T18:10:17.138Z,1558721417.138 [DVL_micro](ERROR): only read 15 of 46 data items
2019-05-24T18:10:17.139Z,1558721417.139 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 622 954 - 2 3 2 2 2966.9 624.6 124.3 2 1154.7 -2803.3 124.3 2 2966 624 124 2 1154 -2803 124 2 -5.58 -1.59 280.5 -3.0 21.7 0.005 35.0 1489 84
2019-05-24T18:10:48.622Z,1558721448.622 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@1000.0)
2019-05-24T18:10:48.622Z,1558721448.622 [ESPComponent](DEBUG): Writing sampleVolume=1000.000000
2019-05-24T18:10:49.026Z,1558721449.026 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@1000.0)
2019-05-24T18:10:51.450Z,1558721451.450 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@59)
2019-05-24T18:12:49.034Z,1558721569.034 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:12:49.034Z,1558721569.034 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:12:49.034Z,1558721569.034 [DVL_micro](ERROR): Data Fault
2019-05-24T18:12:49.100Z,1558721569.100 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:12:49.433Z,1558721569.433 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:12:50.278Z,1558721570.278 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:12:50.279Z,1558721570.279 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:12:50.650Z,1558721570.650 [DVL_micro](INFO): Initializing
2019-05-24T18:15:54.890Z,1558721754.890 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:15:54.890Z,1558721754.890 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:15:54.890Z,1558721754.890 [DVL_micro](ERROR): Data Fault
2019-05-24T18:15:54.924Z,1558721754.924 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:15:55.276Z,1558721755.276 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:15:56.142Z,1558721756.142 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:15:56.143Z,1558721756.143 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:15:56.494Z,1558721756.494 [DVL_micro](INFO): Initializing
2019-05-24T18:19:00.714Z,1558721940.714 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:19:00.714Z,1558721940.714 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:19:00.714Z,1558721940.714 [DVL_micro](ERROR): Data Fault
2019-05-24T18:19:00.758Z,1558721940.758 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:19:01.126Z,1558721941.126 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:19:01.972Z,1558721941.972 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:19:01.972Z,1558721941.972 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:19:02.340Z,1558721942.340 [DVL_micro](INFO): Initializing
2019-05-24T18:22:06.554Z,1558722126.554 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:22:06.554Z,1558722126.554 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:22:06.554Z,1558722126.554 [DVL_micro](ERROR): Data Fault
2019-05-24T18:22:06.595Z,1558722126.595 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:22:06.956Z,1558722126.956 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:22:07.817Z,1558722127.817 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:22:07.817Z,1558722127.817 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:22:08.170Z,1558722128.170 [DVL_micro](INFO): Initializing
2019-05-24T18:22:15.826Z,1558722135.826 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@59)
2019-05-24T18:22:41.279Z,1558722161.279 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.
2019-05-24T18:22:41.279Z,1558722161.279 [ESPComponent](DEBUG): Writing samplingActive=0, sampleNumber=1
2019-05-24T18:22:41.353Z,1558722161.353 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-05-24T18:22:41.353Z,1558722161.353 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-24T18:22:41.353Z,1558722161.353 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-05-24T18:22:41.353Z,1558722161.353 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-24T18:22:41.354Z,1558722161.354 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper
2019-05-24T18:22:41.354Z,1558722161.354 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-05-24T18:22:41.354Z,1558722161.354 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-05-24T18:22:41.354Z,1558722161.354 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-05-24T18:22:41.355Z,1558722161.355 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth
2019-05-24T18:22:41.355Z,1558722161.355 [sample:SampleAtDepth] Stopped
2019-05-24T18:22:41.355Z,1558722161.355 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-24T18:22:41.682Z,1558722161.682 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):
@10:36:55.79 Selecting Cartridge 59
@11:10:43.18 Sampled  1000.0ml

2019-05-24T18:22:41.683Z,1558722161.683 [ESPComponent](INFO): powering down ESP
2019-05-24T18:22:41.684Z,1558722161.684 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-24T18:22:41.861Z,1558722161.861 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample
2019-05-24T18:22:41.861Z,1558722161.861 [sample:SampleRepeater:Sample] Stopped
2019-05-24T18:22:41.861Z,1558722161.861 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-24T18:22:41.861Z,1558722161.861 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater
2019-05-24T18:22:41.861Z,1558722161.861 [sample:SampleRepeater] Stopped
2019-05-24T18:22:41.862Z,1558722161.862 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-24T18:22:41.862Z,1558722161.862 [sample](INFO): Completed sample
2019-05-24T18:22:41.862Z,1558722161.862 [MissionManager](INFO): sample is completed.
2019-05-24T18:22:41.863Z,1558722161.863 [MissionManager](INFO): Uninitializing Mission sample
2019-05-24T18:22:41.863Z,1558722161.863 [sample] Stopped
2019-05-24T18:22:41.863Z,1558722161.863 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-24T18:22:41.863Z,1558722161.863 [sample:A.AbortSample] Stopped
2019-05-24T18:22:41.863Z,1558722161.863 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-24T18:22:41.863Z,1558722161.863 [sample:B.Pitch] Stopped
2019-05-24T18:22:41.863Z,1558722161.863 [sample:C.SetSpeed] Stopped
2019-05-24T18:22:41.863Z,1558722161.863 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-24T18:22:42.150Z,1558722162.150 [MissionManager](IMPORTANT): Started mission Default
2019-05-24T18:22:42.151Z,1558722162.151 [Default] Running Loop=1
2019-05-24T18:22:42.151Z,1558722162.151 [Default](DEBUG): Aggregate::initialize Default
2019-05-24T18:22:42.151Z,1558722162.151 [Default:B.GoToSurface] Running Loop=1
2019-05-24T18:22:42.151Z,1558722162.151 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-24T18:22:42.151Z,1558722162.151 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-24T18:22:42.152Z,1558722162.152 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-24T18:22:42.152Z,1558722162.152 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-24T18:22:42.152Z,1558722162.152 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-24T18:22:42.153Z,1558722162.153 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-24T18:22:42.153Z,1558722162.153 [Default:A.Wait] Running Loop=1
2019-05-24T18:22:42.153Z,1558722162.153 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-24T18:22:42.536Z,1558722162.536 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -13.00 mm (1 active estimators).
2019-05-24T18:22:42.753Z,1558722162.753 [Radio_Surface](INFO): Powering up
2019-05-24T18:22:42.853Z,1558722162.853 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2019-05-24T18:22:42.853Z,1558722162.853 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2019-05-24T18:22:42.853Z,1558722162.853 [BuoyancyServo] Communications Fault, FailCount= 1
2019-05-24T18:22:42.853Z,1558722162.853 [BuoyancyServo](ERROR): Communications Fault
2019-05-24T18:22:42.858Z,1558722162.858 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2019-05-24T18:22:44.486Z,1558722164.486 [CommandLine](IMPORTANT): got command maintain clear
2019-05-24T18:22:44.594Z,1558722164.594 [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-05-24T18:22:44.670Z,1558722164.670 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-24T18:22:44.670Z,1558722164.670 [BuoyancyServo](INFO): Powering down
2019-05-24T18:22:45.501Z,1558722165.501 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-05-24T18:22:45.501Z,1558722165.501 [BuoyancyServo] No Fault, FailCount= 1
2019-05-24T18:22:45.852Z,1558722165.852 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-24T18:22:45.852Z,1558722165.852 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-24T18:22:48.061Z,1558722168.061 [DataOverHttps](INFO): Radio surface powered ON.
2019-05-24T18:22:55.557Z,1558722175.557 [Default:A.Wait](INFO): Done Waiting.
2019-05-24T18:22:55.557Z,1558722175.557 [Default:A.Wait] Stopped
2019-05-24T18:22:55.557Z,1558722175.557 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-24T18:22:55.964Z,1558722175.964 [Default:CheckIn] Running Loop=1
2019-05-24T18:22:55.964Z,1558722175.964 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-24T18:22:55.964Z,1558722175.964 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-24T18:22:57.549Z,1558722177.549 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-24T18:22:57.549Z,1558722177.549 [NAL9602] Data Fault, FailCount= 2
2019-05-24T18:22:57.549Z,1558722177.549 [NAL9602](ERROR): Data Fault
2019-05-24T18:22:57.634Z,1558722177.634 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-24T18:22:57.950Z,1558722177.950 [NAL9602](INFO): Powering down
2019-05-24T18:22:58.814Z,1558722178.814 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-24T18:22:58.814Z,1558722178.814 [NAL9602] No Fault, FailCount= 2
2019-05-24T18:23:18.361Z,1558722198.361 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-05-24T18:23:28.250Z,1558722208.250 [NAL9602](INFO): Powering up NAL9602
2019-05-24T18:23:39.157Z,1558722219.157 [NAL9602](INFO): NAL9602 initialized
2019-05-24T18:23:39.977Z,1558722219.977 [NAL9602](DEBUG): Fix Requested
2019-05-24T18:23:49.065Z,1558722229.065 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-05-24T18:24:19.769Z,1558722259.769 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-05-24T18:24:50.473Z,1558722290.473 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-05-24T18:25:12.480Z,1558722312.480 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:25:12.480Z,1558722312.480 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:25:12.480Z,1558722312.480 [DVL_micro](ERROR): Data Fault
2019-05-24T18:25:12.515Z,1558722312.515 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:25:12.985Z,1558722312.985 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:25:13.754Z,1558722313.754 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:25:13.754Z,1558722313.754 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:25:14.116Z,1558722314.116 [DVL_micro](INFO): Initializing
2019-05-24T18:25:17.541Z,1558722317.541 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003493
2019-05-24T18:26:41.382Z,1558722401.382 [DVL_micro](ERROR): only read 42 of 46 data items
2019-05-24T18:26:41.382Z,1558722401.382 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 1995 1088 -544 594 2 3 2 2 3388.6 659.3 844.7 2 1265.6 -3211.6 844.7 2 3388 2 1265 -3211 844 2 -5.55 -1.57 280.5 -3.0 22.2 0.005 35.0 1489 101
2019-05-24T18:27:56.133Z,1558722476.133 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-24T18:22:55.0Z
2019-05-24T18:27:56.133Z,1558722476.133 [Default:CheckIn:Read_GPS] Stopped
2019-05-24T18:27:56.133Z,1558722476.133 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-24T18:28:00.301Z,1558722480.301 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20190524T172306/Courier0007.lzma
2019-05-24T18:28:01.118Z,1558722481.118 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Courier0007.lzma.bak
2019-05-24T18:28:01.118Z,1558722481.118 [DataOverHttps](INFO): SBD MOMSN=11180293
2019-05-24T18:28:18.858Z,1558722498.858 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:28:18.858Z,1558722498.858 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:28:18.858Z,1558722498.858 [DVL_micro](ERROR): Data Fault
2019-05-24T18:28:18.900Z,1558722498.900 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:28:19.329Z,1558722499.329 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:28:20.126Z,1558722500.126 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:28:20.126Z,1558722500.126 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:28:20.494Z,1558722500.494 [DVL_micro](INFO): Initializing
2019-05-24T18:28:23.600Z,1558722503.600 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190524T172306/Courier0010.lzma
2019-05-24T18:28:24.406Z,1558722504.406 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Courier0010.lzma.bak
2019-05-24T18:28:24.406Z,1558722504.406 [DataOverHttps](INFO): SBD MOMSN=11180298
2019-05-24T18:28:42.288Z,1558722522.288 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-24T18:28:50.527Z,1558722530.527 [DataOverHttps](INFO): Sending 1732 bytes from file Logs/20190524T172306/Express0008.lzma
2019-05-24T18:28:51.330Z,1558722531.330 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Express0008.lzma.bak
2019-05-24T18:28:51.330Z,1558722531.330 [DataOverHttps](INFO): SBD MOMSN=11180313
2019-05-24T18:29:12.990Z,1558722552.990 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-24T18:29:15.292Z,1558722555.292 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190524T172306/Express0011.lzma
2019-05-24T18:29:16.098Z,1558722556.098 [DataOverHttps](INFO): Moved sent file to Logs/20190524T172306/Express0011.lzma.bak
2019-05-24T18:29:16.098Z,1558722556.098 [DataOverHttps](INFO): SBD MOMSN=11180383
2019-05-24T18:29:20.340Z,1558722560.340 [Default:CheckIn:Read_Iridium] Stopped
2019-05-24T18:29:20.340Z,1558722560.340 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-24T18:29:20.340Z,1558722560.340 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-24T18:31:24.696Z,1558722684.696 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-24T18:31:24.696Z,1558722684.696 [DVL_micro] Data Fault, FailCount= 1
2019-05-24T18:31:24.696Z,1558722684.696 [DVL_micro](ERROR): Data Fault
2019-05-24T18:31:24.731Z,1558722684.731 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-24T18:31:25.173Z,1558722685.173 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:31:25.939Z,1558722685.939 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-24T18:31:25.939Z,1558722685.939 [DVL_micro] No Fault, FailCount= 1
2019-05-24T18:31:26.325Z,1558722686.325 [DVL_micro](INFO): Initializing
2019-05-24T18:32:25.409Z,1558722745.409 [CommandLine](IMPORTANT): got command gfscan
2019-05-24T18:32:25.762Z,1558722745.762 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-24T18:32:36.685Z,1558722756.685 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.135599
CHAN A1 (24V): -0.013321
CHAN A2 (12V): -0.000467
CHAN A3 (5V): -0.002225
CHAN B0 (3.3V): -0.001208
CHAN B1 (3.15aV): -0.001937
CHAN B2 (3.15bV): -0.001338
CHAN B3 (GND): -0.004018
OPEN: 0.007401
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-24T18:32:47.851Z,1558722767.851 [CommandLine](IMPORTANT): got command quit
2019-05-24T18:32:48.857Z,1558722768.857 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-24T18:32:48.857Z,1558722768.857 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:48.857Z,1558722768.857 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:48.937Z,1558722768.937 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-24T18:32:48.937Z,1558722768.937 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:48.938Z,1558722768.938 [CommandLine](INFO): Join timeout helper Thread ID is 6047
2019-05-24T18:32:48.938Z,1558722768.938 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-24T18:32:48.938Z,1558722768.938 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:48.939Z,1558722768.939 [NavChartDb](INFO): Join timeout helper Thread ID is 6048
2019-05-24T18:32:49.153Z,1558722769.153 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:49.153Z,1558722769.153 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.161Z,1558722769.161 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-24T18:32:49.161Z,1558722769.161 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.161Z,1558722769.161 [Radio_Surface](INFO): Join timeout helper Thread ID is 6049
2019-05-24T18:32:49.297Z,1558722769.297 [Radio_Surface](INFO): Powering down
2019-05-24T18:32:49.298Z,1558722769.298 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:49.298Z,1558722769.298 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.313Z,1558722769.313 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-24T18:32:49.313Z,1558722769.313 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.313Z,1558722769.313 [DataOverHttps](INFO): Join timeout helper Thread ID is 6050
2019-05-24T18:32:49.597Z,1558722769.597 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:49.597Z,1558722769.597 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.613Z,1558722769.613 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-05-24T18:32:49.613Z,1558722769.613 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.613Z,1558722769.613 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 6051
2019-05-24T18:32:49.865Z,1558722769.865 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:49.866Z,1558722769.866 [WetLabsBB2FL](INFO): Powering down
2019-05-24T18:32:49.866Z,1558722769.866 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.882Z,1558722769.882 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-05-24T18:32:49.882Z,1558722769.882 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:49.882Z,1558722769.882 [CTD_Seabird](INFO): Join timeout helper Thread ID is 6052
2019-05-24T18:32:50.125Z,1558722770.125 [CTD_Seabird](INFO): Powering down
2019-05-24T18:32:50.137Z,1558722770.137 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:50.137Z,1558722770.137 [CTD_Seabird](INFO): Powering down
2019-05-24T18:32:50.149Z,1558722770.149 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.165Z,1558722770.165 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-24T18:32:50.166Z,1558722770.166 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.166Z,1558722770.166 [logger](INFO): Join timeout helper Thread ID is 6053
2019-05-24T18:32:50.217Z,1558722770.217 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:50.217Z,1558722770.217 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.225Z,1558722770.225 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-24T18:32:50.226Z,1558722770.226 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.226Z,1558722770.226 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-24T18:32:50.226Z,1558722770.226 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.226Z,1558722770.226 [controlThread](INFO): Join timeout helper Thread ID is 6054
2019-05-24T18:32:50.321Z,1558722770.321 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-24T18:32:50.321Z,1558722770.321 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-24T18:32:50.322Z,1558722770.322 [Aanderaa_O2](INFO): Powering down
2019-05-24T18:32:50.324Z,1558722770.324 [AHRS_M2](INFO): Powering down
2019-05-24T18:32:50.465Z,1558722770.465 [DVL_micro](INFO): uninitialize:Powering down
2019-05-24T18:32:50.466Z,1558722770.466 [NAL9602](INFO): Powering down
2019-05-24T18:32:50.467Z,1558722770.467 [DAT](INFO): Powering down
2019-05-24T18:32:50.586Z,1558722770.586 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-24T18:32:50.587Z,1558722770.587 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-24T18:32:50.587Z,1558722770.587 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-24T18:32:50.587Z,1558722770.587 [MissionManager](INFO): Uninitializing Mission Default
2019-05-24T18:32:50.588Z,1558722770.588 [Default] Stopped
2019-05-24T18:32:50.588Z,1558722770.588 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-24T18:32:50.588Z,1558722770.588 [Default:B.GoToSurface] Stopped
2019-05-24T18:32:50.588Z,1558722770.588 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-24T18:32:50.588Z,1558722770.588 [Default:CheckIn] Stopped
2019-05-24T18:32:50.588Z,1558722770.588 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-24T18:32:50.588Z,1558722770.588 [Default:CheckIn:C.Wait] Stopped
2019-05-24T18:32:50.588Z,1558722770.588 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-24T18:32:50.590Z,1558722770.590 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-24T18:32:50.591Z,1558722770.591 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-24T18:32:50.591Z,1558722770.591 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-24T18:32:50.591Z,1558722770.591 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-24T18:32:50.592Z,1558722770.592 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-24T18:32:50.592Z,1558722770.592 [BuoyancyServo](INFO): Powering down
2019-05-24T18:32:50.605Z,1558722770.605 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-24T18:32:50.605Z,1558722770.605 [ElevatorServo](INFO): Powering down
2019-05-24T18:32:50.606Z,1558722770.606 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-24T18:32:50.606Z,1558722770.606 [MassServo](INFO): Powering down
2019-05-24T18:32:50.607Z,1558722770.607 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-24T18:32:50.607Z,1558722770.607 [RudderServo](INFO): Powering down
2019-05-24T18:32:50.608Z,1558722770.608 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-24T18:32:50.608Z,1558722770.608 [ThrusterServo](INFO): Powering down
2019-05-24T18:32:50.608Z,1558722770.608 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-24T18:32:50.609Z,1558722770.609 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-24T18:32:50.609Z,1558722770.609 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-24T18:32:50.609Z,1558722770.609 [CBIT](DEBUG): Powering off loads.
2019-05-24T18:32:50.621Z,1558722770.621 [CBIT](DEBUG): Disabling WDT.
2019-05-24T18:32:50.633Z,1558722770.633 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-24T18:32:50.633Z,1558722770.633 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.671Z,1558722770.671 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.758Z,1558722770.758 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.820Z,1558722770.820 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.828Z,1558722770.828 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.877Z,1558722770.877 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-24T18:32:50.942Z,1558722770.942 [logger ThreadHandler](INFO): Thread cancelled.