2019-08-09T21:52:36.205Z,1565387556.205 [Supervisor](DEBUG): Initializing supervisor.
2019-08-09T21:52:36.208Z,1565387556.208 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-08-09T21:52:36.209Z,1565387556.209 [SyncHandler](INFO): Protected caller Thread ID is 5451
2019-08-09T21:52:36.209Z,1565387556.209 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-08-09T21:52:36.210Z,1565387556.210 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-08-09T21:52:36.210Z,1565387556.210 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5452
2019-08-09T21:52:36.213Z,1565387556.213 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-08-09T21:52:36.225Z,1565387556.225 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-08-09T21:52:36.226Z,1565387556.226 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-08-09T21:52:36.227Z,1565387556.227 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5453
2019-08-09T21:52:36.228Z,1565387556.228 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-08-09T21:52:36.229Z,1565387556.229 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-08-09T21:52:36.229Z,1565387556.229 [logger ThreadHandler](INFO): Protected caller Thread ID is 5454
2019-08-09T21:52:36.231Z,1565387556.231 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-08-09T21:52:36.231Z,1565387556.231 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-08-09T21:52:36.233Z,1565387556.233 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-08-09T21:52:36.657Z,1565387556.657 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-08-09T21:52:36.658Z,1565387556.658 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-08-09T21:52:36.755Z,1565387556.755 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-08-09T21:52:36.755Z,1565387556.755 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-08-09T21:52:37.074Z,1565387557.074 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-08-09T21:52:37.074Z,1565387557.074 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-08-09T21:52:37.214Z,1565387557.214 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-08-09T21:52:37.215Z,1565387557.215 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-08-09T21:52:37.407Z,1565387557.407 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-08-09T21:52:37.408Z,1565387557.408 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-08-09T21:52:37.865Z,1565387557.865 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-08-09T21:52:37.865Z,1565387557.865 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-08-09T21:52:38.204Z,1565387558.204 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-08-09T21:52:38.205Z,1565387558.205 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-08-09T21:52:38.348Z,1565387558.348 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-08-09T21:52:38.349Z,1565387558.349 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-08-09T21:52:38.544Z,1565387558.544 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-08-09T21:52:38.544Z,1565387558.544 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-08-09T21:52:38.640Z,1565387558.640 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-08-09T21:52:38.640Z,1565387558.640 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-08-09T21:52:38.941Z,1565387558.941 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-08-09T21:52:38.942Z,1565387558.942 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-08-09T21:52:39.022Z,1565387559.022 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-08-09T21:52:39.124Z,1565387559.124 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-08-09T21:52:39.124Z,1565387559.124 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-08-09T21:52:39.721Z,1565387559.721 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-08-09T21:52:39.722Z,1565387559.722 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-08-09T21:52:40.123Z,1565387560.123 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-08-09T21:52:40.125Z,1565387560.125 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-08-09T21:52:40.126Z,1565387560.126 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-08-09T21:52:40.335Z,1565387560.335 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-08-09T21:52:40.435Z,1565387560.435 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-08-09T21:52:40.533Z,1565387560.533 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-08-09T21:52:40.760Z,1565387560.760 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-08-09T21:52:40.761Z,1565387560.761 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-08-09T21:52:40.844Z,1565387560.844 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-08-09T21:52:40.937Z,1565387560.937 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-08-09T21:52:41.032Z,1565387561.032 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-08-09T21:52:41.114Z,1565387561.114 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-08-09T21:52:41.222Z,1565387561.222 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-08-09T21:52:41.407Z,1565387561.407 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-08-09T21:52:41.539Z,1565387561.539 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-08-09T21:52:41.540Z,1565387561.540 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-08-09T21:52:41.550Z,1565387561.550 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-08-09T21:52:41.960Z,1565387561.960 [AHRS_M2] Loaded
2019-08-09T21:52:41.960Z,1565387561.960 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-08-09T21:52:42.036Z,1565387562.036 [DataOverHttps] Loaded
2019-08-09T21:52:42.036Z,1565387562.036 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-08-09T21:52:42.037Z,1565387562.037 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407664E0
2019-08-09T21:52:42.037Z,1565387562.037 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5533
2019-08-09T21:52:42.051Z,1565387562.051 [Depth_Keller] Loaded
2019-08-09T21:52:42.051Z,1565387562.051 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-08-09T21:52:42.056Z,1565387562.056 [DropWeight] Loaded
2019-08-09T21:52:42.056Z,1565387562.056 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-08-09T21:52:42.114Z,1565387562.114 [DUSBL_Hydroid] Loaded
2019-08-09T21:52:42.114Z,1565387562.114 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-08-09T21:52:42.163Z,1565387562.163 [Micromodem] Loaded
2019-08-09T21:52:42.163Z,1565387562.163 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-08-09T21:52:42.262Z,1565387562.262 [NAL9602] Loaded
2019-08-09T21:52:42.262Z,1565387562.262 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-08-09T21:52:42.278Z,1565387562.278 [Onboard] Loaded
2019-08-09T21:52:42.279Z,1565387562.279 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-08-09T21:52:42.285Z,1565387562.285 [PowerOnly] Loaded
2019-08-09T21:52:42.285Z,1565387562.285 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-08-09T21:52:42.291Z,1565387562.291 [Radio_Surface] Loaded
2019-08-09T21:52:42.292Z,1565387562.292 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-08-09T21:52:42.293Z,1565387562.293 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407964E0
2019-08-09T21:52:42.293Z,1565387562.293 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5534
2019-08-09T21:52:42.339Z,1565387562.339 [RDI_Pathfinder] Loaded
2019-08-09T21:52:42.339Z,1565387562.339 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-08-09T21:52:44.232Z,1565387564.232 [BPC1] Loaded
2019-08-09T21:52:44.233Z,1565387564.233 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-08-09T21:52:44.233Z,1565387564.233 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-08-09T21:52:44.234Z,1565387564.234 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-08-09T21:52:44.247Z,1565387564.247 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-08-09T21:52:44.247Z,1565387564.247 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-08-09T21:52:44.356Z,1565387564.356 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-08-09T21:52:44.356Z,1565387564.356 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-08-09T21:52:44.377Z,1565387564.377 [NavChart] Loaded
2019-08-09T21:52:44.377Z,1565387564.377 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-08-09T21:52:44.381Z,1565387564.381 [UniversalFixResidualReporter] Loaded
2019-08-09T21:52:44.381Z,1565387564.381 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-08-09T21:52:44.382Z,1565387564.382 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-08-09T21:52:44.382Z,1565387564.382 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-08-09T21:52:44.490Z,1565387564.490 [BuoyancyServo] Loaded
2019-08-09T21:52:44.490Z,1565387564.490 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-08-09T21:52:44.505Z,1565387564.505 [ElevatorServo] Loaded
2019-08-09T21:52:44.506Z,1565387564.506 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-08-09T21:52:44.521Z,1565387564.521 [MassServo] Loaded
2019-08-09T21:52:44.521Z,1565387564.521 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-08-09T21:52:44.536Z,1565387564.536 [RudderServo] Loaded
2019-08-09T21:52:44.537Z,1565387564.537 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-08-09T21:52:44.551Z,1565387564.551 [ThrusterServo] Loaded
2019-08-09T21:52:44.552Z,1565387564.552 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-08-09T21:52:44.552Z,1565387564.552 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-08-09T21:52:44.553Z,1565387564.553 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-08-09T21:52:44.803Z,1565387564.803 [CTD_NeilBrown] Loaded
2019-08-09T21:52:44.804Z,1565387564.804 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-08-09T21:52:44.805Z,1565387564.805 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E14E0
2019-08-09T21:52:44.805Z,1565387564.805 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5535
2019-08-09T21:52:44.835Z,1565387564.835 [ESPComponent] Loaded
2019-08-09T21:52:44.836Z,1565387564.836 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-08-09T21:52:44.881Z,1565387564.881 [WetLabsSeaOWL_UV_A] Loaded
2019-08-09T21:52:44.881Z,1565387564.881 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-08-09T21:52:44.882Z,1565387564.882 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409114E0
2019-08-09T21:52:44.882Z,1565387564.882 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 5536
2019-08-09T21:52:44.883Z,1565387564.883 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-08-09T21:52:44.884Z,1565387564.884 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-08-09T21:52:45.174Z,1565387565.174 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-08-09T21:52:45.175Z,1565387565.175 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-08-09T21:52:45.217Z,1565387565.217 [DepthRateCalculator] Loaded
2019-08-09T21:52:45.217Z,1565387565.217 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-08-09T21:52:45.223Z,1565387565.223 [PitchRateCalculator] Loaded
2019-08-09T21:52:45.223Z,1565387565.223 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-08-09T21:52:45.236Z,1565387565.236 [SpeedCalculator] Loaded
2019-08-09T21:52:45.236Z,1565387565.236 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-08-09T21:52:45.258Z,1565387565.258 [TempGradientCalculator] Loaded
2019-08-09T21:52:45.258Z,1565387565.258 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-08-09T21:52:45.264Z,1565387565.264 [YawRateCalculator] Loaded
2019-08-09T21:52:45.264Z,1565387565.264 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-08-09T21:52:45.305Z,1565387565.305 [ElevatorOffsetCalculator] Loaded
2019-08-09T21:52:45.305Z,1565387565.305 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-08-09T21:52:45.306Z,1565387565.306 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-08-09T21:52:45.306Z,1565387565.306 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-08-09T21:52:45.439Z,1565387565.439 [SBIT](DEBUG): Construct Startup Built In Test.
2019-08-09T21:52:45.462Z,1565387565.462 [SBIT] Loaded
2019-08-09T21:52:45.462Z,1565387565.462 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-08-09T21:52:45.463Z,1565387565.463 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-08-09T21:52:45.474Z,1565387565.474 [IBIT] Loaded
2019-08-09T21:52:45.474Z,1565387565.474 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-08-09T21:52:45.477Z,1565387565.477 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-08-09T21:52:45.618Z,1565387565.618 [CBIT] Loaded
2019-08-09T21:52:45.619Z,1565387565.619 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-08-09T21:52:45.619Z,1565387565.619 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-08-09T21:52:45.620Z,1565387565.620 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-08-09T21:52:45.699Z,1565387565.699 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-08-09T21:52:45.699Z,1565387565.699 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-08-09T21:52:45.798Z,1565387565.798 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-08-09T21:52:45.799Z,1565387565.799 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-08-09T21:52:45.865Z,1565387565.865 [VerticalControl](DEBUG): Construct VerticalControl.
2019-08-09T21:52:45.951Z,1565387565.951 [VerticalControl] Loaded
2019-08-09T21:52:45.952Z,1565387565.952 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-08-09T21:52:45.952Z,1565387565.952 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-08-09T21:52:46.011Z,1565387566.011 [HorizontalControl] Loaded
2019-08-09T21:52:46.011Z,1565387566.011 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-08-09T21:52:46.012Z,1565387566.012 [SpeedControl](DEBUG): Construct SpeedControl.
2019-08-09T21:52:46.014Z,1565387566.014 [SpeedControl] Loaded
2019-08-09T21:52:46.014Z,1565387566.014 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-08-09T21:52:46.015Z,1565387566.015 [LoopControl](DEBUG): Construct LoopControl.
2019-08-09T21:52:46.015Z,1565387566.015 [LoopControl] Loaded
2019-08-09T21:52:46.016Z,1565387566.016 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-08-09T21:52:46.016Z,1565387566.016 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-08-09T21:52:46.017Z,1565387566.017 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-08-09T21:52:46.049Z,1565387566.049 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-08-09T21:52:46.052Z,1565387566.052 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-08-09T21:52:46.053Z,1565387566.053 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-08-09T21:52:46.060Z,1565387566.060 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-08-09T21:52:46.061Z,1565387566.061 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AED4E0
2019-08-09T21:52:46.062Z,1565387566.062 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5537
2019-08-09T21:52:46.066Z,1565387566.066 [Supervisor](INFO): Main Thread ID is 4140
2019-08-09T21:52:46.066Z,1565387566.066 [Supervisor](DEBUG): Running supervisor.
2019-08-09T21:52:46.067Z,1565387566.067 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5538
2019-08-09T21:52:46.069Z,1565387566.069 [controlThread ThreadHandler](INFO): Handler Thread ID is 5539
2019-08-09T21:52:46.070Z,1565387566.070 [controlThread](DEBUG): Initializing ControlThread
2019-08-09T21:52:46.076Z,1565387566.076 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-08-09T21:52:46.076Z,1565387566.076 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-08-09T21:52:46.077Z,1565387566.077 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-08-09T21:52:46.078Z,1565387566.078 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-08-09T21:52:46.078Z,1565387566.078 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-08-09T21:52:46.078Z,1565387566.078 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-08-09T21:52:46.079Z,1565387566.079 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-08-09T21:52:46.079Z,1565387566.079 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-08-09T21:52:46.080Z,1565387566.080 [SBIT](INFO): Initialize SBIT Component.
2019-08-09T21:52:46.080Z,1565387566.080 [SBIT](IMPORTANT): git: 2019-07-16A-4-gbc3a532
2019-08-09T21:52:46.081Z,1565387566.081 [SBIT](INFO): git hash: bc3a532330c34a530d393d20f0a16563b6db3de2
2019-08-09T21:52:46.081Z,1565387566.081 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-08-09T21:52:46.082Z,1565387566.082 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #2 PREEMPT Wed May 15 08:34:03 PDT 2019
2019-08-09T21:52:46.083Z,1565387566.083 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-08-09T21:52:46.084Z,1565387566.084 [IBIT](INFO): Initialize IBIT Component.
2019-08-09T21:52:46.085Z,1565387566.085 [CBIT](DEBUG): Initialize CBIT Component.
2019-08-09T21:52:46.086Z,1565387566.086 [logger ThreadHandler](INFO): Handler Thread ID is 5540
2019-08-09T21:52:46.096Z,1565387566.096 [CBIT](DEBUG): Initialized mux pins.
2019-08-09T21:52:46.097Z,1565387566.097 [CBIT](DEBUG): Initializing the watchdog timer.
2019-08-09T21:52:46.105Z,1565387566.105 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5541
2019-08-09T21:52:46.106Z,1565387566.106 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-08-09T21:52:46.117Z,1565387566.117 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5542
2019-08-09T21:52:46.121Z,1565387566.121 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-08-09T21:52:46.121Z,1565387566.121 [CBIT](DEBUG): Initializing heartbeat.
2019-08-09T21:52:46.129Z,1565387566.129 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5543
2019-08-09T21:52:46.130Z,1565387566.130 [CTD_NeilBrown](INFO): Powering down
2019-08-09T21:52:46.157Z,1565387566.157 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 5544
2019-08-09T21:52:46.158Z,1565387566.158 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-08-09T21:52:46.192Z,1565387566.192 [CBIT](DEBUG): Deactivating GF circuits.
2019-08-09T21:52:46.193Z,1565387566.193 [CBIT](DEBUG): Deactivating emergency mode.
2019-08-09T21:52:46.194Z,1565387566.194 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5545
2019-08-09T21:52:46.197Z,1565387566.197 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-08-09T21:52:46.197Z,1565387566.197 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-08-09T21:52:46.197Z,1565387566.197 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-08-09T21:52:46.197Z,1565387566.197 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-08-09T21:52:46.197Z,1565387566.197 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-08-09T21:52:46.197Z,1565387566.197 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-08-09T21:52:46.198Z,1565387566.198 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-08-09T21:52:46.198Z,1565387566.198 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-08-09T21:52:46.198Z,1565387566.198 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-08-09T21:52:46.198Z,1565387566.198 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-08-09T21:52:46.198Z,1565387566.198 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-08-09T21:52:46.198Z,1565387566.198 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-08-09T21:52:46.199Z,1565387566.199 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-08-09T21:52:46.199Z,1565387566.199 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-08-09T21:52:46.199Z,1565387566.199 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-08-09T21:52:46.199Z,1565387566.199 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-08-09T21:52:46.228Z,1565387566.228 [CBIT](DEBUG): Backplane powered.
2019-08-09T21:52:46.229Z,1565387566.229 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-08-09T21:52:46.230Z,1565387566.230 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-08-09T21:52:46.231Z,1565387566.231 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-08-09T21:52:46.231Z,1565387566.231 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-08-09T21:52:46.232Z,1565387566.232 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-08-09T21:52:46.243Z,1565387566.243 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-09T21:52:46.270Z,1565387566.270 [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-08-09T21:52:46.271Z,1565387566.271 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-08-09T21:52:46.344Z,1565387566.344 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-08-09T21:52:46.345Z,1565387566.345 [Default:A.Wait](DEBUG): Construct Wait.
2019-08-09T21:52:46.347Z,1565387566.347 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-09T21:52:46.398Z,1565387566.398 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-08-09T21:52:46.400Z,1565387566.400 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-08-09T21:52:46.437Z,1565387566.437 [Default:E.Execute](DEBUG): Construct Execute.
2019-08-09T21:52:46.457Z,1565387566.457 [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-08-09T21:52:46.462Z,1565387566.462 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,ESPComponent,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-08-09T21:52:46.471Z,1565387566.471 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-08-09T21:52:46.504Z,1565387566.504 [DUSBL_Hydroid](INFO): Powering up
2019-08-09T21:52:46.505Z,1565387566.505 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-08-09T21:52:46.521Z,1565387566.521 [Radio_Surface](INFO): Powering up
2019-08-09T21:52:46.606Z,1565387566.606 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-09T21:52:46.613Z,1565387566.613 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-09T21:52:46.614Z,1565387566.614 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-08-09T21:52:46.621Z,1565387566.621 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-08-09T21:52:46.622Z,1565387566.622 [MassServo](DEBUG): Initializing EZServoServo.
2019-08-09T21:52:46.629Z,1565387566.629 [MassServo](DEBUG): Initializing MassServo.
2019-08-09T21:52:46.630Z,1565387566.630 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-09T21:52:46.641Z,1565387566.641 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-09T21:52:46.642Z,1565387566.642 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-09T21:52:46.649Z,1565387566.649 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-09T21:52:46.887Z,1565387566.887 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-08-09T21:52:46.887Z,1565387566.887 [DropWeight] Hardware Fault, FailCount= 1
2019-08-09T21:52:46.887Z,1565387566.887 [DropWeight](ERROR): Hardware Fault
2019-08-09T21:52:46.889Z,1565387566.889 [Micromodem](INFO): Powering up
2019-08-09T21:52:46.889Z,1565387566.889 [Micromodem](DEBUG): Initializing Micromodem.
2019-08-09T21:52:46.946Z,1565387566.946 [CommandLine](FAULT): Scheduling is paused
2019-08-09T21:52:46.946Z,1565387566.946 [CBIT](INFO): Critical error at 20190809T215246
2019-08-09T21:52:46.947Z,1565387566.947 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-08-09T21:52:46.949Z,1565387566.949 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-08-09T21:52:46.950Z,1565387566.950 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-08-09T21:52:47.586Z,1565387567.586 [CBIT](INFO): Critical error at 20190809T215246
2019-08-09T21:52:51.762Z,1565387571.762 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-08-09T21:52:52.163Z,1565387572.163 [Micromodem](INFO): Nmea in: $CATMG,2019-08-09T21:52:51.717230Z,RTC,RTC*5B

2019-08-09T21:52:52.163Z,1565387572.163 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-08-09T21:52:51.717230Z,RTC,RTC*5B

2019-08-09T21:52:52.567Z,1565387572.567 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-08-09T21:52:52.567Z,1565387572.567 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-08-09T21:52:52.958Z,1565387572.958 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-08-09T21:52:52.959Z,1565387572.959 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-08-09T21:52:53.375Z,1565387573.375 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-08-09T21:52:53.375Z,1565387573.375 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-08-09T21:52:53.779Z,1565387573.779 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-08-09T21:52:53.779Z,1565387573.779 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-08-09T21:52:54.183Z,1565387574.183 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-08-09T21:52:54.183Z,1565387574.183 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-08-09T21:52:54.575Z,1565387574.575 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-08-09T21:52:54.575Z,1565387574.575 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-08-09T21:52:54.983Z,1565387574.983 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-08-09T21:52:54.983Z,1565387574.983 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-08-09T21:52:55.372Z,1565387575.372 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-08-09T21:52:55.373Z,1565387575.373 [Micromodem](INFO): Nmea out: $CCCLK,2019,08,09,21,52,56*48

2019-08-09T21:52:55.783Z,1565387575.783 [Micromodem](INFO): Nmea in: $CACLK,2019,8,9,21,52,56*4A

2019-08-09T21:52:56.179Z,1565387576.179 [Micromodem](INFO): Nmea in: $CATMS,0,2019-08-09T21:52:57Z*7B

2019-08-09T21:52:56.181Z,1565387576.181 [Micromodem](INFO): Nmea in: $CATMG,2019-08-09T21:52:57.027442Z,USER_CMD,RTC*1B

2019-08-09T21:52:59.832Z,1565387579.832 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-08-09T21:53:04.661Z,1565387584.661 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-08-09T21:53:12.327Z,1565387592.327 [NAL9602](INFO): Powering up NAL9602
2019-08-09T21:53:14.803Z,1565387594.803 [SBIT](IMPORTANT): Beginning Startup BIT
2019-08-09T21:53:14.808Z,1565387594.808 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-09T21:53:23.431Z,1565387603.431 [NAL9602](INFO): NAL9602 initialized
2019-08-09T21:53:24.252Z,1565387604.252 [NAL9602](DEBUG): Fix Requested
2019-08-09T21:53:25.957Z,1565387605.957 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.009300
CHAN A1 (24V): -0.027640
CHAN A2 (12V): -0.006324
CHAN A3 (5V): -0.002030
CHAN B0 (3.3V): 0.000087
CHAN B1 (3.15aV): 0.000002
CHAN B2 (3.15bV): 0.000292
CHAN B3 (GND): 0.002248
OPEN: 0.006990
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-09T21:53:46.698Z,1565387626.698 [RDI_Pathfinder](ERROR): Failed to parse:
+1,    -4,    +0,A
2019-08-09T21:53:57.696Z,1565387637.696 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-08-09T21:53:57.696Z,1565387637.696 [RDI_Pathfinder](ERROR): Failed to parse:
:BD-0.01,       -0.07,       -0.02,   9.59,  0.00
2019-08-09T21:54:08.191Z,1565387648.191 [SBIT](IMPORTANT): SBIT PASSED
2019-08-09T21:54:08.253Z,1565387648.253 [CommandLine](IMPORTANT): got command configSet list
2019-08-09T21:54:08.253Z,1565387648.253 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-09T21:54:08.254Z,1565387648.254 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-08-09T21:54:08.254Z,1565387648.254 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-08-09T21:54:08.254Z,1565387648.254 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=10 minute;

2019-08-09T21:54:08.254Z,1565387648.254 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2019-08-09T21:54:08.254Z,1565387648.254 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.acoustic_contact_range 2.000000 meter;

2019-08-09T21:54:08.255Z,1565387648.255 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none;

2019-08-09T21:54:08.255Z,1565387648.255 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree;

2019-08-09T21:54:08.255Z,1565387648.255 [CommandLine](IMPORTANT): Micromodem.surfaceThreshold=2 meter;

2019-08-09T21:54:08.255Z,1565387648.255 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-08-09T21:54:08.594Z,1565387648.594 [MissionManager](IMPORTANT): Started mission Startup
2019-08-09T21:54:08.594Z,1565387648.594 [Startup] Running Loop=1
2019-08-09T21:54:08.595Z,1565387648.595 [Startup](DEBUG): Aggregate::initialize Startup
2019-08-09T21:54:08.595Z,1565387648.595 [Startup:A.GoToSurface] Running Loop=1
2019-08-09T21:54:08.595Z,1565387648.595 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-09T21:54:08.595Z,1565387648.595 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-09T21:54:08.596Z,1565387648.596 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-09T21:54:08.596Z,1565387648.596 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-09T21:54:08.597Z,1565387648.597 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-09T21:54:08.597Z,1565387648.597 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-09T21:54:08.599Z,1565387648.599 [Startup:StartupSatComms] Running Loop=1
2019-08-09T21:54:08.599Z,1565387648.599 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-08-09T21:54:08.599Z,1565387648.599 [Startup:StartupSatComms:A] Running Loop=1
2019-08-09T21:54:09.012Z,1565387649.012 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-08-09T21:54:10.981Z,1565387650.981 [NAL9602](INFO): SBD MO Status=2, MOMSN=8311, MT Status=2, MTMSN=0
2019-08-09T21:54:10.982Z,1565387650.982 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-09T21:54:49.764Z,1565387689.764 [NAL9602](INFO): SBD MO Status=2, MOMSN=8311, MT Status=2, MTMSN=0
2019-08-09T21:54:49.764Z,1565387689.764 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-09T21:55:06.395Z,1565387706.395 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1565387648.000000 second
2019-08-09T21:55:08.854Z,1565387708.854 [Startup:StartupSatComms:A](INFO): Timed out from 2019-08-09T21:54:08.6Z
2019-08-09T21:55:08.854Z,1565387708.854 [Startup:StartupSatComms:A] Stopped
2019-08-09T21:55:08.854Z,1565387708.854 [Startup:StartupSatComms:B] Running Loop=1
2019-08-09T21:55:09.199Z,1565387709.199 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-09T21:55:13.879Z,1565387713.879 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004991
2019-08-09T21:55:15.433Z,1565387715.433 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-08-09T21:55:15.590Z,1565387715.590 [Startup:StartupSatComms:B] Stopped
2019-08-09T21:55:15.590Z,1565387715.590 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-08-09T21:55:15.590Z,1565387715.590 [Startup:StartupSatComms] Stopped
2019-08-09T21:55:15.590Z,1565387715.590 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-08-09T21:55:15.591Z,1565387715.591 [Startup](INFO): Completed Startup
2019-08-09T21:55:15.591Z,1565387715.591 [MissionManager](INFO): Startup is completed.
2019-08-09T21:55:15.591Z,1565387715.591 [MissionManager](INFO): Uninitializing Mission Startup
2019-08-09T21:55:15.591Z,1565387715.591 [Startup] Stopped
2019-08-09T21:55:15.591Z,1565387715.591 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-08-09T21:55:15.591Z,1565387715.591 [Startup:A.GoToSurface] Stopped
2019-08-09T21:55:15.591Z,1565387715.591 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-09T21:55:16.003Z,1565387716.003 [MissionManager](IMPORTANT): Started mission Default
2019-08-09T21:55:16.003Z,1565387716.003 [Default] Running Loop=1
2019-08-09T21:55:16.003Z,1565387716.003 [Default](DEBUG): Aggregate::initialize Default
2019-08-09T21:55:16.004Z,1565387716.004 [Default:B.GoToSurface] Running Loop=1
2019-08-09T21:55:16.004Z,1565387716.004 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-09T21:55:16.004Z,1565387716.004 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-09T21:55:16.012Z,1565387716.012 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-09T21:55:16.013Z,1565387716.013 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-09T21:55:16.013Z,1565387716.013 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-09T21:55:16.014Z,1565387716.014 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-09T21:55:16.014Z,1565387716.014 [Default:A.Wait] Running Loop=1
2019-08-09T21:55:16.014Z,1565387716.014 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-09T21:55:19.132Z,1565387719.132 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20190809T214827/Courier0004.lzma
2019-08-09T21:55:19.774Z,1565387719.774 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-08-09T21:55:19.774Z,1565387719.774 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-08-09T21:55:19.810Z,1565387719.810 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-08-09T21:55:19.813Z,1565387719.813 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-08-09T21:55:19.817Z,1565387719.817 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-08-09T21:55:19.820Z,1565387719.820 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-08-09T21:55:19.823Z,1565387719.823 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-08-09T21:55:19.825Z,1565387719.825 [DUSBL:A.Pitch](DEBUG): Construct.
2019-08-09T21:55:19.831Z,1565387719.831 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-08-09T21:55:19.859Z,1565387719.859 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-08-09T21:55:19.867Z,1565387719.867 [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="DUSBL">

    <Description>
        This mission is requests a DUSBL arming.
    </Description>

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

    <DefineArg Name="NumberOfRequests"><Description>
        Number of pings to requst.
    </Description><Units:count/><Value>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>   

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

    <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>

    <ReadData>
        <When>
            <Arg Name="EnabledDUSBL"/>
        </When>
            <Universal:acoustic_contact_range/>
            <Universal:acoustic_contact_direction_vehicle_frame/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

        <Sequence Repeat="NumberOfRequests"/>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.transponderCode/><Arg Name="TransponderCode"/></Assign>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.pingRequested/><Arg Name="NumberOfPings"/></Assign>
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:second/><Value>90</Value></Setting>
          </Guidance:Wait>
      </Aggregate>    
</Mission>


2019-08-09T21:55:19.869Z,1565387719.869 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-08-09T21:55:19.938Z,1565387719.938 [DataOverHttps](INFO): Moved sent file to Logs/20190809T214827/Courier0004.lzma.bak
2019-08-09T21:55:19.938Z,1565387719.938 [DataOverHttps](INFO): SBD MOMSN=11549170
2019-08-09T21:55:20.027Z,1565387720.027 [Default] Stopped
2019-08-09T21:55:20.027Z,1565387720.027 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-09T21:55:20.028Z,1565387720.028 [Default:A.Wait] Stopped
2019-08-09T21:55:20.028Z,1565387720.028 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-09T21:55:20.028Z,1565387720.028 [Default:B.GoToSurface] Stopped
2019-08-09T21:55:20.028Z,1565387720.028 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-09T21:55:20.028Z,1565387720.028 [MissionManager](IMPORTANT): Started mission DUSBL
2019-08-09T21:55:20.028Z,1565387720.028 [DUSBL] Running Loop=1
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL:A.Pitch] Running Loop=1
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL:C] Running Loop=1
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL:RequestRepeater] Running Loop=1
2019-08-09T21:55:20.029Z,1565387720.029 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-08-09T21:55:20.030Z,1565387720.030 [DUSBL:RequestRepeater:A] Running Loop=1
2019-08-09T21:55:20.030Z,1565387720.030 [DUSBL:RequestRepeater:B] Running Loop=1
2019-08-09T21:55:20.030Z,1565387720.030 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-08-09T21:55:20.030Z,1565387720.030 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-08-09T21:55:20.030Z,1565387720.030 [DUSBL:RequestRepeater:B] Running Loop=1
2019-08-09T21:55:20.030Z,1565387720.030 [DUSBL:RequestRepeater:A] Running Loop=1
2019-08-09T21:55:20.031Z,1565387720.031 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-08-09T21:55:20.032Z,1565387720.032 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-08-09T21:55:20.032Z,1565387720.032 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-09T21:55:20.033Z,1565387720.033 [DUSBL:A.Pitch] Running Loop=1
2019-08-09T21:55:21.598Z,1565387721.598 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-09T21:55:21.598Z,1565387721.598 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-09T21:55:21.598Z,1565387721.598 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 10
2019-08-09T21:55:21.598Z,1565387721.598 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-09T21:55:22.002Z,1565387722.002 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
O
2019-08-09T21:55:22.002Z,1565387722.002 [DUSBL_Hydroid](INFO): Command Ack
2019-08-09T21:55:22.002Z,1565387722.002 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-09T21:55:22.004Z,1565387722.004 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-09T21:55:22.415Z,1565387722.415 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-09T21:55:22.810Z,1565387722.810 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,00B,000,0005A,183,80,80,05
2019-08-09T21:55:22.810Z,1565387722.810 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,00B,000,0005A,183,80,80,05
2019-08-09T21:55:23.214Z,1565387723.214 [DUSBL_Hydroid](INFO): DUSBL response received:,FF
!U1,R,ED9,000,00000,187,80,81,08,FF
2019-08-09T21:55:23.214Z,1565387723.214 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: ,FF
!U1,R,ED9,000,00000,187,80,81,08,FF
2019-08-09T21:55:23.226Z,1565387723.226 [Micromodem](INFO): Nmea in: $SNTTA,0.188684,,,,215523.04*4D

