2019-08-14T15:38:22.429Z,1565797102.429 [Supervisor](DEBUG): Initializing supervisor.
2019-08-14T15:38:22.432Z,1565797102.432 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-08-14T15:38:22.432Z,1565797102.432 [SyncHandler](INFO): Protected caller Thread ID is 9023
2019-08-14T15:38:22.433Z,1565797102.433 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-08-14T15:38:22.434Z,1565797102.434 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-08-14T15:38:22.434Z,1565797102.434 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 9024
2019-08-14T15:38:22.436Z,1565797102.436 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-08-14T15:38:22.447Z,1565797102.447 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-08-14T15:38:22.448Z,1565797102.448 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-08-14T15:38:22.449Z,1565797102.449 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 9025
2019-08-14T15:38:22.449Z,1565797102.449 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-08-14T15:38:22.450Z,1565797102.450 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-08-14T15:38:22.451Z,1565797102.451 [logger ThreadHandler](INFO): Protected caller Thread ID is 9026
2019-08-14T15:38:22.452Z,1565797102.452 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-08-14T15:38:22.453Z,1565797102.453 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-08-14T15:38:22.454Z,1565797102.454 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-08-14T15:38:22.879Z,1565797102.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-08-14T15:38:22.879Z,1565797102.879 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-08-14T15:38:22.976Z,1565797102.976 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-08-14T15:38:22.977Z,1565797102.977 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-08-14T15:38:23.282Z,1565797103.282 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-08-14T15:38:23.283Z,1565797103.283 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-08-14T15:38:23.420Z,1565797103.420 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-08-14T15:38:23.421Z,1565797103.421 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-08-14T15:38:23.608Z,1565797103.608 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-08-14T15:38:23.609Z,1565797103.609 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-08-14T15:38:24.040Z,1565797104.040 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-08-14T15:38:24.041Z,1565797104.041 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-08-14T15:38:24.242Z,1565797104.242 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-08-14T15:38:24.242Z,1565797104.242 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-08-14T15:38:24.383Z,1565797104.383 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-08-14T15:38:24.384Z,1565797104.384 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-08-14T15:38:24.571Z,1565797104.571 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-08-14T15:38:24.572Z,1565797104.572 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-08-14T15:38:24.667Z,1565797104.667 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-08-14T15:38:24.667Z,1565797104.667 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-08-14T15:38:24.958Z,1565797104.958 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-08-14T15:38:24.958Z,1565797104.958 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-08-14T15:38:25.038Z,1565797105.038 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-08-14T15:38:25.140Z,1565797105.140 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-08-14T15:38:25.141Z,1565797105.141 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-08-14T15:38:25.711Z,1565797105.711 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-08-14T15:38:25.712Z,1565797105.712 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-08-14T15:38:26.098Z,1565797106.098 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-08-14T15:38:26.100Z,1565797106.100 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-08-14T15:38:26.101Z,1565797106.101 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-08-14T15:38:26.304Z,1565797106.304 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-08-14T15:38:26.403Z,1565797106.403 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-08-14T15:38:26.501Z,1565797106.501 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-08-14T15:38:26.723Z,1565797106.723 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-08-14T15:38:26.724Z,1565797106.724 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-08-14T15:38:26.808Z,1565797106.808 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-08-14T15:38:26.901Z,1565797106.901 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-08-14T15:38:26.996Z,1565797106.996 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-08-14T15:38:27.079Z,1565797107.079 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-08-14T15:38:27.202Z,1565797107.202 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-08-14T15:38:27.802Z,1565797107.802 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-08-14T15:38:28.257Z,1565797108.257 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-08-14T15:38:28.267Z,1565797108.267 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-08-14T15:38:28.621Z,1565797108.621 [AHRS_M2] Loaded
2019-08-14T15:38:28.622Z,1565797108.622 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-08-14T15:38:28.695Z,1565797108.695 [DataOverHttps] Loaded
2019-08-14T15:38:28.696Z,1565797108.696 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-08-14T15:38:28.697Z,1565797108.697 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407664E0
2019-08-14T15:38:28.697Z,1565797108.697 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 9105
2019-08-14T15:38:28.710Z,1565797108.710 [Depth_Keller] Loaded
2019-08-14T15:38:28.710Z,1565797108.710 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-08-14T15:38:28.714Z,1565797108.714 [DropWeight] Loaded
2019-08-14T15:38:28.714Z,1565797108.714 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-08-14T15:38:28.768Z,1565797108.768 [DUSBL_Hydroid] Loaded
2019-08-14T15:38:28.769Z,1565797108.769 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-08-14T15:38:28.815Z,1565797108.815 [Micromodem] Loaded
2019-08-14T15:38:28.815Z,1565797108.815 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-08-14T15:38:28.908Z,1565797108.908 [NAL9602] Loaded
2019-08-14T15:38:28.909Z,1565797108.909 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-08-14T15:38:28.924Z,1565797108.924 [Onboard] Loaded
2019-08-14T15:38:28.924Z,1565797108.924 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-08-14T15:38:28.930Z,1565797108.930 [PowerOnly] Loaded
2019-08-14T15:38:28.930Z,1565797108.930 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-08-14T15:38:28.936Z,1565797108.936 [Radio_Surface] Loaded
2019-08-14T15:38:28.937Z,1565797108.937 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-08-14T15:38:28.938Z,1565797108.938 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407964E0
2019-08-14T15:38:28.938Z,1565797108.938 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 9106
2019-08-14T15:38:28.980Z,1565797108.980 [RDI_Pathfinder] Loaded
2019-08-14T15:38:28.981Z,1565797108.981 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-08-14T15:38:30.418Z,1565797110.418 [BPC1] Loaded
2019-08-14T15:38:30.418Z,1565797110.418 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-08-14T15:38:30.419Z,1565797110.419 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-08-14T15:38:30.419Z,1565797110.419 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-08-14T15:38:30.432Z,1565797110.432 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-08-14T15:38:30.433Z,1565797110.433 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-08-14T15:38:30.536Z,1565797110.536 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-08-14T15:38:30.536Z,1565797110.536 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-08-14T15:38:30.555Z,1565797110.555 [NavChart] Loaded
2019-08-14T15:38:30.556Z,1565797110.556 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-08-14T15:38:30.559Z,1565797110.559 [UniversalFixResidualReporter] Loaded
2019-08-14T15:38:30.560Z,1565797110.560 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-08-14T15:38:30.560Z,1565797110.560 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-08-14T15:38:30.561Z,1565797110.561 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-08-14T15:38:30.663Z,1565797110.663 [BuoyancyServo] Loaded
2019-08-14T15:38:30.664Z,1565797110.664 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-08-14T15:38:30.678Z,1565797110.678 [ElevatorServo] Loaded
2019-08-14T15:38:30.678Z,1565797110.678 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-08-14T15:38:30.693Z,1565797110.693 [MassServo] Loaded
2019-08-14T15:38:30.693Z,1565797110.693 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-08-14T15:38:30.707Z,1565797110.707 [RudderServo] Loaded
2019-08-14T15:38:30.707Z,1565797110.707 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-08-14T15:38:30.721Z,1565797110.721 [ThrusterServo] Loaded
2019-08-14T15:38:30.722Z,1565797110.722 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-08-14T15:38:30.722Z,1565797110.722 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-08-14T15:38:30.723Z,1565797110.723 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-08-14T15:38:30.960Z,1565797110.960 [CTD_NeilBrown] Loaded
2019-08-14T15:38:30.961Z,1565797110.961 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-08-14T15:38:30.962Z,1565797110.962 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E14E0
2019-08-14T15:38:30.962Z,1565797110.962 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 9107
2019-08-14T15:38:30.991Z,1565797110.991 [ESPComponent] Loaded
2019-08-14T15:38:30.991Z,1565797110.991 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-08-14T15:38:31.033Z,1565797111.033 [WetLabsSeaOWL_UV_A] Loaded
2019-08-14T15:38:31.033Z,1565797111.033 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-08-14T15:38:31.034Z,1565797111.034 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409114E0
2019-08-14T15:38:31.035Z,1565797111.035 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 9108
2019-08-14T15:38:31.035Z,1565797111.035 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-08-14T15:38:31.036Z,1565797111.036 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-08-14T15:38:31.313Z,1565797111.313 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-08-14T15:38:31.313Z,1565797111.313 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-08-14T15:38:31.354Z,1565797111.354 [DepthRateCalculator] Loaded
2019-08-14T15:38:31.354Z,1565797111.354 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-08-14T15:38:31.359Z,1565797111.359 [PitchRateCalculator] Loaded
2019-08-14T15:38:31.359Z,1565797111.359 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-08-14T15:38:31.371Z,1565797111.371 [SpeedCalculator] Loaded
2019-08-14T15:38:31.372Z,1565797111.372 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-08-14T15:38:31.392Z,1565797111.392 [TempGradientCalculator] Loaded
2019-08-14T15:38:31.392Z,1565797111.392 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-08-14T15:38:31.398Z,1565797111.398 [YawRateCalculator] Loaded
2019-08-14T15:38:31.398Z,1565797111.398 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-08-14T15:38:31.436Z,1565797111.436 [ElevatorOffsetCalculator] Loaded
2019-08-14T15:38:31.436Z,1565797111.436 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-08-14T15:38:31.436Z,1565797111.436 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-08-14T15:38:31.437Z,1565797111.437 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-08-14T15:38:31.564Z,1565797111.564 [SBIT](DEBUG): Construct Startup Built In Test.
2019-08-14T15:38:31.585Z,1565797111.585 [SBIT] Loaded
2019-08-14T15:38:31.586Z,1565797111.586 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-08-14T15:38:31.586Z,1565797111.586 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-08-14T15:38:31.597Z,1565797111.597 [IBIT] Loaded
2019-08-14T15:38:31.598Z,1565797111.598 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-08-14T15:38:31.601Z,1565797111.601 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-08-14T15:38:31.733Z,1565797111.733 [CBIT] Loaded
2019-08-14T15:38:31.733Z,1565797111.733 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-08-14T15:38:31.734Z,1565797111.734 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-08-14T15:38:31.734Z,1565797111.734 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-08-14T15:38:31.811Z,1565797111.811 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-08-14T15:38:31.811Z,1565797111.811 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-08-14T15:38:31.906Z,1565797111.906 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-08-14T15:38:31.906Z,1565797111.906 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-08-14T15:38:31.969Z,1565797111.969 [VerticalControl](DEBUG): Construct VerticalControl.
2019-08-14T15:38:32.050Z,1565797112.050 [VerticalControl] Loaded
2019-08-14T15:38:32.050Z,1565797112.050 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-08-14T15:38:32.051Z,1565797112.051 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-08-14T15:38:32.106Z,1565797112.106 [HorizontalControl] Loaded
2019-08-14T15:38:32.106Z,1565797112.106 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-08-14T15:38:32.107Z,1565797112.107 [SpeedControl](DEBUG): Construct SpeedControl.
2019-08-14T15:38:32.109Z,1565797112.109 [SpeedControl] Loaded
2019-08-14T15:38:32.109Z,1565797112.109 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-08-14T15:38:32.109Z,1565797112.109 [LoopControl](DEBUG): Construct LoopControl.
2019-08-14T15:38:32.110Z,1565797112.110 [LoopControl] Loaded
2019-08-14T15:38:32.110Z,1565797112.110 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-08-14T15:38:32.111Z,1565797112.111 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-08-14T15:38:32.111Z,1565797112.111 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-08-14T15:38:32.142Z,1565797112.142 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-08-14T15:38:32.145Z,1565797112.145 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-08-14T15:38:32.146Z,1565797112.146 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-08-14T15:38:32.153Z,1565797112.153 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-08-14T15:38:32.154Z,1565797112.154 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AED4E0
2019-08-14T15:38:32.154Z,1565797112.154 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 9109
2019-08-14T15:38:32.158Z,1565797112.158 [Supervisor](INFO): Main Thread ID is 9022
2019-08-14T15:38:32.159Z,1565797112.159 [Supervisor](DEBUG): Running supervisor.
2019-08-14T15:38:32.159Z,1565797112.159 [CommandLine ThreadHandler](INFO): Handler Thread ID is 9110
2019-08-14T15:38:32.161Z,1565797112.161 [controlThread ThreadHandler](INFO): Handler Thread ID is 9111
2019-08-14T15:38:32.162Z,1565797112.162 [controlThread](DEBUG): Initializing ControlThread
2019-08-14T15:38:32.168Z,1565797112.168 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-08-14T15:38:32.168Z,1565797112.168 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-08-14T15:38:32.170Z,1565797112.170 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-08-14T15:38:32.170Z,1565797112.170 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-08-14T15:38:32.170Z,1565797112.170 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-08-14T15:38:32.171Z,1565797112.171 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-08-14T15:38:32.171Z,1565797112.171 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-08-14T15:38:32.171Z,1565797112.171 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-08-14T15:38:32.172Z,1565797112.172 [SBIT](INFO): Initialize SBIT Component.
2019-08-14T15:38:32.173Z,1565797112.173 [SBIT](IMPORTANT): git: 2019-07-16A-9-g48ab466
2019-08-14T15:38:32.173Z,1565797112.173 [SBIT](INFO): git hash: 48ab466e2d53b4edac844a519bec1bcd9cd82a0d
2019-08-14T15:38:32.173Z,1565797112.173 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-08-14T15:38:32.174Z,1565797112.174 [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-14T15:38:32.175Z,1565797112.175 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-08-14T15:38:32.176Z,1565797112.176 [IBIT](INFO): Initialize IBIT Component.
2019-08-14T15:38:32.177Z,1565797112.177 [CBIT](DEBUG): Initialize CBIT Component.
2019-08-14T15:38:32.178Z,1565797112.178 [logger ThreadHandler](INFO): Handler Thread ID is 9112
2019-08-14T15:38:32.189Z,1565797112.189 [CBIT](DEBUG): Initialized mux pins.
2019-08-14T15:38:32.189Z,1565797112.189 [CBIT](DEBUG): Initializing the watchdog timer.
2019-08-14T15:38:32.197Z,1565797112.197 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 9113
2019-08-14T15:38:32.198Z,1565797112.198 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-08-14T15:38:32.209Z,1565797112.209 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 9114
2019-08-14T15:38:32.213Z,1565797112.213 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-08-14T15:38:32.213Z,1565797112.213 [CBIT](DEBUG): Initializing heartbeat.
2019-08-14T15:38:32.221Z,1565797112.221 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 9115
2019-08-14T15:38:32.222Z,1565797112.222 [CTD_NeilBrown](INFO): Powering down
2019-08-14T15:38:32.261Z,1565797112.261 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 9116
2019-08-14T15:38:32.262Z,1565797112.262 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-08-14T15:38:32.281Z,1565797112.281 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 9117
2019-08-14T15:38:32.285Z,1565797112.285 [CBIT](DEBUG): Deactivating GF circuits.
2019-08-14T15:38:32.285Z,1565797112.285 [CBIT](DEBUG): Deactivating emergency mode.
2019-08-14T15:38:32.288Z,1565797112.288 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-08-14T15:38:32.288Z,1565797112.288 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-08-14T15:38:32.288Z,1565797112.288 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-08-14T15:38:32.288Z,1565797112.288 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-08-14T15:38:32.289Z,1565797112.289 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-08-14T15:38:32.289Z,1565797112.289 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-08-14T15:38:32.290Z,1565797112.290 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-08-14T15:38:32.290Z,1565797112.290 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-08-14T15:38:32.290Z,1565797112.290 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-08-14T15:38:32.290Z,1565797112.290 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-08-14T15:38:32.290Z,1565797112.290 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-08-14T15:38:32.291Z,1565797112.291 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-08-14T15:38:32.291Z,1565797112.291 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-08-14T15:38:32.291Z,1565797112.291 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-08-14T15:38:32.291Z,1565797112.291 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-08-14T15:38:32.291Z,1565797112.291 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-08-14T15:38:32.321Z,1565797112.321 [CBIT](DEBUG): Backplane powered.
2019-08-14T15:38:32.321Z,1565797112.321 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-08-14T15:38:32.323Z,1565797112.323 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-08-14T15:38:32.323Z,1565797112.323 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-08-14T15:38:32.324Z,1565797112.324 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-08-14T15:38:32.325Z,1565797112.325 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-08-14T15:38:32.336Z,1565797112.336 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-14T15:38:32.383Z,1565797112.383 [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-14T15:38:32.384Z,1565797112.384 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-08-14T15:38:32.473Z,1565797112.473 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-08-14T15:38:32.474Z,1565797112.474 [Default:A.Wait](DEBUG): Construct Wait.
2019-08-14T15:38:32.475Z,1565797112.475 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-14T15:38:32.518Z,1565797112.518 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-08-14T15:38:32.521Z,1565797112.521 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-08-14T15:38:32.542Z,1565797112.542 [Default:E.Execute](DEBUG): Construct Execute.
2019-08-14T15:38:32.545Z,1565797112.545 [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-14T15:38:32.557Z,1565797112.557 [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-14T15:38:32.571Z,1565797112.571 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-08-14T15:38:32.613Z,1565797112.613 [Radio_Surface](INFO): Powering up
2019-08-14T15:38:32.629Z,1565797112.629 [DUSBL_Hydroid](INFO): Powering up
2019-08-14T15:38:32.629Z,1565797112.629 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-08-14T15:38:32.714Z,1565797112.714 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-14T15:38:32.721Z,1565797112.721 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-14T15:38:32.722Z,1565797112.722 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-08-14T15:38:32.729Z,1565797112.729 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-08-14T15:38:32.730Z,1565797112.730 [MassServo](DEBUG): Initializing EZServoServo.
2019-08-14T15:38:32.737Z,1565797112.737 [MassServo](DEBUG): Initializing MassServo.
2019-08-14T15:38:32.738Z,1565797112.738 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-14T15:38:32.749Z,1565797112.749 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-14T15:38:32.750Z,1565797112.750 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-14T15:38:32.757Z,1565797112.757 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-14T15:38:33.070Z,1565797113.070 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-08-14T15:38:33.070Z,1565797113.070 [DropWeight] Hardware Fault, FailCount= 1
2019-08-14T15:38:33.070Z,1565797113.070 [DropWeight](ERROR): Hardware Fault
2019-08-14T15:38:33.072Z,1565797113.072 [Micromodem](INFO): Powering up
2019-08-14T15:38:33.072Z,1565797113.072 [Micromodem](DEBUG): Initializing Micromodem.
2019-08-14T15:38:33.138Z,1565797113.138 [CommandLine](FAULT): Scheduling is paused
2019-08-14T15:38:33.139Z,1565797113.139 [CBIT](INFO): Critical error at 20190814T153833
2019-08-14T15:38:33.139Z,1565797113.139 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-08-14T15:38:33.141Z,1565797113.141 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-08-14T15:38:33.142Z,1565797113.142 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-08-14T15:38:33.725Z,1565797113.725 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-08-14T15:38:33.725Z,1565797113.725 [RudderServo](FAULT): Rudder failed to initialize
2019-08-14T15:38:33.725Z,1565797113.725 [RudderServo] Communications Fault, FailCount= 1
2019-08-14T15:38:33.725Z,1565797113.725 [RudderServo](ERROR): Communications Fault
2019-08-14T15:38:33.834Z,1565797113.834 [CBIT](INFO): Critical error at 20190814T153833
2019-08-14T15:38:33.836Z,1565797113.836 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-08-14T15:38:34.010Z,1565797114.010 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-14T15:38:34.010Z,1565797114.010 [RudderServo](INFO): Powering down
2019-08-14T15:38:34.680Z,1565797114.680 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-14T15:38:34.802Z,1565797114.802 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-14T15:38:34.806Z,1565797114.806 [CBIT](INFO): Clearing failed state for component RudderServo
2019-08-14T15:38:34.806Z,1565797114.806 [RudderServo] No Fault, FailCount= 1
2019-08-14T15:38:37.925Z,1565797117.925 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-08-14T15:38:38.327Z,1565797118.327 [Micromodem](INFO): Nmea in: $CATMG,2019-08-14T15:38:38.128493Z,RTC,RTC*56

2019-08-14T15:38:38.328Z,1565797118.328 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-08-14T15:38:38.128493Z,RTC,RTC*56

2019-08-14T15:38:38.847Z,1565797118.847 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-08-14T15:38:38.847Z,1565797118.847 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-08-14T15:38:39.251Z,1565797119.251 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-08-14T15:38:39.251Z,1565797119.251 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-08-14T15:38:39.655Z,1565797119.655 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-08-14T15:38:39.655Z,1565797119.655 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-08-14T15:38:40.059Z,1565797120.059 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-08-14T15:38:40.059Z,1565797120.059 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-08-14T15:38:40.467Z,1565797120.467 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-08-14T15:38:40.467Z,1565797120.467 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-08-14T15:38:40.855Z,1565797120.855 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-08-14T15:38:40.855Z,1565797120.855 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-08-14T15:38:41.263Z,1565797121.263 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-08-14T15:38:41.263Z,1565797121.263 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-08-14T15:38:41.651Z,1565797121.651 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-08-14T15:38:41.651Z,1565797121.651 [Micromodem](INFO): Nmea out: $CCCLK,2019,08,14,15,38,42*4A

2019-08-14T15:38:42.092Z,1565797122.092 [Micromodem](INFO): Nmea in: $CACLK,2019,8,14,15,38,42*78

2019-08-14T15:38:42.106Z,1565797122.106 [Micromodem](INFO): Nmea in: $CATMS,0,2019-08-14T15:38:43Z*79

2019-08-14T15:38:42.107Z,1565797122.107 [Micromodem](INFO): Nmea in: $CATMG,2019-08-14T15:38:43.028604Z,USER_CMD,RTC*16

2019-08-14T15:38:44.091Z,1565797124.091 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004452
2019-08-14T15:38:46.113Z,1565797126.113 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-08-14T15:38:50.530Z,1565797130.530 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-08-14T15:38:59.015Z,1565797139.015 [NAL9602](INFO): Powering up NAL9602
2019-08-14T15:39:00.663Z,1565797140.663 [SBIT](IMPORTANT): Beginning Startup BIT
2019-08-14T15:39:00.671Z,1565797140.671 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-14T15:39:10.019Z,1565797150.019 [NAL9602](INFO): NAL9602 initialized
2019-08-14T15:39:10.837Z,1565797150.837 [NAL9602](DEBUG): Fix Requested
2019-08-14T15:39:11.786Z,1565797151.786 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.018941
CHAN A1 (24V): -0.027463
CHAN A2 (12V): -0.007079
CHAN A3 (5V): -0.002221
CHAN B0 (3.3V): 0.000335
CHAN B1 (3.15aV): 0.000166
CHAN B2 (3.15bV): 0.000058
CHAN B3 (GND): 0.001954
OPEN: 0.007025
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-14T15:39:47.234Z,1565797187.234 [CommandLine](IMPORTANT): got command show stack
2019-08-14T15:39:47.235Z,1565797187.235 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-14T15:39:47.235Z,1565797187.235 [MissionManager](IMPORTANT): Mission loaded, but not running.
2019-08-14T15:39:54.279Z,1565797194.279 [SBIT](IMPORTANT): SBIT PASSED
2019-08-14T15:39:54.345Z,1565797194.345 [CommandLine](IMPORTANT): got command configSet list
2019-08-14T15:39:54.346Z,1565797194.346 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-14T15:39:54.347Z,1565797194.347 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-08-14T15:39:54.347Z,1565797194.347 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=50 millisecond;

2019-08-14T15:39:54.347Z,1565797194.347 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-08-14T15:39:54.347Z,1565797194.347 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=10 minute;

2019-08-14T15:39:54.347Z,1565797194.347 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2019-08-14T15:39:54.348Z,1565797194.348 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.acoustic_contact_range 2.000000 meter;

2019-08-14T15:39:54.348Z,1565797194.348 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none;

2019-08-14T15:39:54.348Z,1565797194.348 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree;

2019-08-14T15:39:54.348Z,1565797194.348 [CommandLine](IMPORTANT): Micromodem.surfaceThreshold=2 meter;

2019-08-14T15:39:54.348Z,1565797194.348 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-08-14T15:39:54.638Z,1565797194.638 [MissionManager](IMPORTANT): Started mission Startup
2019-08-14T15:39:54.638Z,1565797194.638 [Startup] Running Loop=1
2019-08-14T15:39:54.638Z,1565797194.638 [Startup](DEBUG): Aggregate::initialize Startup
2019-08-14T15:39:54.638Z,1565797194.638 [Startup:A.GoToSurface] Running Loop=1
2019-08-14T15:39:54.638Z,1565797194.638 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-14T15:39:54.639Z,1565797194.639 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-14T15:39:54.639Z,1565797194.639 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-14T15:39:54.640Z,1565797194.640 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-14T15:39:54.640Z,1565797194.640 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-14T15:39:54.642Z,1565797194.642 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-14T15:39:54.643Z,1565797194.643 [Startup:StartupSatComms] Running Loop=1
2019-08-14T15:39:54.643Z,1565797194.643 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-08-14T15:39:54.643Z,1565797194.643 [Startup:StartupSatComms:A] Running Loop=1
2019-08-14T15:39:55.052Z,1565797195.052 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-08-14T15:40:20.149Z,1565797220.149 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-08-14T15:40:47.576Z,1565797247.576 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-08-14T15:40:54.897Z,1565797254.897 [Startup:StartupSatComms:A](INFO): Timed out from 2019-08-14T15:39:54.6Z
2019-08-14T15:40:54.897Z,1565797254.897 [Startup:StartupSatComms:A] Stopped
2019-08-14T15:40:54.897Z,1565797254.897 [Startup:StartupSatComms:B] Running Loop=1
2019-08-14T15:40:55.251Z,1565797255.251 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-14T15:40:57.818Z,1565797257.818 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190814T153822/Courier0000.lzma
2019-08-14T15:40:58.450Z,1565797258.450 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Courier0000.lzma.bak
2019-08-14T15:40:58.450Z,1565797258.450 [DataOverHttps](INFO): SBD MOMSN=11569485
2019-08-14T15:41:09.784Z,1565797269.784 [DataOverHttps](INFO): Sending 88 bytes from file Logs/20190814T053158/Express0022.lzma
2019-08-14T15:41:10.590Z,1565797270.590 [DataOverHttps](INFO): Moved sent file to Logs/20190814T053158/Express0022.lzma.bak
2019-08-14T15:41:10.590Z,1565797270.590 [DataOverHttps](INFO): SBD MOMSN=11569490
2019-08-14T15:41:21.394Z,1565797281.394 [DataOverHttps](INFO): Sending 961 bytes from file Logs/20190814T153822/Express0001.lzma
2019-08-14T15:41:22.198Z,1565797282.198 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Express0001.lzma.bak
2019-08-14T15:41:22.198Z,1565797282.198 [DataOverHttps](INFO): SBD MOMSN=11569493
2019-08-14T15:41:23.235Z,1565797283.235 [Startup:StartupSatComms:B] Stopped
2019-08-14T15:41:23.235Z,1565797283.235 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-08-14T15:41:23.235Z,1565797283.235 [Startup:StartupSatComms] Stopped
2019-08-14T15:41:23.235Z,1565797283.235 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-08-14T15:41:23.236Z,1565797283.236 [Startup](INFO): Completed Startup
2019-08-14T15:41:23.236Z,1565797283.236 [MissionManager](INFO): Startup is completed.
2019-08-14T15:41:23.236Z,1565797283.236 [MissionManager](INFO): Uninitializing Mission Startup
2019-08-14T15:41:23.236Z,1565797283.236 [Startup] Stopped
2019-08-14T15:41:23.236Z,1565797283.236 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-08-14T15:41:23.241Z,1565797283.241 [Startup:A.GoToSurface] Stopped
2019-08-14T15:41:23.241Z,1565797283.241 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-14T15:41:23.626Z,1565797283.626 [MissionManager](IMPORTANT): Started mission Default
2019-08-14T15:41:23.626Z,1565797283.626 [Default] Running Loop=1
2019-08-14T15:41:23.626Z,1565797283.626 [Default](DEBUG): Aggregate::initialize Default
2019-08-14T15:41:23.626Z,1565797283.626 [Default:B.GoToSurface] Running Loop=1
2019-08-14T15:41:23.626Z,1565797283.626 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-14T15:41:23.627Z,1565797283.627 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-14T15:41:23.627Z,1565797283.627 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-14T15:41:23.627Z,1565797283.627 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-14T15:41:23.628Z,1565797283.628 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-14T15:41:23.628Z,1565797283.628 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-14T15:41:23.628Z,1565797283.628 [Default:A.Wait] Running Loop=1
2019-08-14T15:41:23.628Z,1565797283.628 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:41:30.064Z,1565797290.064 [NAL9602](INFO): SBD MO Status=2, MOMSN=8394, MT Status=2, MTMSN=0
2019-08-14T15:41:30.064Z,1565797290.064 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-14T15:41:32.509Z,1565797292.509 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-08-14T15:41:32.509Z,1565797292.509 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-14T15:41:32.527Z,1565797292.527 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-14T15:41:32.986Z,1565797292.986 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-14T15:41:32.986Z,1565797292.986 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-08-14T15:41:36.962Z,1565797296.962 [Default:A.Wait](INFO): Done Waiting.
2019-08-14T15:41:36.963Z,1565797296.963 [Default:A.Wait] Stopped
2019-08-14T15:41:36.963Z,1565797296.963 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:41:37.362Z,1565797297.362 [Default:CheckIn] Running Loop=1
2019-08-14T15:41:37.362Z,1565797297.362 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-14T15:41:37.362Z,1565797297.362 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-14T15:41:37.770Z,1565797297.770 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-14T15:41:47.441Z,1565797307.441 [NAL9602](INFO): SBD MO Status=2, MOMSN=8394, MT Status=2, MTMSN=0
2019-08-14T15:41:47.442Z,1565797307.442 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-14T15:41:51.574Z,1565797311.574 [CommandLine](IMPORTANT): got command show stack
2019-08-14T15:41:51.574Z,1565797311.574 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-14T15:41:51.575Z,1565797311.575 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-08-14T15:41:51.575Z,1565797311.575 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS
2019-08-14T15:42:12.901Z,1565797332.901 [NAL9602](INFO): SBD MO Status=2, MOMSN=8394, MT Status=2, MTMSN=0
2019-08-14T15:42:12.901Z,1565797332.901 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-14T15:42:23.392Z,1565797343.392 [NAL9602](INFO): SBD MO Status=0, MOMSN=8394, MT Status=0, MTMSN=0
2019-08-14T15:42:23.392Z,1565797343.392 [NAL9602](INFO): No messages in MT queue
2019-08-14T15:42:24.217Z,1565797344.217 [NAL9602](DEBUG): Fix Requested
2019-08-14T15:42:24.613Z,1565797344.613 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,153844.00,A,3648.16319,N,12147.28151,W,0.369,184.48,140819,,,A*70
2019-08-14T15:42:24.616Z,1565797344.616 [NAL9602](INFO): GPS fix at 20190814T153844: (36.802720, -121.788025)
2019-08-14T15:42:24.652Z,1565797344.652 [Default:CheckIn:Read_GPS] Stopped
2019-08-14T15:42:24.652Z,1565797344.652 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-14T15:42:25.070Z,1565797345.070 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-14T15:42:28.630Z,1565797348.630 [CommandLine](IMPORTANT): got command run ./Missions/DUSBL_Tracking.xml
2019-08-14T15:42:28.631Z,1565797348.631 [MissionManager](INFO): Loading Mission: ./Missions/DUSBL_Tracking.xml
2019-08-14T15:42:28.769Z,1565797348.769 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-08-14T15:42:28.772Z,1565797348.772 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-08-14T15:42:28.784Z,1565797348.784 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-08-14T15:42:28.824Z,1565797348.824 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-08-14T15:42:28.853Z,1565797348.853 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-08-14T15:42:28.857Z,1565797348.857 [DUSBL:A.Pitch](DEBUG): Construct.
2019-08-14T15:42:28.910Z,1565797348.910 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-08-14T15:42:29.337Z,1565797349.337 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-08-14T15:42:29.340Z,1565797349.340 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</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>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-08-14T15:42:29.354Z,1565797349.354 [CommandLine](IMPORTANT): Running ./Missions/DUSBL_Tracking.xml
2019-08-14T15:42:29.507Z,1565797349.507 [Default] Stopped
2019-08-14T15:42:29.507Z,1565797349.507 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-14T15:42:29.507Z,1565797349.507 [Default:B.GoToSurface] Stopped
2019-08-14T15:42:29.507Z,1565797349.507 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-14T15:42:29.507Z,1565797349.507 [Default:CheckIn] Stopped
2019-08-14T15:42:29.507Z,1565797349.507 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-14T15:42:29.507Z,1565797349.507 [Default:CheckIn:Read_Iridium] Stopped
2019-08-14T15:42:29.508Z,1565797349.508 [MissionManager](IMPORTANT): Started mission DUSBL
2019-08-14T15:42:29.508Z,1565797349.508 [DUSBL] Running Loop=1
2019-08-14T15:42:29.508Z,1565797349.508 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-08-14T15:42:29.508Z,1565797349.508 [DUSBL:A.Pitch] Running Loop=1
2019-08-14T15:42:29.508Z,1565797349.508 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-08-14T15:42:29.521Z,1565797349.521 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-14T15:42:29.521Z,1565797349.521 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-08-14T15:42:29.521Z,1565797349.521 [DUSBL:C.] Running Loop=1
2019-08-14T15:42:29.521Z,1565797349.521 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-08-14T15:42:29.522Z,1565797349.522 [DUSBL:RequestRepeater] Running Loop=1
2019-08-14T15:42:29.522Z,1565797349.522 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-08-14T15:42:29.522Z,1565797349.522 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-08-14T15:42:29.522Z,1565797349.522 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:42:29.522Z,1565797349.522 [DUSBL:C.] Running Loop=1
2019-08-14T15:42:29.523Z,1565797349.523 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-14T15:42:29.523Z,1565797349.523 [DUSBL:A.Pitch] Running Loop=1
2019-08-14T15:42:33.524Z,1565797353.524 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:42:33.668Z,1565797353.668 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190814T153822/Courier0004.lzma
2019-08-14T15:42:34.307Z,1565797354.307 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:42:34.475Z,1565797354.475 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Courier0004.lzma.bak
2019-08-14T15:42:34.475Z,1565797354.475 [DataOverHttps](INFO): SBD MOMSN=11569522
2019-08-14T15:42:34.718Z,1565797354.718 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:42:35.534Z,1565797355.534 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154235.54*5B

2019-08-14T15:42:39.224Z,1565797359.224 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:42:39.971Z,1565797359.971 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:42:40.369Z,1565797360.369 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:42:41.198Z,1565797361.198 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154241.21*5A

2019-08-14T15:42:44.857Z,1565797364.857 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:42:45.619Z,1565797365.619 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:42:46.037Z,1565797366.037 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:42:46.857Z,1565797366.857 [Micromodem](INFO): Nmea in: $SNTTA,,,0.268137,,154246.86*47

2019-08-14T15:42:50.489Z,1565797370.489 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:42:51.287Z,1565797371.287 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:42:51.693Z,1565797371.693 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:42:52.508Z,1565797372.508 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154252.52*5C

2019-08-14T15:42:56.969Z,1565797376.969 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:42:57.347Z,1565797377.347 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-14T15:42:57.743Z,1565797377.743 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:42:58.153Z,1565797378.153 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:42:58.966Z,1565797378.966 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154258.98*50

2019-08-14T15:43:02.695Z,1565797382.695 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:43:03.399Z,1565797383.399 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:43:03.805Z,1565797383.805 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:43:04.619Z,1565797384.619 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154304.64*5B

2019-08-14T15:43:07.032Z,1565797387.032 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-14T15:43:07.067Z,1565797387.067 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:43:07.471Z,1565797387.471 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:43:07.938Z,1565797387.938 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:43:08.651Z,1565797388.651 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154308.71*53

2019-08-14T15:43:11.114Z,1565797391.114 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-14T15:43:11.180Z,1565797391.180 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:43:11.903Z,1565797391.903 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:43:12.285Z,1565797392.285 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:43:13.102Z,1565797393.102 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154313.14*5A

2019-08-14T15:43:15.910Z,1565797395.910 [CommandLine](IMPORTANT): got command stop
2019-08-14T15:43:15.911Z,1565797395.911 [CommandLine](IMPORTANT): Scheduling is paused
2019-08-14T15:43:15.911Z,1565797395.911 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-08-14T15:43:15.984Z,1565797395.984 [MissionManager](INFO): MissionManager is completed.
2019-08-14T15:43:15.985Z,1565797395.985 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL] Stopped
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:A.Pitch] Stopped
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:B.SetSpeed] Stopped
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:C.] Stopped
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:RequestRepeater] Stopped
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-08-14T15:43:15.985Z,1565797395.985 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:43:16.371Z,1565797396.371 [MissionManager](IMPORTANT): Started mission Default
2019-08-14T15:43:16.372Z,1565797396.372 [Default] Running Loop=1
2019-08-14T15:43:16.372Z,1565797396.372 [Default](DEBUG): Aggregate::initialize Default
2019-08-14T15:43:16.372Z,1565797396.372 [Default:B.GoToSurface] Running Loop=1
2019-08-14T15:43:16.372Z,1565797396.372 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-14T15:43:16.372Z,1565797396.372 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-14T15:43:16.373Z,1565797396.373 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-14T15:43:16.373Z,1565797396.373 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-14T15:43:16.373Z,1565797396.373 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-14T15:43:16.374Z,1565797396.374 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-14T15:43:16.374Z,1565797396.374 [Default:A.Wait] Running Loop=1
2019-08-14T15:43:16.374Z,1565797396.374 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:43:29.701Z,1565797409.701 [Default:A.Wait](INFO): Done Waiting.
2019-08-14T15:43:29.702Z,1565797409.702 [Default:A.Wait] Stopped
2019-08-14T15:43:29.702Z,1565797409.702 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:43:30.123Z,1565797410.123 [Default:CheckIn] Running Loop=1
2019-08-14T15:43:30.123Z,1565797410.123 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-14T15:43:30.124Z,1565797410.124 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-14T15:43:31.693Z,1565797411.693 [NAL9602](DEBUG): Fix Requested
2019-08-14T15:43:32.086Z,1565797412.086 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,153951.00,A,3648.17240,N,12147.28029,W,0.097,184.48,140819,,,A*75
2019-08-14T15:43:32.089Z,1565797412.089 [NAL9602](INFO): GPS fix at 20190814T153951: (36.802873, -121.788005)
2019-08-14T15:43:32.122Z,1565797412.122 [Default:CheckIn:Read_GPS] Stopped
2019-08-14T15:43:32.123Z,1565797412.123 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-14T15:43:35.753Z,1565797415.753 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-08-14T15:43:37.756Z,1565797417.756 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190814T153822/Courier0007.lzma
2019-08-14T15:43:38.562Z,1565797418.562 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Courier0007.lzma.bak
2019-08-14T15:43:38.562Z,1565797418.562 [DataOverHttps](INFO): SBD MOMSN=11569527
2019-08-14T15:43:47.077Z,1565797427.077 [NAL9602](INFO): SBD MO Status=2, MOMSN=8395, MT Status=2, MTMSN=0
2019-08-14T15:43:47.077Z,1565797427.077 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-14T15:43:50.517Z,1565797430.517 [DataOverHttps](INFO): Sending 329 bytes from file Logs/20190814T153822/Express0005.lzma
2019-08-14T15:43:51.322Z,1565797431.322 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Express0005.lzma.bak
2019-08-14T15:43:51.322Z,1565797431.322 [DataOverHttps](INFO): SBD MOMSN=11569531
2019-08-14T15:44:03.365Z,1565797443.365 [DataOverHttps](INFO): Sending 345 bytes from file Logs/20190814T153822/Express0008.lzma
2019-08-14T15:44:04.170Z,1565797444.170 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Express0008.lzma.bak
2019-08-14T15:44:04.170Z,1565797444.170 [DataOverHttps](INFO): SBD MOMSN=11569539
2019-08-14T15:44:04.927Z,1565797444.927 [Default:CheckIn:Read_Iridium] Stopped
2019-08-14T15:44:04.928Z,1565797444.928 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-14T15:44:04.928Z,1565797444.928 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:44:35.378Z,1565797475.378 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.verbosity 4.000000 count
2019-08-14T15:44:40.258Z,1565797480.258 [CommandLine](IMPORTANT): got command run ./Missions/DUSBL_Tracking.xml
2019-08-14T15:44:40.259Z,1565797480.259 [MissionManager](INFO): Loading Mission: ./Missions/DUSBL_Tracking.xml
2019-08-14T15:44:40.281Z,1565797480.281 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-08-14T15:44:40.283Z,1565797480.283 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-08-14T15:44:40.286Z,1565797480.286 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-08-14T15:44:40.288Z,1565797480.288 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-08-14T15:44:40.291Z,1565797480.291 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-08-14T15:44:40.292Z,1565797480.292 [DUSBL:A.Pitch](DEBUG): Construct.
2019-08-14T15:44:40.296Z,1565797480.296 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-08-14T15:44:40.309Z,1565797480.309 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-08-14T15:44:40.313Z,1565797480.313 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</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>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-08-14T15:44:40.315Z,1565797480.315 [CommandLine](IMPORTANT): Running ./Missions/DUSBL_Tracking.xml
2019-08-14T15:44:40.420Z,1565797480.420 [Default] Stopped
2019-08-14T15:44:40.420Z,1565797480.420 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-14T15:44:40.420Z,1565797480.420 [Default:B.GoToSurface] Stopped
2019-08-14T15:44:40.420Z,1565797480.420 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-14T15:44:40.420Z,1565797480.420 [Default:CheckIn] Stopped
2019-08-14T15:44:40.420Z,1565797480.420 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-14T15:44:40.427Z,1565797480.427 [Default:CheckIn:C.Wait] Stopped
2019-08-14T15:44:40.427Z,1565797480.427 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:44:40.427Z,1565797480.427 [MissionManager](IMPORTANT): Started mission DUSBL
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL] Running Loop=1
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL:A.Pitch] Running Loop=1
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL:C.] Running Loop=1
2019-08-14T15:44:40.428Z,1565797480.428 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-08-14T15:44:40.433Z,1565797480.433 [DUSBL:RequestRepeater] Running Loop=1
2019-08-14T15:44:40.433Z,1565797480.433 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-08-14T15:44:40.433Z,1565797480.433 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-08-14T15:44:40.433Z,1565797480.433 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:44:40.433Z,1565797480.433 [DUSBL:C.] Running Loop=1
2019-08-14T15:44:40.434Z,1565797480.434 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-14T15:44:40.434Z,1565797480.434 [DUSBL:A.Pitch] Running Loop=1
2019-08-14T15:44:44.460Z,1565797484.460 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:44:44.842Z,1565797484.842 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-14T15:44:44.842Z,1565797484.842 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-14T15:44:44.842Z,1565797484.842 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-08-14T15:44:44.843Z,1565797484.843 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-14T15:44:45.242Z,1565797485.242 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
002,000,00F0F,183,80,80,3D,FF
2019-08-14T15:44:45.242Z,1565797485.242 [DUSBL_Hydroid](INFO): Command Ack
2019-08-14T15:44:45.242Z,1565797485.242 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-14T15:44:45.244Z,1565797485.244 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:44:45.653Z,1565797485.653 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:44:46.050Z,1565797486.050 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,F7B,000,002D9,187,80,80,0E,FF
2019-08-14T15:44:46.050Z,1565797486.050 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-08-14T15:44:46.157Z,1565797486.157 [Reporter](INFO): acoustic_contact_range 6.240000 m
2019-08-14T15:44:46.481Z,1565797486.481 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154446.48*54

