2019-08-13T03:39:08.136Z,1565667548.136 [Supervisor](DEBUG): Initializing supervisor.
2019-08-13T03:39:08.139Z,1565667548.139 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-08-13T03:39:08.139Z,1565667548.139 [SyncHandler](INFO): Protected caller Thread ID is 9645
2019-08-13T03:39:08.140Z,1565667548.140 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-08-13T03:39:08.141Z,1565667548.141 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-08-13T03:39:08.141Z,1565667548.141 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 9646
2019-08-13T03:39:08.144Z,1565667548.144 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-08-13T03:39:08.156Z,1565667548.156 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-08-13T03:39:08.157Z,1565667548.157 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-08-13T03:39:08.157Z,1565667548.157 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 9647
2019-08-13T03:39:08.158Z,1565667548.158 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-08-13T03:39:08.159Z,1565667548.159 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-08-13T03:39:08.159Z,1565667548.159 [logger ThreadHandler](INFO): Protected caller Thread ID is 9648
2019-08-13T03:39:08.161Z,1565667548.161 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-08-13T03:39:08.161Z,1565667548.161 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-08-13T03:39:08.163Z,1565667548.163 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-08-13T03:39:08.635Z,1565667548.635 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-08-13T03:39:08.636Z,1565667548.636 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-08-13T03:39:08.735Z,1565667548.735 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-08-13T03:39:08.736Z,1565667548.736 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-08-13T03:39:09.056Z,1565667549.056 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-08-13T03:39:09.057Z,1565667549.057 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-08-13T03:39:09.198Z,1565667549.198 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-08-13T03:39:09.199Z,1565667549.199 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-08-13T03:39:09.393Z,1565667549.393 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-08-13T03:39:09.394Z,1565667549.394 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-08-13T03:39:09.842Z,1565667549.842 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-08-13T03:39:09.843Z,1565667549.843 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-08-13T03:39:10.051Z,1565667550.051 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-08-13T03:39:10.052Z,1565667550.052 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-08-13T03:39:10.198Z,1565667550.198 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-08-13T03:39:10.198Z,1565667550.198 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-08-13T03:39:10.411Z,1565667550.411 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-08-13T03:39:10.412Z,1565667550.412 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-08-13T03:39:10.574Z,1565667550.574 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-08-13T03:39:10.575Z,1565667550.575 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-08-13T03:39:10.879Z,1565667550.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-08-13T03:39:10.880Z,1565667550.880 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-08-13T03:39:10.962Z,1565667550.962 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-08-13T03:39:11.066Z,1565667551.066 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-08-13T03:39:11.067Z,1565667551.067 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-08-13T03:39:11.659Z,1565667551.659 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-08-13T03:39:11.660Z,1565667551.660 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-08-13T03:39:12.208Z,1565667552.208 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-08-13T03:39:12.210Z,1565667552.210 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-08-13T03:39:12.211Z,1565667552.211 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-08-13T03:39:12.909Z,1565667552.909 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-08-13T03:39:13.571Z,1565667553.571 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-08-13T03:39:13.720Z,1565667553.720 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-08-13T03:39:14.147Z,1565667554.147 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-08-13T03:39:14.147Z,1565667554.147 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-08-13T03:39:14.289Z,1565667554.289 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-08-13T03:39:14.440Z,1565667554.440 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-08-13T03:39:14.609Z,1565667554.609 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-08-13T03:39:14.746Z,1565667554.746 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-08-13T03:39:14.957Z,1565667554.957 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-08-13T03:39:15.344Z,1565667555.344 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-08-13T03:39:15.636Z,1565667555.636 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-08-13T03:39:15.636Z,1565667555.636 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-08-13T03:39:15.648Z,1565667555.648 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-08-13T03:39:16.270Z,1565667556.270 [AHRS_M2] Loaded
2019-08-13T03:39:16.270Z,1565667556.270 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-08-13T03:39:16.459Z,1565667556.459 [DataOverHttps] Loaded
2019-08-13T03:39:16.459Z,1565667556.459 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-08-13T03:39:16.476Z,1565667556.476 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407664E0
2019-08-13T03:39:16.477Z,1565667556.477 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 9733
2019-08-13T03:39:16.495Z,1565667556.495 [Depth_Keller] Loaded
2019-08-13T03:39:16.495Z,1565667556.495 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-08-13T03:39:16.500Z,1565667556.500 [DropWeight] Loaded
2019-08-13T03:39:16.500Z,1565667556.500 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-08-13T03:39:16.565Z,1565667556.565 [DUSBL_Hydroid] Loaded
2019-08-13T03:39:16.565Z,1565667556.565 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-08-13T03:39:16.613Z,1565667556.613 [Micromodem] Loaded
2019-08-13T03:39:16.613Z,1565667556.613 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-08-13T03:39:16.712Z,1565667556.712 [NAL9602] Loaded
2019-08-13T03:39:16.712Z,1565667556.712 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-08-13T03:39:16.728Z,1565667556.728 [Onboard] Loaded
2019-08-13T03:39:16.729Z,1565667556.729 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-08-13T03:39:16.734Z,1565667556.734 [PowerOnly] Loaded
2019-08-13T03:39:16.735Z,1565667556.735 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-08-13T03:39:16.741Z,1565667556.741 [Radio_Surface] Loaded
2019-08-13T03:39:16.741Z,1565667556.741 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-08-13T03:39:16.742Z,1565667556.742 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407964E0
2019-08-13T03:39:16.743Z,1565667556.743 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 9734
2019-08-13T03:39:16.787Z,1565667556.787 [RDI_Pathfinder] Loaded
2019-08-13T03:39:16.787Z,1565667556.787 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-08-13T03:39:18.634Z,1565667558.634 [BPC1] Loaded
2019-08-13T03:39:18.634Z,1565667558.634 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-08-13T03:39:18.635Z,1565667558.635 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-08-13T03:39:18.635Z,1565667558.635 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-08-13T03:39:18.659Z,1565667558.659 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-08-13T03:39:18.659Z,1565667558.659 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-08-13T03:39:18.781Z,1565667558.781 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-08-13T03:39:18.781Z,1565667558.781 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-08-13T03:39:18.801Z,1565667558.801 [NavChart] Loaded
2019-08-13T03:39:18.801Z,1565667558.801 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-08-13T03:39:18.805Z,1565667558.805 [UniversalFixResidualReporter] Loaded
2019-08-13T03:39:18.805Z,1565667558.805 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-08-13T03:39:18.806Z,1565667558.806 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-08-13T03:39:18.806Z,1565667558.806 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-08-13T03:39:18.935Z,1565667558.935 [BuoyancyServo] Loaded
2019-08-13T03:39:18.935Z,1565667558.935 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-08-13T03:39:18.950Z,1565667558.950 [ElevatorServo] Loaded
2019-08-13T03:39:18.951Z,1565667558.951 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-08-13T03:39:18.966Z,1565667558.966 [MassServo] Loaded
2019-08-13T03:39:18.966Z,1565667558.966 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-08-13T03:39:18.981Z,1565667558.981 [RudderServo] Loaded
2019-08-13T03:39:18.981Z,1565667558.981 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-08-13T03:39:18.995Z,1565667558.995 [ThrusterServo] Loaded
2019-08-13T03:39:18.996Z,1565667558.996 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-08-13T03:39:18.996Z,1565667558.996 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-08-13T03:39:18.997Z,1565667558.997 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-08-13T03:39:19.318Z,1565667559.318 [CTD_NeilBrown] Loaded
2019-08-13T03:39:19.318Z,1565667559.318 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-08-13T03:39:19.319Z,1565667559.319 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E14E0
2019-08-13T03:39:19.320Z,1565667559.320 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 9735
2019-08-13T03:39:19.349Z,1565667559.349 [ESPComponent] Loaded
2019-08-13T03:39:19.349Z,1565667559.349 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-08-13T03:39:19.393Z,1565667559.393 [WetLabsSeaOWL_UV_A] Loaded
2019-08-13T03:39:19.393Z,1565667559.393 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-08-13T03:39:19.394Z,1565667559.394 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409114E0
2019-08-13T03:39:19.394Z,1565667559.394 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 9736
2019-08-13T03:39:19.395Z,1565667559.395 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-08-13T03:39:19.395Z,1565667559.395 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-08-13T03:39:19.729Z,1565667559.729 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-08-13T03:39:19.730Z,1565667559.730 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-08-13T03:39:19.785Z,1565667559.785 [DepthRateCalculator] Loaded
2019-08-13T03:39:19.785Z,1565667559.785 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-08-13T03:39:19.791Z,1565667559.791 [PitchRateCalculator] Loaded
2019-08-13T03:39:19.791Z,1565667559.791 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-08-13T03:39:19.803Z,1565667559.803 [SpeedCalculator] Loaded
2019-08-13T03:39:19.803Z,1565667559.803 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-08-13T03:39:19.824Z,1565667559.824 [TempGradientCalculator] Loaded
2019-08-13T03:39:19.825Z,1565667559.825 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-08-13T03:39:19.830Z,1565667559.830 [YawRateCalculator] Loaded
2019-08-13T03:39:19.830Z,1565667559.830 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-08-13T03:39:19.870Z,1565667559.870 [ElevatorOffsetCalculator] Loaded
2019-08-13T03:39:19.870Z,1565667559.870 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-08-13T03:39:19.870Z,1565667559.870 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-08-13T03:39:19.871Z,1565667559.871 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-08-13T03:39:20.030Z,1565667560.030 [SBIT](DEBUG): Construct Startup Built In Test.
2019-08-13T03:39:20.052Z,1565667560.052 [SBIT] Loaded
2019-08-13T03:39:20.052Z,1565667560.052 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-08-13T03:39:20.053Z,1565667560.053 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-08-13T03:39:20.065Z,1565667560.065 [IBIT] Loaded
2019-08-13T03:39:20.065Z,1565667560.065 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-08-13T03:39:20.068Z,1565667560.068 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-08-13T03:39:20.204Z,1565667560.204 [CBIT] Loaded
2019-08-13T03:39:20.204Z,1565667560.204 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-08-13T03:39:20.204Z,1565667560.204 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-08-13T03:39:20.205Z,1565667560.205 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-08-13T03:39:20.326Z,1565667560.326 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-08-13T03:39:20.327Z,1565667560.327 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-08-13T03:39:20.452Z,1565667560.452 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-08-13T03:39:20.453Z,1565667560.453 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-08-13T03:39:20.541Z,1565667560.541 [VerticalControl](DEBUG): Construct VerticalControl.
2019-08-13T03:39:20.623Z,1565667560.623 [VerticalControl] Loaded
2019-08-13T03:39:20.624Z,1565667560.624 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-08-13T03:39:20.624Z,1565667560.624 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-08-13T03:39:20.680Z,1565667560.680 [HorizontalControl] Loaded
2019-08-13T03:39:20.681Z,1565667560.681 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-08-13T03:39:20.681Z,1565667560.681 [SpeedControl](DEBUG): Construct SpeedControl.
2019-08-13T03:39:20.683Z,1565667560.683 [SpeedControl] Loaded
2019-08-13T03:39:20.683Z,1565667560.683 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-08-13T03:39:20.684Z,1565667560.684 [LoopControl](DEBUG): Construct LoopControl.
2019-08-13T03:39:20.685Z,1565667560.685 [LoopControl] Loaded
2019-08-13T03:39:20.685Z,1565667560.685 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-08-13T03:39:20.685Z,1565667560.685 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-08-13T03:39:20.686Z,1565667560.686 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-08-13T03:39:20.733Z,1565667560.733 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-08-13T03:39:20.737Z,1565667560.737 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-08-13T03:39:20.737Z,1565667560.737 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-08-13T03:39:20.744Z,1565667560.744 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-08-13T03:39:20.745Z,1565667560.745 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AED4E0
2019-08-13T03:39:20.746Z,1565667560.746 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 9737
2019-08-13T03:39:20.750Z,1565667560.750 [Supervisor](INFO): Main Thread ID is 9644
2019-08-13T03:39:20.750Z,1565667560.750 [Supervisor](DEBUG): Running supervisor.
2019-08-13T03:39:20.751Z,1565667560.751 [CommandLine ThreadHandler](INFO): Handler Thread ID is 9738
2019-08-13T03:39:20.754Z,1565667560.754 [controlThread ThreadHandler](INFO): Handler Thread ID is 9739
2019-08-13T03:39:20.754Z,1565667560.754 [controlThread](DEBUG): Initializing ControlThread
2019-08-13T03:39:20.760Z,1565667560.760 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-08-13T03:39:20.760Z,1565667560.760 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-08-13T03:39:20.761Z,1565667560.761 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-08-13T03:39:20.762Z,1565667560.762 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-08-13T03:39:20.762Z,1565667560.762 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-08-13T03:39:20.762Z,1565667560.762 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-08-13T03:39:20.763Z,1565667560.763 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-08-13T03:39:20.763Z,1565667560.763 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-08-13T03:39:20.764Z,1565667560.764 [SBIT](INFO): Initialize SBIT Component.
2019-08-13T03:39:20.765Z,1565667560.765 [SBIT](IMPORTANT): git: 2019-07-16A-7-g200b843
2019-08-13T03:39:20.765Z,1565667560.765 [SBIT](INFO): git hash: 200b84367a0203c27138cd5fcf606fd584607e4c
2019-08-13T03:39:20.765Z,1565667560.765 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-08-13T03:39:20.766Z,1565667560.766 [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-13T03:39:20.767Z,1565667560.767 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-08-13T03:39:20.768Z,1565667560.768 [IBIT](INFO): Initialize IBIT Component.
2019-08-13T03:39:20.771Z,1565667560.771 [CBIT](DEBUG): Initialize CBIT Component.
2019-08-13T03:39:20.772Z,1565667560.772 [logger ThreadHandler](INFO): Handler Thread ID is 9740
2019-08-13T03:39:20.784Z,1565667560.784 [CBIT](DEBUG): Initialized mux pins.
2019-08-13T03:39:20.785Z,1565667560.785 [CBIT](DEBUG): Initializing the watchdog timer.
2019-08-13T03:39:20.789Z,1565667560.789 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 9741
2019-08-13T03:39:20.790Z,1565667560.790 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-08-13T03:39:20.797Z,1565667560.797 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 9742
2019-08-13T03:39:20.805Z,1565667560.805 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 9743
2019-08-13T03:39:20.806Z,1565667560.806 [CTD_NeilBrown](INFO): Powering down
2019-08-13T03:39:20.809Z,1565667560.809 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-08-13T03:39:20.809Z,1565667560.809 [CBIT](DEBUG): Initializing heartbeat.
2019-08-13T03:39:20.845Z,1565667560.845 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 9744
2019-08-13T03:39:20.846Z,1565667560.846 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-08-13T03:39:20.873Z,1565667560.873 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 9745
2019-08-13T03:39:20.880Z,1565667560.880 [CBIT](DEBUG): Deactivating GF circuits.
2019-08-13T03:39:20.881Z,1565667560.881 [CBIT](DEBUG): Deactivating emergency mode.
2019-08-13T03:39:20.883Z,1565667560.883 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-08-13T03:39:20.883Z,1565667560.883 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-08-13T03:39:20.883Z,1565667560.883 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-08-13T03:39:20.884Z,1565667560.884 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-08-13T03:39:20.884Z,1565667560.884 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-08-13T03:39:20.884Z,1565667560.884 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-08-13T03:39:20.884Z,1565667560.884 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-08-13T03:39:20.884Z,1565667560.884 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-08-13T03:39:20.885Z,1565667560.885 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-08-13T03:39:20.885Z,1565667560.885 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-08-13T03:39:20.885Z,1565667560.885 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-08-13T03:39:20.885Z,1565667560.885 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-08-13T03:39:20.885Z,1565667560.885 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-08-13T03:39:20.885Z,1565667560.885 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-08-13T03:39:20.886Z,1565667560.886 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-08-13T03:39:20.886Z,1565667560.886 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-08-13T03:39:20.916Z,1565667560.916 [CBIT](DEBUG): Backplane powered.
2019-08-13T03:39:20.917Z,1565667560.917 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-08-13T03:39:20.919Z,1565667560.919 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-08-13T03:39:20.919Z,1565667560.919 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-08-13T03:39:20.920Z,1565667560.920 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-08-13T03:39:20.921Z,1565667560.921 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-08-13T03:39:20.936Z,1565667560.936 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-13T03:39:20.956Z,1565667560.956 [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-13T03:39:20.957Z,1565667560.957 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-08-13T03:39:21.033Z,1565667561.033 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-08-13T03:39:21.035Z,1565667561.035 [Default:A.Wait](DEBUG): Construct Wait.
2019-08-13T03:39:21.036Z,1565667561.036 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-13T03:39:21.067Z,1565667561.067 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-08-13T03:39:21.083Z,1565667561.083 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-08-13T03:39:21.108Z,1565667561.108 [Default:E.Execute](DEBUG): Construct Execute.
2019-08-13T03:39:21.111Z,1565667561.111 [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-13T03:39:21.129Z,1565667561.129 [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-13T03:39:21.135Z,1565667561.135 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-08-13T03:39:21.201Z,1565667561.201 [Radio_Surface](INFO): Powering up
2019-08-13T03:39:21.407Z,1565667561.407 [DUSBL_Hydroid](INFO): Powering up
2019-08-13T03:39:21.407Z,1565667561.407 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-08-13T03:39:21.507Z,1565667561.507 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-13T03:39:21.513Z,1565667561.513 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-13T03:39:21.514Z,1565667561.514 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-08-13T03:39:21.521Z,1565667561.521 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-08-13T03:39:21.522Z,1565667561.522 [MassServo](DEBUG): Initializing EZServoServo.
2019-08-13T03:39:21.529Z,1565667561.529 [MassServo](DEBUG): Initializing MassServo.
2019-08-13T03:39:21.530Z,1565667561.530 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-13T03:39:21.537Z,1565667561.537 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-13T03:39:21.538Z,1565667561.538 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-13T03:39:21.545Z,1565667561.545 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-13T03:39:21.630Z,1565667561.630 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-08-13T03:39:21.630Z,1565667561.630 [DropWeight] Hardware Fault, FailCount= 1
2019-08-13T03:39:21.630Z,1565667561.630 [DropWeight](ERROR): Hardware Fault
2019-08-13T03:39:21.632Z,1565667561.632 [Micromodem](INFO): Powering up
2019-08-13T03:39:21.632Z,1565667561.632 [Micromodem](DEBUG): Initializing Micromodem.
2019-08-13T03:39:21.682Z,1565667561.682 [CommandLine](FAULT): Scheduling is paused
2019-08-13T03:39:21.683Z,1565667561.683 [CBIT](INFO): Critical error at 20190813T033921
2019-08-13T03:39:21.683Z,1565667561.683 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-08-13T03:39:21.686Z,1565667561.686 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-08-13T03:39:21.686Z,1565667561.686 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-08-13T03:39:22.030Z,1565667562.030 [CBIT](INFO): Critical error at 20190813T033921
2019-08-13T03:39:26.453Z,1565667566.453 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-08-13T03:39:26.855Z,1565667566.855 [Micromodem](INFO): Nmea in: $CATMG,2019-08-13T03:39:26.452564Z,RTC,RTC*59

2019-08-13T03:39:26.856Z,1565667566.856 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-08-13T03:39:26.452564Z,RTC,RTC*59

2019-08-13T03:39:27.259Z,1565667567.259 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-08-13T03:39:27.259Z,1565667567.259 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-08-13T03:39:27.651Z,1565667567.651 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-08-13T03:39:27.651Z,1565667567.651 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-08-13T03:39:28.072Z,1565667568.072 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-08-13T03:39:28.072Z,1565667568.072 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-08-13T03:39:28.471Z,1565667568.471 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-08-13T03:39:28.471Z,1565667568.471 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-08-13T03:39:28.875Z,1565667568.875 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-08-13T03:39:28.875Z,1565667568.875 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-08-13T03:39:29.267Z,1565667569.267 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-08-13T03:39:29.267Z,1565667569.267 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-08-13T03:39:29.675Z,1565667569.675 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-08-13T03:39:29.675Z,1565667569.675 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-08-13T03:39:30.067Z,1565667570.067 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-08-13T03:39:30.068Z,1565667570.068 [Micromodem](INFO): Nmea out: $CCCLK,2019,08,13,03,39,31*4F

2019-08-13T03:39:30.493Z,1565667570.493 [Micromodem](INFO): Nmea in: $CACLK,2019,8,13,3,39,31*4D

2019-08-13T03:39:30.494Z,1565667570.494 [Micromodem](INFO): Nmea in: $CATMS,0,2019-08-13T03:39:32Z*7E

2019-08-13T03:39:30.496Z,1565667570.496 [Micromodem](INFO): Nmea in: $CATMG,2019-08-13T03:39:32.028684Z,USER_CMD,RTC*19

2019-08-13T03:39:32.718Z,1565667572.718 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004660
2019-08-13T03:39:34.928Z,1565667574.928 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-08-13T03:39:39.346Z,1565667579.346 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-08-13T03:39:47.035Z,1565667587.035 [NAL9602](INFO): Powering up NAL9602
2019-08-13T03:39:49.529Z,1565667589.529 [SBIT](IMPORTANT): Beginning Startup BIT
2019-08-13T03:39:49.537Z,1565667589.537 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-13T03:39:58.035Z,1565667598.035 [NAL9602](INFO): NAL9602 initialized
2019-08-13T03:39:58.859Z,1565667598.859 [NAL9602](DEBUG): Fix Requested
2019-08-13T03:40:00.541Z,1565667600.541 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010053
CHAN A1 (24V): -0.028191
CHAN A2 (12V): -0.007447
CHAN A3 (5V): -0.002225
CHAN B0 (3.3V): 0.000001
CHAN B1 (3.15aV): 0.000290
CHAN B2 (3.15bV): 0.000214
CHAN B3 (GND): 0.001995
OPEN: 0.004335
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-13T03:40:20.045Z,1565667620.045 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-08-13T03:40:20.045Z,1565667620.045 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   I,-32768,-32768,-32768,-32768,V
2019-08-13T03:40:43.562Z,1565667643.562 [SBIT](IMPORTANT): SBIT PASSED
2019-08-13T03:40:43.633Z,1565667643.633 [CommandLine](IMPORTANT): got command configSet list
2019-08-13T03:40:43.633Z,1565667643.633 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-13T03:40:43.634Z,1565667643.634 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-08-13T03:40:43.634Z,1565667643.634 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-08-13T03:40:43.634Z,1565667643.634 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=10 minute;

2019-08-13T03:40:43.634Z,1565667643.634 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2019-08-13T03:40:43.634Z,1565667643.634 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.acoustic_contact_range 2.000000 meter;

2019-08-13T03:40:43.635Z,1565667643.635 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none;

2019-08-13T03:40:43.635Z,1565667643.635 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree;

2019-08-13T03:40:43.635Z,1565667643.635 [CommandLine](IMPORTANT): Micromodem.surfaceThreshold=2 meter;

2019-08-13T03:40:43.635Z,1565667643.635 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-08-13T03:40:43.998Z,1565667643.998 [MissionManager](IMPORTANT): Started mission Startup
2019-08-13T03:40:43.999Z,1565667643.999 [Startup] Running Loop=1
2019-08-13T03:40:43.999Z,1565667643.999 [Startup](DEBUG): Aggregate::initialize Startup
2019-08-13T03:40:43.999Z,1565667643.999 [Startup:A.GoToSurface] Running Loop=1
2019-08-13T03:40:43.999Z,1565667643.999 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-13T03:40:43.000Z,1565667644.000 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-13T03:40:44.000Z,1565667644.000 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-13T03:40:44.001Z,1565667644.001 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-13T03:40:44.001Z,1565667644.001 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-13T03:40:44.001Z,1565667644.001 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-13T03:40:44.003Z,1565667644.003 [Startup:StartupSatComms] Running Loop=1
2019-08-13T03:40:44.003Z,1565667644.003 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-08-13T03:40:44.004Z,1565667644.004 [Startup:StartupSatComms:A] Running Loop=1
2019-08-13T03:40:44.386Z,1565667644.386 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-08-13T03:41:44.177Z,1565667704.177 [Startup:StartupSatComms:A](INFO): Timed out from 2019-08-13T03:40:44.0Z
2019-08-13T03:41:44.177Z,1565667704.177 [Startup:StartupSatComms:A] Stopped
2019-08-13T03:41:44.177Z,1565667704.177 [Startup:StartupSatComms:B] Running Loop=1
2019-08-13T03:41:44.562Z,1565667704.562 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-13T03:41:46.845Z,1565667706.845 [DataOverHttps](INFO): Sending 241 bytes from file Logs/20190809T215236/Courier0000.lzma
2019-08-13T03:41:47.534Z,1565667707.534 [DataOverHttps](INFO): Moved sent file to Logs/20190809T215236/Courier0000.lzma.bak
2019-08-13T03:41:47.534Z,1565667707.534 [DataOverHttps](INFO): SBD MOMSN=11565491
2019-08-13T03:41:58.636Z,1565667718.636 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190813T033908/Courier0000.lzma
2019-08-13T03:41:59.434Z,1565667719.434 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Courier0000.lzma.bak
2019-08-13T03:41:59.434Z,1565667719.434 [DataOverHttps](INFO): SBD MOMSN=11565496
2019-08-13T03:42:10.742Z,1565667730.742 [DataOverHttps](INFO): Sending 356 bytes from file Logs/20190809T214827/Express0005.lzma
2019-08-13T03:42:11.546Z,1565667731.546 [DataOverHttps](INFO): Moved sent file to Logs/20190809T214827/Express0005.lzma.bak
2019-08-13T03:42:11.546Z,1565667731.546 [DataOverHttps](INFO): SBD MOMSN=11565501
2019-08-13T03:42:21.065Z,1565667741.065 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-08-13T03:42:21.065Z,1565667741.065 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-13T03:42:21.083Z,1565667741.083 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-13T03:42:21.469Z,1565667741.469 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-13T03:42:21.469Z,1565667741.469 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-08-13T03:42:22.787Z,1565667742.787 [DataOverHttps](INFO): Sending 874 bytes from file Logs/20190809T215236/Express0001.lzma
2019-08-13T03:42:23.590Z,1565667743.590 [DataOverHttps](INFO): Moved sent file to Logs/20190809T215236/Express0001.lzma.bak
2019-08-13T03:42:23.590Z,1565667743.590 [DataOverHttps](INFO): SBD MOMSN=11565516
2019-08-13T03:42:34.624Z,1565667754.624 [DataOverHttps](INFO): Sending 237 bytes from file Logs/20190809T215236/Express0005.lzma
2019-08-13T03:42:35.422Z,1565667755.422 [DataOverHttps](INFO): Moved sent file to Logs/20190809T215236/Express0005.lzma.bak
2019-08-13T03:42:35.422Z,1565667755.422 [DataOverHttps](INFO): SBD MOMSN=11565539
2019-08-13T03:42:44.215Z,1565667764.215 [Startup:StartupSatComms:B](INFO): Timed out from 2019-08-13T03:41:44.2Z
2019-08-13T03:42:44.215Z,1565667764.215 [Startup:StartupSatComms:B] Stopped
2019-08-13T03:42:44.215Z,1565667764.215 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-08-13T03:42:44.215Z,1565667764.215 [Startup:StartupSatComms] Stopped
2019-08-13T03:42:44.215Z,1565667764.215 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-08-13T03:42:44.216Z,1565667764.216 [Startup](INFO): Completed Startup
2019-08-13T03:42:44.216Z,1565667764.216 [MissionManager](INFO): Startup is completed.
2019-08-13T03:42:44.257Z,1565667764.257 [MissionManager](INFO): Uninitializing Mission Startup
2019-08-13T03:42:44.257Z,1565667764.257 [Startup] Stopped
2019-08-13T03:42:44.257Z,1565667764.257 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-08-13T03:42:44.257Z,1565667764.257 [Startup:A.GoToSurface] Stopped
2019-08-13T03:42:44.257Z,1565667764.257 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-13T03:42:44.477Z,1565667764.477 [MissionManager](IMPORTANT): Started mission Default
2019-08-13T03:42:44.477Z,1565667764.477 [Default] Running Loop=1
2019-08-13T03:42:44.477Z,1565667764.477 [Default](DEBUG): Aggregate::initialize Default
2019-08-13T03:42:44.478Z,1565667764.478 [Default:B.GoToSurface] Running Loop=1
2019-08-13T03:42:44.478Z,1565667764.478 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-13T03:42:44.478Z,1565667764.478 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-13T03:42:44.478Z,1565667764.478 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-13T03:42:44.479Z,1565667764.479 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-13T03:42:44.479Z,1565667764.479 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-13T03:42:44.479Z,1565667764.479 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-13T03:42:44.479Z,1565667764.479 [Default:A.Wait] Running Loop=1
2019-08-13T03:42:44.480Z,1565667764.480 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-13T03:42:46.745Z,1565667766.745 [DataOverHttps](INFO): Sending 832 bytes from file Logs/20190813T033908/Express0001.lzma
2019-08-13T03:42:47.550Z,1565667767.550 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Express0001.lzma.bak
2019-08-13T03:42:47.550Z,1565667767.550 [DataOverHttps](INFO): SBD MOMSN=11565550
2019-08-13T03:42:57.813Z,1565667777.813 [Default:A.Wait](INFO): Done Waiting.
2019-08-13T03:42:57.813Z,1565667777.813 [Default:A.Wait] Stopped
2019-08-13T03:42:57.813Z,1565667777.813 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-13T03:42:58.226Z,1565667778.226 [Default:CheckIn] Running Loop=1
2019-08-13T03:42:58.226Z,1565667778.226 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-13T03:42:58.226Z,1565667778.226 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-13T03:42:58.640Z,1565667778.640 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-13T03:43:43.428Z,1565667823.428 [NAL9602](INFO): SBD MO Status=2, MOMSN=8311, MT Status=2, MTMSN=0
2019-08-13T03:43:43.428Z,1565667823.428 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-13T03:45:07.870Z,1565667907.870 [NAL9602](INFO): SBD MO Status=2, MOMSN=8311, MT Status=2, MTMSN=0
2019-08-13T03:45:07.870Z,1565667907.870 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-13T03:45:08.274Z,1565667908.274 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-13T03:45:09.088Z,1565667909.088 [NAL9602](DEBUG): Fix Requested
2019-08-13T03:45:09.492Z,1565667909.492 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,034214.00,A,3648.16330,N,12147.27837,W,0.369,189.73,130819,,,A*70
2019-08-13T03:45:09.496Z,1565667909.496 [NAL9602](INFO): GPS fix at 20190813T034214: (36.802722, -121.787973)
2019-08-13T03:45:09.552Z,1565667909.552 [Default:CheckIn:Read_GPS] Stopped
2019-08-13T03:45:09.552Z,1565667909.552 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-13T03:45:09.951Z,1565667909.951 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-13T03:45:15.481Z,1565667915.481 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190813T033908/Courier0004.lzma
2019-08-13T03:45:16.070Z,1565667916.070 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Courier0004.lzma.bak
2019-08-13T03:45:16.070Z,1565667916.070 [DataOverHttps](INFO): SBD MOMSN=11565572
2019-08-13T03:45:29.489Z,1565667929.489 [DataOverHttps](INFO): Sending 300 bytes from file Logs/20190813T033908/Express0005.lzma
2019-08-13T03:45:30.294Z,1565667930.294 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Express0005.lzma.bak
2019-08-13T03:45:30.294Z,1565667930.294 [DataOverHttps](INFO): SBD MOMSN=11565575
2019-08-13T03:45:31.132Z,1565667931.132 [Default:CheckIn:Read_Iridium] Stopped
2019-08-13T03:45:31.132Z,1565667931.132 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-13T03:45:31.132Z,1565667931.132 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-13T03:45:41.570Z,1565667941.570 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-13T03:46:26.026Z,1565667986.026 [RDI_Pathfinder](ERROR): Failed to parse:
:B,-32768,-32768,V
2019-08-13T03:46:45.020Z,1565668005.020 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-08-13T03:46:45.023Z,1565668005.023 [BPC1](INFO): Received data from all battery sticks.
2019-08-13T03:48:04.210Z,1565668084.210 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-08-13T03:50:31.653Z,1565668231.653 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-13T03:50:31.653Z,1565668231.653 [Default:CheckIn:C.Wait] Stopped
2019-08-13T03:50:31.653Z,1565668231.653 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-13T03:50:31.653Z,1565668231.653 [Default:CheckIn:D] Running Loop=1
2019-08-13T03:50:32.077Z,1565668232.077 [Default:CheckIn:D] Stopped
2019-08-13T03:50:32.077Z,1565668232.077 [Default:CheckIn:E] Running Loop=1
2019-08-13T03:50:32.476Z,1565668232.476 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.793322 min 
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn:E] Stopped
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn] Stopped
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn](INFO): Running loop #2
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn] Running Loop=2
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-13T03:50:32.477Z,1565668232.477 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-13T03:50:34.068Z,1565668234.068 [NAL9602](DEBUG): Fix Requested
2019-08-13T03:50:34.460Z,1565668234.460 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,034739.00,A,3648.16212,N,12147.29093,W,0.369,189.73,130819,,,A*73
2019-08-13T03:50:34.462Z,1565668234.462 [NAL9602](INFO): GPS fix at 20190813T034739: (36.802702, -121.788182)
2019-08-13T03:50:34.486Z,1565668234.486 [Default:CheckIn:Read_GPS] Stopped
2019-08-13T03:50:34.486Z,1565668234.486 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-13T03:50:39.964Z,1565668239.964 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20190813T033908/Courier0007.lzma
2019-08-13T03:50:40.770Z,1565668240.770 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Courier0007.lzma.bak
2019-08-13T03:50:40.770Z,1565668240.770 [DataOverHttps](INFO): SBD MOMSN=11565579
2019-08-13T03:50:52.092Z,1565668252.092 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20190813T033908/Express0008.lzma
2019-08-13T03:50:52.898Z,1565668252.898 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Express0008.lzma.bak
2019-08-13T03:50:52.898Z,1565668252.898 [DataOverHttps](INFO): SBD MOMSN=11565582
2019-08-13T03:50:53.871Z,1565668253.871 [Default:CheckIn:Read_Iridium] Stopped
2019-08-13T03:50:53.872Z,1565668253.872 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-13T03:50:53.872Z,1565668253.872 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-13T03:51:10.025Z,1565668270.025 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-08-13T03:51:10.025Z,1565668270.025 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19081220585360,35.0, -0.1,  8.9,  0
2019-08-13T03:52:24.358Z,1565668344.358 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-08-13T03:52:24.358Z,1565668344.358 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19081221000760,31,   0.0,1448.9,  0
2019-08-13T03:52:26.368Z,1565668346.368 [NAL9602](INFO): SBD MO Status=2, MOMSN=8311, MT Status=2, MTMSN=0
2019-08-13T03:52:26.368Z,1565668346.368 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-13T03:52:41.719Z,1565668361.719 [NAL9602](INFO): SBD MO Status=0, MOMSN=8311, MT Status=0, MTMSN=0
2019-08-13T03:52:41.720Z,1565668361.720 [NAL9602](INFO): No messages in MT queue
2019-08-13T03:52:48.642Z,1565668368.642 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-08-13T03:53:07.058Z,1565668387.058 [CommandLine](IMPORTANT): got command run ./Missions/DUSBL_Tracking.xml
2019-08-13T03:53:07.059Z,1565668387.059 [MissionManager](INFO): Loading Mission: ./Missions/DUSBL_Tracking.xml
2019-08-13T03:53:07.086Z,1565668387.086 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-08-13T03:53:07.089Z,1565668387.089 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-08-13T03:53:07.093Z,1565668387.093 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 0.100000 s
2019-08-13T03:53:07.097Z,1565668387.097 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-08-13T03:53:07.100Z,1565668387.100 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-08-13T03:53:07.102Z,1565668387.102 [DUSBL:A.Pitch](DEBUG): Construct.
2019-08-13T03:53:07.108Z,1565668387.108 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-08-13T03:53:07.370Z,1565668387.370 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-08-13T03:53:07.378Z,1565668387.378 [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>0.1</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-13T03:53:07.386Z,1565668387.386 [CommandLine](IMPORTANT): Running ./Missions/DUSBL_Tracking.xml
2019-08-13T03:53:07.605Z,1565668387.605 [Default] Stopped
2019-08-13T03:53:07.606Z,1565668387.606 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-13T03:53:07.606Z,1565668387.606 [Default:B.GoToSurface] Stopped
2019-08-13T03:53:07.606Z,1565668387.606 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-13T03:53:07.607Z,1565668387.607 [Default:CheckIn] Stopped
2019-08-13T03:53:07.607Z,1565668387.607 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-13T03:53:07.607Z,1565668387.607 [Default:CheckIn:C.Wait] Stopped
2019-08-13T03:53:07.607Z,1565668387.607 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-13T03:53:07.608Z,1565668387.608 [MissionManager](IMPORTANT): Started mission DUSBL
2019-08-13T03:53:07.609Z,1565668387.609 [DUSBL] Running Loop=1
2019-08-13T03:53:07.609Z,1565668387.609 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-08-13T03:53:07.610Z,1565668387.610 [DUSBL:A.Pitch] Running Loop=1
2019-08-13T03:53:07.610Z,1565668387.610 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-08-13T03:53:07.611Z,1565668387.611 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-13T03:53:07.611Z,1565668387.611 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-08-13T03:53:07.612Z,1565668387.612 [DUSBL:C.] Running Loop=1
2019-08-13T03:53:07.612Z,1565668387.612 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-08-13T03:53:07.613Z,1565668387.613 [DUSBL:RequestRepeater] Running Loop=1
2019-08-13T03:53:07.614Z,1565668387.614 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-08-13T03:53:07.614Z,1565668387.614 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-08-13T03:53:07.614Z,1565668387.614 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-08-13T03:53:07.615Z,1565668387.615 [DUSBL:C.] Running Loop=1
2019-08-13T03:53:07.618Z,1565668387.618 [DUSBL:B.SetSpeed] Running Loop=1
2019-08-13T03:53:07.618Z,1565668387.618 [DUSBL:A.Pitch] Running Loop=1
2019-08-13T03:53:08.008Z,1565668388.008 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:08.405Z,1565668388.405 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:08.830Z,1565668388.830 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:09.218Z,1565668389.218 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:09.278Z,1565668389.278 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:09.593Z,1565668389.593 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:09.686Z,1565668389.686 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:09.998Z,1565668389.998 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-13T03:53:10.034Z,1565668390.034 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:10.407Z,1565668390.407 [DUSBL_Hydroid](INFO): rearmLockTime: 0.41/2.50
2019-08-13T03:53:10.422Z,1565668390.422 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035311.22*5B

2019-08-13T03:53:10.452Z,1565668390.452 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:10.803Z,1565668390.803 [DUSBL_Hydroid](INFO): rearmLockTime: 0.80/2.50
2019-08-13T03:53:10.860Z,1565668390.860 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:11.210Z,1565668391.210 [DUSBL_Hydroid](INFO): rearmLockTime: 1.21/2.50
2019-08-13T03:53:11.252Z,1565668391.252 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:11.615Z,1565668391.615 [DUSBL_Hydroid](INFO): rearmLockTime: 1.62/2.50
2019-08-13T03:53:11.660Z,1565668391.660 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:12.014Z,1565668392.014 [DUSBL_Hydroid](INFO): rearmLockTime: 2.01/2.50
2019-08-13T03:53:12.071Z,1565668392.071 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:12.422Z,1565668392.422 [DUSBL_Hydroid](INFO): rearmLockTime: 2.42/2.50
2019-08-13T03:53:12.434Z,1565668392.434 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-13T03:53:12.488Z,1565668392.488 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:12.892Z,1565668392.892 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:13.227Z,1565668393.227 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:13.327Z,1565668393.327 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:13.633Z,1565668393.633 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:13.676Z,1565668393.676 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:14.034Z,1565668394.034 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-13T03:53:14.069Z,1565668394.069 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:14.438Z,1565668394.438 [DUSBL_Hydroid](INFO): rearmLockTime: 0.40/2.50
2019-08-13T03:53:14.450Z,1565668394.450 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035315.23*5E

2019-08-13T03:53:14.476Z,1565668394.476 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:14.848Z,1565668394.848 [DUSBL_Hydroid](INFO): rearmLockTime: 0.81/2.50
2019-08-13T03:53:14.895Z,1565668394.895 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:15.246Z,1565668395.246 [DUSBL_Hydroid](INFO): rearmLockTime: 1.21/2.50
2019-08-13T03:53:15.288Z,1565668395.288 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:15.653Z,1565668395.653 [DUSBL_Hydroid](INFO): rearmLockTime: 1.62/2.50
2019-08-13T03:53:15.714Z,1565668395.714 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:16.058Z,1565668396.058 [DUSBL_Hydroid](INFO): rearmLockTime: 2.02/2.50
2019-08-13T03:53:16.115Z,1565668396.115 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:16.462Z,1565668396.462 [DUSBL_Hydroid](INFO): rearmLockTime: 2.43/2.50
2019-08-13T03:53:16.500Z,1565668396.500 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:16.911Z,1565668396.911 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:17.267Z,1565668397.267 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:17.318Z,1565668397.318 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:17.673Z,1565668397.673 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:17.719Z,1565668397.719 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:18.113Z,1565668398.113 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:18.486Z,1565668398.486 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035319.27*56

2019-08-13T03:53:18.541Z,1565668398.541 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:18.924Z,1565668398.924 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:19.314Z,1565668399.314 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:19.729Z,1565668399.729 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:20.124Z,1565668400.124 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:20.523Z,1565668400.523 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:20.905Z,1565668400.905 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-13T03:53:20.941Z,1565668400.941 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:21.348Z,1565668401.348 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:21.711Z,1565668401.711 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:21.815Z,1565668401.815 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:22.116Z,1565668402.116 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:22.216Z,1565668402.216 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:22.518Z,1565668402.518 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-13T03:53:22.544Z,1565668402.544 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:22.926Z,1565668402.926 [DUSBL_Hydroid](INFO): rearmLockTime: 0.41/2.50
2019-08-13T03:53:22.938Z,1565668402.938 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035323.71*5C

2019-08-13T03:53:23.043Z,1565668403.043 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:23.326Z,1565668403.326 [DUSBL_Hydroid](INFO): rearmLockTime: 0.81/2.50
2019-08-13T03:53:23.385Z,1565668403.385 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:23.730Z,1565668403.730 [DUSBL_Hydroid](INFO): rearmLockTime: 1.21/2.50
2019-08-13T03:53:23.770Z,1565668403.770 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:24.134Z,1565668404.134 [DUSBL_Hydroid](INFO): rearmLockTime: 1.62/2.50
2019-08-13T03:53:24.203Z,1565668404.203 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:24.550Z,1565668404.550 [DUSBL_Hydroid](INFO): rearmLockTime: 2.03/2.50
2019-08-13T03:53:24.592Z,1565668404.592 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:24.942Z,1565668404.942 [DUSBL_Hydroid](INFO): rearmLockTime: 2.42/2.50
2019-08-13T03:53:25.024Z,1565668405.024 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:25.376Z,1565668405.376 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:25.767Z,1565668405.767 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:25.884Z,1565668405.884 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:26.161Z,1565668406.161 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:26.200Z,1565668406.200 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:26.589Z,1565668406.589 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:26.972Z,1565668406.972 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035327.77*5E

2019-08-13T03:53:27.008Z,1565668407.008 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:27.404Z,1565668407.404 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:27.821Z,1565668407.821 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:28.218Z,1565668408.218 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:28.646Z,1565668408.646 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:29.019Z,1565668409.019 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:29.390Z,1565668409.390 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-13T03:53:29.414Z,1565668409.414 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:29.834Z,1565668409.834 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:30.199Z,1565668410.199 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:30.252Z,1565668410.252 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:30.606Z,1565668410.606 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:30.655Z,1565668410.655 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:31.043Z,1565668411.043 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:31.415Z,1565668411.415 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035332.20*58

2019-08-13T03:53:31.465Z,1565668411.465 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:31.865Z,1565668411.865 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:32.242Z,1565668412.242 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:32.652Z,1565668412.652 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:33.061Z,1565668413.061 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:33.457Z,1565668413.457 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:33.830Z,1565668413.830 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-13T03:53:33.854Z,1565668413.854 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:34.283Z,1565668414.283 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:34.665Z,1565668414.665 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:34.733Z,1565668414.733 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:35.045Z,1565668415.045 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:35.101Z,1565668415.101 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:35.474Z,1565668415.474 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:35.859Z,1565668415.859 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035336.67*5F

2019-08-13T03:53:35.896Z,1565668415.896 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:36.281Z,1565668416.281 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:36.696Z,1565668416.696 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:37.090Z,1565668417.090 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:37.496Z,1565668417.496 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:37.931Z,1565668417.931 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:38.277Z,1565668418.277 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-08-13T03:53:38.301Z,1565668418.301 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:38.737Z,1565668418.737 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:39.087Z,1565668419.087 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:39.157Z,1565668419.157 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:39.493Z,1565668419.493 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:39.532Z,1565668419.532 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:39.894Z,1565668419.894 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-08-13T03:53:39.929Z,1565668419.929 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:40.302Z,1565668420.302 [DUSBL_Hydroid](INFO): rearmLockTime: 0.41/2.50
2019-08-13T03:53:40.314Z,1565668420.314 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035341.09*57

2019-08-13T03:53:40.344Z,1565668420.344 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:40.713Z,1565668420.713 [DUSBL_Hydroid](INFO): rearmLockTime: 0.82/2.50
2019-08-13T03:53:40.759Z,1565668420.759 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:41.102Z,1565668421.102 [DUSBL_Hydroid](INFO): rearmLockTime: 1.21/2.50
2019-08-13T03:53:41.152Z,1565668421.152 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:41.510Z,1565668421.510 [DUSBL_Hydroid](INFO): rearmLockTime: 1.62/2.50
2019-08-13T03:53:41.568Z,1565668421.568 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:41.914Z,1565668421.914 [DUSBL_Hydroid](INFO): rearmLockTime: 2.02/2.50
2019-08-13T03:53:41.983Z,1565668421.983 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:42.318Z,1565668422.318 [DUSBL_Hydroid](INFO): rearmLockTime: 2.42/2.50
2019-08-13T03:53:42.356Z,1565668422.356 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:42.752Z,1565668422.752 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:43.127Z,1565668423.127 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-08-13T03:53:43.193Z,1565668423.193 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:43.533Z,1565668423.533 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-08-13T03:53:43.572Z,1565668423.572 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:43.681Z,1565668423.681 [CommandLine](IMPORTANT): got command stop
2019-08-13T03:53:43.681Z,1565668423.681 [CommandLine](IMPORTANT): Scheduling is paused
2019-08-13T03:53:43.682Z,1565668423.682 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-08-13T03:53:43.995Z,1565668423.995 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-08-13T03:53:43.996Z,1565668423.996 [MissionManager](INFO): MissionManager is completed.
2019-08-13T03:53:44.001Z,1565668424.001 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL] Stopped
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:A.Pitch] Stopped
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:B.SetSpeed] Stopped
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:C.] Stopped
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:RequestRepeater] Stopped
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-08-13T03:53:44.001Z,1565668424.001 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-13T03:53:44.339Z,1565668424.339 [Micromodem](INFO): Nmea in: $SNTTA,,,,,035345.13*58