2019-08-09T21:55:27.685Z,1565387727.685 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.085951
2019-08-09T21:55:27.686Z,1565387727.686 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-09T21:55:27.686Z,1565387727.686 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-09T21:55:27.686Z,1565387727.686 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 10
2019-08-09T21:55:27.687Z,1565387727.687 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-09T21:55:28.062Z,1565387728.062 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
1,R,ED9,000,00000,187,80,81,08,FF
2019-08-09T21:55:28.062Z,1565387728.062 [DUSBL_Hydroid](INFO): Command Ack
2019-08-09T21:55:28.062Z,1565387728.062 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-09T21:55:28.064Z,1565387728.064 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-09T21:55:28.465Z,1565387728.465 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-09T21:55:28.870Z,1565387728.870 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,FE3,000,0005A,185,80,80,05,,08,FF
2019-08-09T21:55:28.870Z,1565387728.870 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,FE3,000,0005A,185,80,80,05,,08,FF
2019-08-09T21:55:29.278Z,1565387729.278 [DUSBL_Hydroid](INFO): DUSBL response received:FF
!U1,R,F3D,000,00000,187,80,81,05,FF

2019-08-09T21:55:29.278Z,1565387729.278 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: FF
!U1,R,F3D,000,00000,187,80,81,05,FF