2019-08-14T15:44:50.204Z,1565797490.204 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:44:50.497Z,1565797490.497 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-14T15:44:50.497Z,1565797490.497 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-14T15:44:50.498Z,1565797490.498 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-08-14T15:44:50.498Z,1565797490.498 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-14T15:44:50.906Z,1565797490.906 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
F7B,000,002D9,187,80,80,0E,FF
2019-08-14T15:44:50.906Z,1565797490.906 [DUSBL_Hydroid](INFO): Command Ack
2019-08-14T15:44:50.906Z,1565797490.906 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-14T15:44:50.907Z,1565797490.907 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:44:51.309Z,1565797491.309 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:44:51.323Z,1565797491.323 [NAL9602](INFO): SBD MO Status=2, MOMSN=8395, MT Status=2, MTMSN=0
2019-08-14T15:44:51.323Z,1565797491.323 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-14T15:44:52.115Z,1565797492.115 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154452.14*58

2019-08-14T15:44:54.538Z,1565797494.538 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,61,E4
9,187,80,80,0E,FF
2019-08-14T15:44:54.538Z,1565797494.538 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,61,E4
9,187,80,80,0E,FF
2019-08-14T15:44:54.538Z,1565797494.538 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-14T15:44:54.563Z,1565797494.563 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:44:54.937Z,1565797494.937 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-14T15:44:54.938Z,1565797494.938 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-14T15:44:54.938Z,1565797494.938 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-08-14T15:44:54.939Z,1565797494.939 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-14T15:44:55.342Z,1565797495.342 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,61,E4
9,187,80,80,0E,FF
2019-08-14T15:44:55.342Z,1565797495.342 [DUSBL_Hydroid](INFO): Command Ack
2019-08-14T15:44:55.342Z,1565797495.342 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-14T15:44:55.344Z,1565797495.344 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:44:55.749Z,1565797495.749 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:44:56.559Z,1565797496.559 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154456.58*54