2019-08-13T03:53:44.397Z,1565668424.397 [MissionManager](IMPORTANT): Started mission Default
2019-08-13T03:53:44.397Z,1565668424.397 [Default] Running Loop=1
2019-08-13T03:53:44.397Z,1565668424.397 [Default](DEBUG): Aggregate::initialize Default
2019-08-13T03:53:44.397Z,1565668424.397 [Default:B.GoToSurface] Running Loop=1
2019-08-13T03:53:44.397Z,1565668424.397 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-13T03:53:44.397Z,1565668424.397 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-13T03:53:44.398Z,1565668424.398 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-13T03:53:44.398Z,1565668424.398 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-13T03:53:44.398Z,1565668424.398 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-13T03:53:44.399Z,1565668424.399 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-13T03:53:44.399Z,1565668424.399 [Default:A.Wait] Running Loop=1
2019-08-13T03:53:44.399Z,1565668424.399 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-13T03:53:57.731Z,1565668437.731 [Default:A.Wait](INFO): Done Waiting.
2019-08-13T03:53:57.731Z,1565668437.731 [Default:A.Wait] Stopped
2019-08-13T03:53:57.731Z,1565668437.731 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-13T03:53:58.118Z,1565668438.118 [Default:CheckIn] Running Loop=1
2019-08-13T03:53:58.119Z,1565668438.119 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-13T03:53:58.119Z,1565668438.119 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-13T03:53:59.700Z,1565668439.700 [NAL9602](DEBUG): Fix Requested
2019-08-13T03:54:00.108Z,1565668440.108 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,035106.00,A,3648.16379,N,12147.29785,W,0.039,189.73,130819,,,A*72
2019-08-13T03:54:00.114Z,1565668440.114 [NAL9602](INFO): GPS fix at 20190813T035106: (36.802730, -121.788297)
2019-08-13T03:54:00.138Z,1565668440.138 [Default:CheckIn:Read_GPS] Stopped
2019-08-13T03:54:00.138Z,1565668440.138 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-13T03:54:06.804Z,1565668446.804 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190813T033908/Courier0010.lzma
2019-08-13T03:54:07.613Z,1565668447.613 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Courier0010.lzma.bak
2019-08-13T03:54:07.614Z,1565668447.614 [DataOverHttps](INFO): SBD MOMSN=11565591
2019-08-13T03:54:21.956Z,1565668461.956 [CBIT](INFO): Clearing failed state for component DropWeight
2019-08-13T03:54:21.956Z,1565668461.956 [DropWeight] No Fault, FailCount= 1
2019-08-13T03:54:22.144Z,1565668462.144 [DataOverHttps](INFO): Sending 194 bytes from file Logs/20190813T033908/Express0011.lzma
2019-08-13T03:54:22.954Z,1565668462.954 [DataOverHttps](INFO): Moved sent file to Logs/20190813T033908/Express0011.lzma.bak
2019-08-13T03:54:22.955Z,1565668462.955 [DataOverHttps](INFO): SBD MOMSN=11565595
2019-08-13T03:54:23.545Z,1565668463.545 [Default:CheckIn:Read_Iridium] Stopped
2019-08-13T03:54:23.545Z,1565668463.545 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-13T03:54:23.546Z,1565668463.546 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-13T03:54:41.708Z,1565668481.708 [NAL9602](INFO): SBD MO Status=2, MOMSN=8312, MT Status=2, MTMSN=0
2019-08-13T03:54:41.708Z,1565668481.708 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-13T03:55:20.896Z,1565668520.896 [NAL9602](INFO): SBD MO Status=2, MOMSN=8312, MT Status=2, MTMSN=0
2019-08-13T03:55:20.897Z,1565668520.897 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-13T03:56:08.738Z,1565668568.738 [CommandLine](IMPORTANT): got command quit
2019-08-13T03:56:09.749Z,1565668569.749 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:09.749Z,1565668569.749 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:09.816Z,1565668569.816 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-08-13T03:56:09.817Z,1565668569.817 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:09.817Z,1565668569.817 [CommandLine](INFO): Join timeout helper Thread ID is 9791
2019-08-13T03:56:09.836Z,1565668569.836 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-08-13T03:56:09.837Z,1565668569.837 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:09.837Z,1565668569.837 [NavChartDb](INFO): Join timeout helper Thread ID is 9792
2019-08-13T03:56:09.937Z,1565668569.937 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:09.937Z,1565668569.937 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:09.953Z,1565668569.953 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-08-13T03:56:09.953Z,1565668569.953 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:09.953Z,1565668569.953 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 9793
2019-08-13T03:56:10.113Z,1565668570.113 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:10.113Z,1565668570.113 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-08-13T03:56:10.114Z,1565668570.114 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:10.129Z,1565668570.129 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-08-13T03:56:10.129Z,1565668570.129 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:10.129Z,1565668570.129 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 9794
2019-08-13T03:56:10.189Z,1565668570.189 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:10.189Z,1565668570.189 [CTD_NeilBrown](INFO): Powering down
2019-08-13T03:56:10.201Z,1565668570.201 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:10.212Z,1565668570.212 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-08-13T03:56:10.213Z,1565668570.213 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:10.213Z,1565668570.213 [Radio_Surface](INFO): Join timeout helper Thread ID is 9795
2019-08-13T03:56:10.493Z,1565668570.493 [Radio_Surface](INFO): Powering down
2019-08-13T03:56:10.494Z,1565668570.494 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:10.494Z,1565668570.494 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:10.497Z,1565668570.497 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-08-13T03:56:10.498Z,1565668570.498 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:10.498Z,1565668570.498 [DataOverHttps](INFO): Join timeout helper Thread ID is 9796
2019-08-13T03:56:13.443Z,1565668573.443 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:13.451Z,1565668573.451 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:13.469Z,1565668573.469 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-08-13T03:56:13.470Z,1565668573.470 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:13.470Z,1565668573.470 [logger](INFO): Join timeout helper Thread ID is 9797
2019-08-13T03:56:13.493Z,1565668573.493 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:13.493Z,1565668573.493 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:13.509Z,1565668573.509 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-08-13T03:56:13.509Z,1565668573.509 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:13.509Z,1565668573.509 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-08-13T03:56:13.510Z,1565668573.510 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:13.510Z,1565668573.510 [controlThread](INFO): Join timeout helper Thread ID is 9798
2019-08-13T03:56:13.797Z,1565668573.797 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-13T03:56:13.797Z,1565668573.797 [controlThread](DEBUG): Uninitializing ControlThread
2019-08-13T03:56:13.797Z,1565668573.797 [AHRS_M2](INFO): Powering down
2019-08-13T03:56:13.869Z,1565668573.869 [DUSBL_Hydroid](INFO): Powering down
2019-08-13T03:56:13.941Z,1565668573.941 [Micromodem](INFO): Powering down
2019-08-13T03:56:14.037Z,1565668574.037 [NAL9602](INFO): Powering down
2019-08-13T03:56:14.109Z,1565668574.109 [RDI_Pathfinder](INFO): Powering down
2019-08-13T03:56:14.110Z,1565668574.110 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-08-13T03:56:14.111Z,1565668574.111 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-08-13T03:56:14.111Z,1565668574.111 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-08-13T03:56:14.112Z,1565668574.112 [MissionManager](INFO): Uninitializing Mission Default
2019-08-13T03:56:14.112Z,1565668574.112 [Default] Stopped
2019-08-13T03:56:14.112Z,1565668574.112 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-13T03:56:14.112Z,1565668574.112 [Default:B.GoToSurface] Stopped
2019-08-13T03:56:14.112Z,1565668574.112 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-13T03:56:14.112Z,1565668574.112 [Default:CheckIn] Stopped
2019-08-13T03:56:14.113Z,1565668574.113 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-13T03:56:14.113Z,1565668574.113 [Default:CheckIn:C.Wait] Stopped
2019-08-13T03:56:14.113Z,1565668574.113 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-13T03:56:14.115Z,1565668574.115 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-08-13T03:56:14.115Z,1565668574.115 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-08-13T03:56:14.116Z,1565668574.116 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-08-13T03:56:14.116Z,1565668574.116 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-08-13T03:56:14.116Z,1565668574.116 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-08-13T03:56:14.117Z,1565668574.117 [BuoyancyServo](INFO): Powering down
2019-08-13T03:56:14.129Z,1565668574.129 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-08-13T03:56:14.129Z,1565668574.129 [ElevatorServo](INFO): Powering down
2019-08-13T03:56:14.130Z,1565668574.130 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-08-13T03:56:14.130Z,1565668574.130 [MassServo](INFO): Powering down
2019-08-13T03:56:14.130Z,1565668574.130 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-13T03:56:14.131Z,1565668574.131 [RudderServo](INFO): Powering down
2019-08-13T03:56:14.131Z,1565668574.131 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-08-13T03:56:14.131Z,1565668574.131 [ThrusterServo](INFO): Powering down
2019-08-13T03:56:14.132Z,1565668574.132 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-08-13T03:56:14.133Z,1565668574.133 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-08-13T03:56:14.133Z,1565668574.133 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-08-13T03:56:14.133Z,1565668574.133 [CBIT](DEBUG): Powering off loads.
2019-08-13T03:56:14.144Z,1565668574.144 [CBIT](DEBUG): Disabling WDT.
2019-08-13T03:56:14.156Z,1565668574.156 [CBIT](DEBUG): Opening all GF detection circuits.
2019-08-13T03:56:14.157Z,1565668574.157 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:14.205Z,1565668574.205 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:14.214Z,1565668574.214 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:14.255Z,1565668574.255 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:14.258Z,1565668574.258 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:14.315Z,1565668574.315 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-13T03:56:14.388Z,1565668574.388 [logger ThreadHandler](INFO): Thread cancelled.