2019-08-09T21:55:29.290Z,1565387729.290 [Micromodem](INFO): Nmea in: $SNTTA,,,,,215529.10*57

2019-08-09T21:55:33.725Z,1565387733.725 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.037264
2019-08-09T21:55:33.725Z,1565387733.725 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-09T21:55:33.725Z,1565387733.725 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-09T21:55:33.725Z,1565387733.725 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 10
2019-08-09T21:55:33.726Z,1565387733.726 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-09T21:55:34.118Z,1565387734.118 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
,R,F3D,000,00000,187,80,81,05,FF

2019-08-09T21:55:34.118Z,1565387734.118 [DUSBL_Hydroid](INFO): Command Ack
2019-08-09T21:55:34.118Z,1565387734.118 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-09T21:55:34.120Z,1565387734.120 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-09T21:55:34.529Z,1565387734.529 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-09T21:55:34.934Z,1565387734.934 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,FB9,000,0005A,185,80,80,05,FF
FF

2019-08-09T21:55:34.935Z,1565387734.935 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-09T21:55:37.449Z,1565387737.449 [Micromodem](INFO): Nmea in: $SNTTA,,,,,215535.15*5F

2019-08-09T21:55:37.697Z,1565387737.697 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-09T21:55:37.698Z,1565387737.698 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-09T21:55:37.698Z,1565387737.698 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 10
2019-08-09T21:55:37.698Z,1565387737.698 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-09T21:55:38.029Z,1565387738.029 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
FB9,000,0005A,185,80,80,05,FF
FF