2019-08-14T15:44:58.610Z,1565797498.610 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:44:58.978Z,1565797498.978 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,61,E4
9,187,80,80,0E,FF
2019-08-14T15:44:58.978Z,1565797498.978 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,61,E4
9,187,80,80,0E,FF
2019-08-14T15:44:58.978Z,1565797498.978 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-14T15:45:02.674Z,1565797502.674 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:45:03.021Z,1565797503.021 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-14T15:45:03.022Z,1565797503.022 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-14T15:45:03.022Z,1565797503.022 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-08-14T15:45:03.023Z,1565797503.023 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-14T15:45:03.426Z,1565797503.426 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,61,E4
9,187,80,80,0E,FF
2019-08-14T15:45:03.426Z,1565797503.426 [DUSBL_Hydroid](INFO): Command Ack
2019-08-14T15:45:03.426Z,1565797503.426 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-14T15:45:03.427Z,1565797503.427 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:45:03.831Z,1565797503.831 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:45:03.921Z,1565797503.921 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-08-14T15:45:03.921Z,1565797503.921 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,    +3,    +1, 

2019-08-14T15:45:04.234Z,1565797504.234 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,F81,000,002D9,187,80,80,0E,FF
2019-08-14T15:45:04.234Z,1565797504.234 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-08-14T15:45:04.292Z,1565797504.292 [Reporter](INFO): acoustic_contact_range 6.240000 m
2019-08-14T15:45:04.650Z,1565797504.650 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154504.67*5E