2019-08-09T21:55:38.029Z,1565387738.029 [DUSBL_Hydroid](INFO): Command Ack
2019-08-09T21:55:38.029Z,1565387738.029 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-09T21:55:38.030Z,1565387738.030 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-09T21:55:38.437Z,1565387738.437 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-09T21:55:38.842Z,1565387738.842 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,018,000,00059,183,80,80,06,FF
FF

2019-08-09T21:55:38.842Z,1565387738.842 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-09T21:55:41.358Z,1565387741.358 [Micromodem](INFO): Nmea in: $SNTTA,0.174187,,,,215539.06*43

2019-08-09T21:55:41.515Z,1565387741.515 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-09T21:55:41.515Z,1565387741.515 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-09T21:55:41.515Z,1565387741.515 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 10
2019-08-09T21:55:41.516Z,1565387741.516 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-09T21:55:41.842Z,1565387741.842 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
018,000,00059,183,80,80,06,FF
FF

2019-08-09T21:55:41.842Z,1565387741.842 [DUSBL_Hydroid](INFO): Command Ack
2019-08-09T21:55:41.842Z,1565387741.842 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-09T21:55:41.844Z,1565387741.844 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-09T21:55:42.253Z,1565387742.253 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-09T21:55:42.648Z,1565387742.648 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,011,000,00059,183,80,80,06,FF
FF