2019-08-14T15:45:08.305Z,1565797508.305 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:45:08.677Z,1565797508.677 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-14T15:45:08.678Z,1565797508.678 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-14T15:45:08.678Z,1565797508.678 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-08-14T15:45:08.679Z,1565797508.679 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-14T15:45:09.094Z,1565797509.094 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
F81,000,002D9,187,80,80,0E,FF
2019-08-14T15:45:09.094Z,1565797509.094 [DUSBL_Hydroid](INFO): Command Ack
2019-08-14T15:45:09.094Z,1565797509.094 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-14T15:45:09.095Z,1565797509.095 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:45:09.239Z,1565797509.239 [CommandLine](IMPORTANT): got command stop
2019-08-14T15:45:09.239Z,1565797509.239 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-08-14T15:45:09.485Z,1565797509.485 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:45:09.554Z,1565797509.554 [MissionManager](INFO): MissionManager is completed.
2019-08-14T15:45:09.554Z,1565797509.554 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-08-14T15:45:09.554Z,1565797509.554 [DUSBL] Stopped
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:A.Pitch] Stopped
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:B.SetSpeed] Stopped
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:C.] Stopped
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:RequestRepeater] Stopped
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-08-14T15:45:09.555Z,1565797509.555 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:45:09.951Z,1565797509.951 [MissionManager](IMPORTANT): Started mission Default
2019-08-14T15:45:09.952Z,1565797509.952 [Default] Running Loop=1
2019-08-14T15:45:09.952Z,1565797509.952 [Default](DEBUG): Aggregate::initialize Default
2019-08-14T15:45:09.952Z,1565797509.952 [Default:B.GoToSurface] Running Loop=1
2019-08-14T15:45:09.952Z,1565797509.952 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-14T15:45:09.952Z,1565797509.952 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-14T15:45:09.953Z,1565797509.953 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-14T15:45:09.953Z,1565797509.953 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-14T15:45:09.953Z,1565797509.953 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-14T15:45:09.954Z,1565797509.954 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-14T15:45:09.954Z,1565797509.954 [Default:A.Wait] Running Loop=1
2019-08-14T15:45:09.954Z,1565797509.954 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:45:10.295Z,1565797510.295 [Micromodem](INFO): Nmea in: $SNTTA,,,,,154510.33*5A

2019-08-14T15:45:23.253Z,1565797523.253 [Default:A.Wait](INFO): Done Waiting.
2019-08-14T15:45:23.253Z,1565797523.253 [Default:A.Wait] Stopped
2019-08-14T15:45:23.253Z,1565797523.253 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:45:23.652Z,1565797523.652 [Default:CheckIn] Running Loop=1
2019-08-14T15:45:23.652Z,1565797523.652 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-14T15:45:23.652Z,1565797523.652 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-14T15:45:57.187Z,1565797557.187 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-08-14T15:45:57.190Z,1565797557.190 [BPC1](INFO): Received data from all battery sticks.
2019-08-14T15:48:33.918Z,1565797713.918 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-14T15:48:34.737Z,1565797714.737 [NAL9602](DEBUG): Fix Requested
2019-08-14T15:48:39.585Z,1565797719.585 [NAL9602](DEBUG): Fix Requested
2019-08-14T15:48:39.972Z,1565797719.972 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,154459.00,A,3648.17063,N,12147.28422,W,0.486,184.48,140819,,,A*7F
2019-08-14T15:48:39.975Z,1565797719.975 [NAL9602](INFO): GPS fix at 20190814T154459: (36.802844, -121.788070)
2019-08-14T15:48:40.008Z,1565797720.008 [Default:CheckIn:Read_GPS] Stopped
2019-08-14T15:48:40.008Z,1565797720.008 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-14T15:48:45.263Z,1565797725.263 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20190814T153822/Courier0010.lzma
2019-08-14T15:48:46.054Z,1565797726.054 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Courier0010.lzma.bak
2019-08-14T15:48:46.054Z,1565797726.054 [DataOverHttps](INFO): SBD MOMSN=11569569
2019-08-14T15:48:57.603Z,1565797737.603 [DataOverHttps](INFO): Sending 364 bytes from file Logs/20190814T153822/Express0011.lzma
2019-08-14T15:48:58.403Z,1565797738.403 [DataOverHttps](INFO): Moved sent file to Logs/20190814T153822/Express0011.lzma.bak
2019-08-14T15:48:58.403Z,1565797738.403 [DataOverHttps](INFO): SBD MOMSN=11569573
2019-08-14T15:48:59.404Z,1565797739.404 [Default:CheckIn:Read_Iridium] Stopped
2019-08-14T15:48:59.404Z,1565797739.404 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-14T15:48:59.404Z,1565797739.404 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:49:12.303Z,1565797752.303 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-14T15:51:07.079Z,1565797867.079 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-08-14T15:52:40.387Z,1565797960.387 [Micromodem](INFO): Nmea in: 155241,COPROC,0.10.0.46*46