2019-08-09T21:55:42.650Z,1565387742.650 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-09T21:55:45.166Z,1565387745.166 [Micromodem](INFO): Nmea in: $SNTTA,,,,,215542.88*5B

2019-08-09T21:55:45.301Z,1565387745.301 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-09T21:55:45.302Z,1565387745.302 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-09T21:55:45.302Z,1565387745.302 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 10
2019-08-09T21:55:45.303Z,1565387745.303 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-09T21:55:45.691Z,1565387745.691 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
011,000,00059,183,80,80,06,FF
FF

2019-08-09T21:55:45.691Z,1565387745.691 [DUSBL_Hydroid](INFO): Command Ack
2019-08-09T21:55:45.691Z,1565387745.691 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-09T21:55:45.693Z,1565387745.693 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-09T21:55:46.085Z,1565387746.085 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-09T21:55:46.125Z,1565387746.125 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-08-09T21:55:46.125Z,1565387746.125 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-09T21:55:46.135Z,1565387746.135 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-09T21:55:46.482Z,1565387746.482 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,FAE,000,00038,185,80,80,0C,FF
FF

2019-08-09T21:55:46.483Z,1565387746.483 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-09T21:55:48.997Z,1565387748.997 [Micromodem](INFO): Nmea in: $SNTTA,,,,,215546.73*5B