2019-08-14T15:52:40.387Z,1565797960.387 [Micromodem](ERROR): Response from modem failed NMEA checksum: 155241,COPROC,0.10.0.46*46
 expected 0
2019-08-14T15:53:33.338Z,1565798013.338 [CBIT](INFO): Clearing failed state for component DropWeight
2019-08-14T15:53:33.338Z,1565798013.338 [DropWeight] No Fault, FailCount= 1
2019-08-14T15:54:00.003Z,1565798040.003 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-14T15:54:00.004Z,1565798040.004 [Default:CheckIn:C.Wait] Stopped
2019-08-14T15:54:00.004Z,1565798040.004 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:54:00.004Z,1565798040.004 [Default:CheckIn:D] Running Loop=1
2019-08-14T15:54:00.408Z,1565798040.408 [Default:CheckIn:D] Stopped
2019-08-14T15:54:00.408Z,1565798040.408 [Default:CheckIn:E] Running Loop=1
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.840932 min 
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn:E] Stopped
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn] Stopped
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn](INFO): Running loop #2
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn] Running Loop=2
2019-08-14T15:54:00.817Z,1565798040.817 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-14T15:54:00.818Z,1565798040.818 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-14T15:54:02.416Z,1565798042.416 [NAL9602](DEBUG): Fix Requested
2019-08-14T15:54:02.799Z,1565798042.799 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,155022.00,A,3648.15872,N,12147.27722,W,0.019,184.48,140819,,,A*72
2019-08-14T15:54:02.801Z,1565798042.801 [NAL9602](INFO): GPS fix at 20190814T155022: (36.802645, -121.787954)
2019-08-14T15:54:02.868Z,1565798042.868 [Default:CheckIn:Read_GPS] Stopped
2019-08-14T15:54:02.868Z,1565798042.868 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-14T15:54:03.053Z,1565798043.053 [CommandLine](IMPORTANT): got command run ./Missions/DUSBL_Tracking.xml
2019-08-14T15:54:03.054Z,1565798043.054 [MissionManager](INFO): Loading Mission: ./Missions/DUSBL_Tracking.xml
2019-08-14T15:54:03.079Z,1565798043.079 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-08-14T15:54:03.081Z,1565798043.081 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-08-14T15:54:03.083Z,1565798043.083 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-08-14T15:54:03.085Z,1565798043.085 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-08-14T15:54:03.087Z,1565798043.087 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-08-14T15:54:03.088Z,1565798043.088 [DUSBL:A.Pitch](DEBUG): Construct.
2019-08-14T15:54:03.092Z,1565798043.092 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-08-14T15:54:03.105Z,1565798043.105 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-08-14T15:54:03.108Z,1565798043.108 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</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>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-08-14T15:54:03.110Z,1565798043.110 [CommandLine](IMPORTANT): Running ./Missions/DUSBL_Tracking.xml
2019-08-14T15:54:03.254Z,1565798043.254 [Default] Stopped
2019-08-14T15:54:03.254Z,1565798043.254 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-14T15:54:03.254Z,1565798043.254 [Default:B.GoToSurface] Stopped
2019-08-14T15:54:03.254Z,1565798043.254 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-14T15:54:03.254Z,1565798043.254 [Default:CheckIn] Stopped
2019-08-14T15:54:03.254Z,1565798043.254 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-14T15:54:03.255Z,1565798043.255 [Default:CheckIn:Read_Iridium] Stopped
2019-08-14T15:54:03.255Z,1565798043.255 [MissionManager](IMPORTANT): Started mission DUSBL
2019-08-14T15:54:03.255Z,1565798043.255 [DUSBL] Running Loop=1
2019-08-14T15:54:03.255Z,1565798043.255 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-08-14T15:54:03.255Z,1565798043.255 [DUSBL:A.Pitch] Running Loop=1
2019-08-14T15:54:03.255Z,1565798043.255 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-08-14T15:54:03.255Z,1565798043.255 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-14T15:54:03.255Z,1565798043.255 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-08-14T15:54:03.256Z,1565798043.256 [DUSBL:C.] Running Loop=1
2019-08-14T15:54:03.256Z,1565798043.256 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-08-14T15:54:03.256Z,1565798043.256 [DUSBL:RequestRepeater] Running Loop=1
2019-08-14T15:54:03.256Z,1565798043.256 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-08-14T15:54:03.256Z,1565798043.256 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-08-14T15:54:03.256Z,1565798043.256 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:54:03.261Z,1565798043.261 [DUSBL:C.] Running Loop=1
2019-08-14T15:54:03.261Z,1565798043.261 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-14T15:54:03.261Z,1565798043.261 [DUSBL:A.Pitch] Running Loop=1
2019-08-14T15:54:04.841Z,1565798044.841 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:536.162292
2019-08-14T15:54:07.276Z,1565798047.276 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:54:07.646Z,1565798047.646 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-14T15:54:07.646Z,1565798047.646 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-14T15:54:07.646Z,1565798047.646 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-08-14T15:54:07.647Z,1565798047.647 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-14T15:54:08.051Z,1565798048.051 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
F81,000,002D9,187,80,80,0E,FF
2019-08-14T15:54:08.051Z,1565798048.051 [DUSBL_Hydroid](INFO): Command Ack
2019-08-14T15:54:08.052Z,1565798048.052 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-14T15:54:08.053Z,1565798048.053 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:54:08.457Z,1565798048.457 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:54:08.876Z,1565798048.876 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,001,000,00290,182,80,80,3E,FF
2019-08-14T15:54:08.878Z,1565798048.878 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-08-14T15:54:08.958Z,1565798048.958 [Reporter](INFO): acoustic_contact_range 1.860000 m
2019-08-14T15:54:09.278Z,1565798049.278 [Micromodem](INFO): Nmea in: $SNTTA,,,,,155409.29*59