2019-08-09T21:55:49.052Z,1565387749.052 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-09T21:55:49.052Z,1565387749.052 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-08-09T21:55:49.122Z,1565387749.122 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-09T21:55:49.122Z,1565387749.122 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-09T21:55:49.122Z,1565387749.122 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 10
2019-08-09T21:55:49.123Z,1565387749.123 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-09T21:55:49.470Z,1565387749.470 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
FAE,000,00038,185,80,80,0C,FF
FF

2019-08-09T21:55:49.470Z,1565387749.470 [DUSBL_Hydroid](INFO): Command Ack
2019-08-09T21:55:49.470Z,1565387749.470 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-09T21:55:49.471Z,1565387749.471 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-09T21:55:49.805Z,1565387749.805 [CommandLine](IMPORTANT): got command stop
2019-08-09T21:55:49.806Z,1565387749.806 [CommandLine](IMPORTANT): Scheduling is paused
2019-08-09T21:55:49.806Z,1565387749.806 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-08-09T21:55:49.881Z,1565387749.881 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-09T21:55:49.971Z,1565387749.971 [MissionManager](INFO): MissionManager is completed.
2019-08-09T21:55:49.971Z,1565387749.971 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-08-09T21:55:49.971Z,1565387749.971 [DUSBL] Stopped
2019-08-09T21:55:49.971Z,1565387749.971 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:A.Pitch] Stopped
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:B.SetSpeed] Stopped
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:C] Stopped
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:RequestRepeater] Stopped
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:RequestRepeater:A] Stopped
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:RequestRepeater:B] Stopped
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-08-09T21:55:49.972Z,1565387749.972 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-09T21:55:50.301Z,1565387750.301 [MissionManager](IMPORTANT): Started mission Default
2019-08-09T21:55:50.302Z,1565387750.302 [Default] Running Loop=1
2019-08-09T21:55:50.302Z,1565387750.302 [Default](DEBUG): Aggregate::initialize Default
2019-08-09T21:55:50.302Z,1565387750.302 [Default:B.GoToSurface] Running Loop=1
2019-08-09T21:55:50.302Z,1565387750.302 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-09T21:55:50.302Z,1565387750.302 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-09T21:55:50.302Z,1565387750.302 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-09T21:55:50.303Z,1565387750.303 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-09T21:55:50.303Z,1565387750.303 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-09T21:55:50.303Z,1565387750.303 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-09T21:55:50.304Z,1565387750.304 [Default:A.Wait] Running Loop=1
2019-08-09T21:55:50.304Z,1565387750.304 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-09T21:55:50.695Z,1565387750.695 [Micromodem](INFO): Nmea in: $SNTTA,,,,,215550.50*5D

2019-08-09T21:55:52.486Z,1565387752.486 [CommandLine](IMPORTANT): got command quit
2019-08-09T21:55:53.493Z,1565387753.493 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:53.493Z,1565387753.493 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:53.620Z,1565387753.620 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-08-09T21:55:53.620Z,1565387753.620 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:53.621Z,1565387753.621 [CommandLine](INFO): Join timeout helper Thread ID is 5563
2019-08-09T21:55:53.622Z,1565387753.622 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-08-09T21:55:53.622Z,1565387753.622 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:53.622Z,1565387753.622 [NavChartDb](INFO): Join timeout helper Thread ID is 5564
2019-08-09T21:55:53.673Z,1565387753.673 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:53.674Z,1565387753.674 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:53.685Z,1565387753.685 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-08-09T21:55:53.685Z,1565387753.685 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:53.686Z,1565387753.686 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 5565
2019-08-09T21:55:54.053Z,1565387754.053 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:54.053Z,1565387754.053 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-08-09T21:55:54.054Z,1565387754.054 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.072Z,1565387754.072 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-08-09T21:55:54.073Z,1565387754.073 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.073Z,1565387754.073 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5566
2019-08-09T21:55:54.197Z,1565387754.197 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:54.197Z,1565387754.197 [CTD_NeilBrown](INFO): Powering down
2019-08-09T21:55:54.208Z,1565387754.208 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.212Z,1565387754.212 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-08-09T21:55:54.213Z,1565387754.213 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.213Z,1565387754.213 [Radio_Surface](INFO): Join timeout helper Thread ID is 5567
2019-08-09T21:55:54.437Z,1565387754.437 [Radio_Surface](INFO): Powering down
2019-08-09T21:55:54.438Z,1565387754.438 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:54.438Z,1565387754.438 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.457Z,1565387754.457 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-08-09T21:55:54.457Z,1565387754.457 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.458Z,1565387754.458 [DataOverHttps](INFO): Join timeout helper Thread ID is 5568
2019-08-09T21:55:54.633Z,1565387754.633 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:54.633Z,1565387754.633 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.641Z,1565387754.641 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-08-09T21:55:54.641Z,1565387754.641 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.642Z,1565387754.642 [logger](INFO): Join timeout helper Thread ID is 5569
2019-08-09T21:55:54.701Z,1565387754.701 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:54.701Z,1565387754.701 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.729Z,1565387754.729 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-08-09T21:55:54.729Z,1565387754.729 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.729Z,1565387754.729 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-08-09T21:55:54.730Z,1565387754.730 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:54.730Z,1565387754.730 [controlThread](INFO): Join timeout helper Thread ID is 5570
2019-08-09T21:55:54.774Z,1565387754.774 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-09T21:55:54.774Z,1565387754.774 [controlThread](DEBUG): Uninitializing ControlThread
2019-08-09T21:55:54.774Z,1565387754.774 [AHRS_M2](INFO): Powering down
2019-08-09T21:55:54.845Z,1565387754.845 [DUSBL_Hydroid](INFO): Powering down
2019-08-09T21:55:54.917Z,1565387754.917 [Micromodem](INFO): Powering down
2019-08-09T21:55:55.013Z,1565387755.013 [NAL9602](INFO): Powering down
2019-08-09T21:55:55.085Z,1565387755.085 [RDI_Pathfinder](INFO): Powering down
2019-08-09T21:55:55.086Z,1565387755.086 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-08-09T21:55:55.087Z,1565387755.087 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-08-09T21:55:55.088Z,1565387755.088 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-08-09T21:55:55.089Z,1565387755.089 [MissionManager](INFO): Uninitializing Mission Default
2019-08-09T21:55:55.089Z,1565387755.089 [Default] Stopped
2019-08-09T21:55:55.089Z,1565387755.089 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-09T21:55:55.089Z,1565387755.089 [Default:A.Wait] Stopped
2019-08-09T21:55:55.089Z,1565387755.089 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-09T21:55:55.089Z,1565387755.089 [Default:B.GoToSurface] Stopped
2019-08-09T21:55:55.089Z,1565387755.089 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-09T21:55:55.091Z,1565387755.091 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-08-09T21:55:55.092Z,1565387755.092 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-08-09T21:55:55.092Z,1565387755.092 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-08-09T21:55:55.092Z,1565387755.092 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-08-09T21:55:55.093Z,1565387755.093 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-08-09T21:55:55.093Z,1565387755.093 [BuoyancyServo](INFO): Powering down
2019-08-09T21:55:55.105Z,1565387755.105 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-08-09T21:55:55.105Z,1565387755.105 [ElevatorServo](INFO): Powering down
2019-08-09T21:55:55.105Z,1565387755.105 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-08-09T21:55:55.106Z,1565387755.106 [MassServo](INFO): Powering down
2019-08-09T21:55:55.106Z,1565387755.106 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-09T21:55:55.106Z,1565387755.106 [RudderServo](INFO): Powering down
2019-08-09T21:55:55.107Z,1565387755.107 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-08-09T21:55:55.107Z,1565387755.107 [ThrusterServo](INFO): Powering down
2019-08-09T21:55:55.108Z,1565387755.108 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-08-09T21:55:55.108Z,1565387755.108 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-08-09T21:55:55.109Z,1565387755.109 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-08-09T21:55:55.109Z,1565387755.109 [CBIT](DEBUG): Powering off loads.
2019-08-09T21:55:55.120Z,1565387755.120 [CBIT](DEBUG): Disabling WDT.
2019-08-09T21:55:55.132Z,1565387755.132 [CBIT](DEBUG): Opening all GF detection circuits.
2019-08-09T21:55:55.133Z,1565387755.133 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:55.186Z,1565387755.186 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:55.195Z,1565387755.195 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:55.236Z,1565387755.236 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:55.239Z,1565387755.239 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:55.296Z,1565387755.296 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-09T21:55:55.354Z,1565387755.354 [logger ThreadHandler](INFO): Thread cancelled.