2019-08-14T15:54:13.327Z,1565798053.327 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-14T15:54:13.706Z,1565798053.706 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-08-14T15:54:13.706Z,1565798053.706 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-08-14T15:54:13.706Z,1565798053.706 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-08-14T15:54:13.707Z,1565798053.707 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-08-14T15:54:14.114Z,1565798054.114 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
001,000,00290,182,80,80,3E,FF
2019-08-14T15:54:14.114Z,1565798054.114 [DUSBL_Hydroid](INFO): Command Ack
2019-08-14T15:54:14.114Z,1565798054.114 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-08-14T15:54:14.116Z,1565798054.116 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-14T15:54:14.271Z,1565798054.271 [CommandLine](IMPORTANT): got command stop
2019-08-14T15:54:14.271Z,1565798054.271 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-08-14T15:54:14.513Z,1565798054.513 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-14T15:54:14.572Z,1565798054.572 [MissionManager](INFO): MissionManager is completed.
2019-08-14T15:54:14.572Z,1565798054.572 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-08-14T15:54:14.572Z,1565798054.572 [DUSBL] Stopped
2019-08-14T15:54:14.572Z,1565798054.572 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-08-14T15:54:14.572Z,1565798054.572 [DUSBL:A.Pitch] Stopped
2019-08-14T15:54:14.572Z,1565798054.572 [DUSBL:B.SetSpeed] Stopped
2019-08-14T15:54:14.572Z,1565798054.572 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-08-14T15:54:14.576Z,1565798054.576 [DUSBL:C.] Stopped
2019-08-14T15:54:14.577Z,1565798054.577 [DUSBL:RequestRepeater] Stopped
2019-08-14T15:54:14.577Z,1565798054.577 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-08-14T15:54:14.577Z,1565798054.577 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-08-14T15:54:14.577Z,1565798054.577 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-14T15:54:14.966Z,1565798054.966 [MissionManager](IMPORTANT): Started mission Default
2019-08-14T15:54:14.966Z,1565798054.966 [Default] Running Loop=1
2019-08-14T15:54:14.966Z,1565798054.966 [Default](DEBUG): Aggregate::initialize Default
2019-08-14T15:54:14.966Z,1565798054.966 [Default:B.GoToSurface] Running Loop=1
2019-08-14T15:54:14.966Z,1565798054.966 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-14T15:54:14.967Z,1565798054.967 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-14T15:54:14.967Z,1565798054.967 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-14T15:54:14.967Z,1565798054.967 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-14T15:54:14.968Z,1565798054.968 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-14T15:54:14.968Z,1565798054.968 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-14T15:54:14.968Z,1565798054.968 [Default:A.Wait] Running Loop=1
2019-08-14T15:54:14.968Z,1565798054.968 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-14T15:54:15.323Z,1565798055.323 [Micromodem](INFO): Nmea in: $SNTTA,,,,,155415.35*59