2019-07-03T03:45:10.127Z,1562125510.127 [Supervisor](DEBUG): Initializing supervisor.
2019-07-03T03:45:10.141Z,1562125510.141 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-03T03:45:10.141Z,1562125510.141 [SyncHandler](INFO): Protected caller Thread ID is 807
2019-07-03T03:45:10.142Z,1562125510.142 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-03T03:45:10.153Z,1562125510.153 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-03T03:45:10.153Z,1562125510.153 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 808
2019-07-03T03:45:10.156Z,1562125510.156 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-03T03:45:10.178Z,1562125510.178 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-03T03:45:10.189Z,1562125510.189 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-03T03:45:10.189Z,1562125510.189 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 809
2019-07-03T03:45:10.190Z,1562125510.190 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-03T03:45:10.201Z,1562125510.201 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-03T03:45:10.201Z,1562125510.201 [logger ThreadHandler](INFO): Protected caller Thread ID is 810
2019-07-03T03:45:10.203Z,1562125510.203 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-03T03:45:10.203Z,1562125510.203 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-03T03:45:10.208Z,1562125510.208 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-03T03:45:11.044Z,1562125511.044 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-03T03:45:11.046Z,1562125511.046 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-03T03:45:11.225Z,1562125511.225 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-03T03:45:11.227Z,1562125511.227 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-03T03:45:11.832Z,1562125511.832 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-03T03:45:11.835Z,1562125511.835 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-03T03:45:12.092Z,1562125512.092 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-03T03:45:12.093Z,1562125512.093 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-03T03:45:12.438Z,1562125512.438 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-03T03:45:12.440Z,1562125512.440 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-03T03:45:13.495Z,1562125513.495 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-03T03:45:13.497Z,1562125513.497 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-03T03:45:13.859Z,1562125513.859 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-03T03:45:13.860Z,1562125513.860 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-03T03:45:14.111Z,1562125514.111 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-03T03:45:14.113Z,1562125514.113 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-03T03:45:14.303Z,1562125514.303 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-03T03:45:14.305Z,1562125514.305 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-03T03:45:14.399Z,1562125514.399 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-03T03:45:14.400Z,1562125514.400 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-03T03:45:14.693Z,1562125514.693 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-03T03:45:14.694Z,1562125514.694 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-03T03:45:14.775Z,1562125514.775 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-03T03:45:14.876Z,1562125514.876 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-03T03:45:14.877Z,1562125514.877 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-03T03:45:15.454Z,1562125515.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-03T03:45:15.456Z,1562125515.456 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-03T03:45:15.839Z,1562125515.839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-03T03:45:15.841Z,1562125515.841 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-07-03T03:45:15.844Z,1562125515.844 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-07-03T03:45:16.048Z,1562125516.048 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-07-03T03:45:16.148Z,1562125516.148 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-07-03T03:45:16.246Z,1562125516.246 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-07-03T03:45:16.469Z,1562125516.469 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-03T03:45:16.469Z,1562125516.469 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-07-03T03:45:16.554Z,1562125516.554 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-07-03T03:45:16.647Z,1562125516.647 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-07-03T03:45:16.742Z,1562125516.742 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-07-03T03:45:16.825Z,1562125516.825 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-07-03T03:45:16.930Z,1562125516.930 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-07-03T03:45:17.106Z,1562125517.106 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-07-03T03:45:17.233Z,1562125517.233 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-07-03T03:45:17.240Z,1562125517.240 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-03T03:45:17.966Z,1562125517.966 [AHRS_M2] Loaded
2019-07-03T03:45:17.966Z,1562125517.966 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-07-03T03:45:18.107Z,1562125518.107 [DataOverHttps] Loaded
2019-07-03T03:45:18.108Z,1562125518.108 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-03T03:45:18.109Z,1562125518.109 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407654E0
2019-07-03T03:45:18.109Z,1562125518.109 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 889
2019-07-03T03:45:18.122Z,1562125518.122 [Depth_Keller] Loaded
2019-07-03T03:45:18.122Z,1562125518.122 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-03T03:45:18.127Z,1562125518.127 [DropWeight] Loaded
2019-07-03T03:45:18.127Z,1562125518.127 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-07-03T03:45:18.182Z,1562125518.182 [DUSBL_Hydroid] Loaded
2019-07-03T03:45:18.183Z,1562125518.183 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-07-03T03:45:18.230Z,1562125518.230 [Micromodem] Loaded
2019-07-03T03:45:18.230Z,1562125518.230 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-07-03T03:45:18.325Z,1562125518.325 [NAL9602] Loaded
2019-07-03T03:45:18.326Z,1562125518.326 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-03T03:45:18.341Z,1562125518.341 [Onboard] Loaded
2019-07-03T03:45:18.341Z,1562125518.341 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-03T03:45:18.347Z,1562125518.347 [PowerOnly] Loaded
2019-07-03T03:45:18.347Z,1562125518.347 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-07-03T03:45:18.354Z,1562125518.354 [Radio_Surface] Loaded
2019-07-03T03:45:18.354Z,1562125518.354 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-03T03:45:18.355Z,1562125518.355 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407954E0
2019-07-03T03:45:18.355Z,1562125518.355 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 890
2019-07-03T03:45:18.398Z,1562125518.398 [RDI_Pathfinder] Loaded
2019-07-03T03:45:18.399Z,1562125518.399 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-07-03T03:45:20.469Z,1562125520.469 [BPC1] Loaded
2019-07-03T03:45:20.469Z,1562125520.469 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-03T03:45:20.469Z,1562125520.469 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-03T03:45:20.470Z,1562125520.470 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-03T03:45:20.494Z,1562125520.494 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-03T03:45:20.494Z,1562125520.494 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-03T03:45:20.616Z,1562125520.616 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-03T03:45:20.616Z,1562125520.616 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-03T03:45:20.636Z,1562125520.636 [NavChart] Loaded
2019-07-03T03:45:20.637Z,1562125520.637 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-03T03:45:20.640Z,1562125520.640 [UniversalFixResidualReporter] Loaded
2019-07-03T03:45:20.641Z,1562125520.641 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-03T03:45:20.641Z,1562125520.641 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-03T03:45:20.642Z,1562125520.642 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-03T03:45:20.770Z,1562125520.770 [BuoyancyServo] Loaded
2019-07-03T03:45:20.770Z,1562125520.770 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-03T03:45:20.785Z,1562125520.785 [ElevatorServo] Loaded
2019-07-03T03:45:20.785Z,1562125520.785 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-03T03:45:20.799Z,1562125520.799 [MassServo] Loaded
2019-07-03T03:45:20.799Z,1562125520.799 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-03T03:45:20.814Z,1562125520.814 [RudderServo] Loaded
2019-07-03T03:45:20.815Z,1562125520.815 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-03T03:45:20.829Z,1562125520.829 [ThrusterServo] Loaded
2019-07-03T03:45:20.829Z,1562125520.829 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-03T03:45:20.830Z,1562125520.830 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-03T03:45:20.830Z,1562125520.830 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-03T03:45:21.147Z,1562125521.147 [CTD_NeilBrown] Loaded
2019-07-03T03:45:21.148Z,1562125521.148 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-07-03T03:45:21.149Z,1562125521.149 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E04E0
2019-07-03T03:45:21.149Z,1562125521.149 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 891
2019-07-03T03:45:21.193Z,1562125521.193 [WetLabsSeaOWL_UV_A] Loaded
2019-07-03T03:45:21.193Z,1562125521.193 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-07-03T03:45:21.194Z,1562125521.194 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409104E0
2019-07-03T03:45:21.194Z,1562125521.194 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 892
2019-07-03T03:45:21.195Z,1562125521.195 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-03T03:45:21.195Z,1562125521.195 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-03T03:45:21.530Z,1562125521.530 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-03T03:45:21.531Z,1562125521.531 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-03T03:45:21.586Z,1562125521.586 [DepthRateCalculator] Loaded
2019-07-03T03:45:21.586Z,1562125521.586 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-03T03:45:21.592Z,1562125521.592 [PitchRateCalculator] Loaded
2019-07-03T03:45:21.592Z,1562125521.592 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-03T03:45:21.604Z,1562125521.604 [SpeedCalculator] Loaded
2019-07-03T03:45:21.604Z,1562125521.604 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-03T03:45:21.625Z,1562125521.625 [TempGradientCalculator] Loaded
2019-07-03T03:45:21.625Z,1562125521.625 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-03T03:45:21.630Z,1562125521.630 [YawRateCalculator] Loaded
2019-07-03T03:45:21.631Z,1562125521.631 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-03T03:45:21.671Z,1562125521.671 [ElevatorOffsetCalculator] Loaded
2019-07-03T03:45:21.671Z,1562125521.671 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-03T03:45:21.671Z,1562125521.671 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-03T03:45:21.672Z,1562125521.672 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-03T03:45:21.831Z,1562125521.831 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-03T03:45:21.852Z,1562125521.852 [SBIT] Loaded
2019-07-03T03:45:21.853Z,1562125521.853 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-03T03:45:21.853Z,1562125521.853 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-03T03:45:21.865Z,1562125521.865 [IBIT] Loaded
2019-07-03T03:45:21.865Z,1562125521.865 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-03T03:45:21.868Z,1562125521.868 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-03T03:45:22.006Z,1562125522.006 [CBIT] Loaded
2019-07-03T03:45:22.006Z,1562125522.006 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-03T03:45:22.006Z,1562125522.006 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-03T03:45:22.007Z,1562125522.007 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-03T03:45:22.129Z,1562125522.129 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-03T03:45:22.129Z,1562125522.129 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-03T03:45:22.252Z,1562125522.252 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-03T03:45:22.253Z,1562125522.253 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-03T03:45:22.339Z,1562125522.339 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-03T03:45:22.421Z,1562125522.421 [VerticalControl] Loaded
2019-07-03T03:45:22.422Z,1562125522.422 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-03T03:45:22.422Z,1562125522.422 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-03T03:45:22.477Z,1562125522.477 [HorizontalControl] Loaded
2019-07-03T03:45:22.478Z,1562125522.478 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-03T03:45:22.478Z,1562125522.478 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-03T03:45:22.480Z,1562125522.480 [SpeedControl] Loaded
2019-07-03T03:45:22.480Z,1562125522.480 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-03T03:45:22.481Z,1562125522.481 [LoopControl](DEBUG): Construct LoopControl.
2019-07-03T03:45:22.481Z,1562125522.481 [LoopControl] Loaded
2019-07-03T03:45:22.482Z,1562125522.482 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-03T03:45:22.482Z,1562125522.482 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-03T03:45:22.483Z,1562125522.483 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-03T03:45:22.530Z,1562125522.530 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-03T03:45:22.534Z,1562125522.534 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-03T03:45:22.535Z,1562125522.535 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-03T03:45:22.542Z,1562125522.542 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-03T03:45:22.543Z,1562125522.543 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AEC4E0
2019-07-03T03:45:22.543Z,1562125522.543 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 893
2019-07-03T03:45:22.547Z,1562125522.547 [Supervisor](INFO): Main Thread ID is 803
2019-07-03T03:45:22.548Z,1562125522.548 [Supervisor](DEBUG): Running supervisor.
2019-07-03T03:45:22.548Z,1562125522.548 [CommandLine ThreadHandler](INFO): Handler Thread ID is 894
2019-07-03T03:45:22.550Z,1562125522.550 [controlThread ThreadHandler](INFO): Handler Thread ID is 895
2019-07-03T03:45:22.551Z,1562125522.551 [controlThread](DEBUG): Initializing ControlThread
2019-07-03T03:45:22.556Z,1562125522.556 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-03T03:45:22.556Z,1562125522.556 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-03T03:45:22.558Z,1562125522.558 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-03T03:45:22.558Z,1562125522.558 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-03T03:45:22.558Z,1562125522.558 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-03T03:45:22.559Z,1562125522.559 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-03T03:45:22.559Z,1562125522.559 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-03T03:45:22.559Z,1562125522.559 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-03T03:45:22.560Z,1562125522.560 [SBIT](INFO): Initialize SBIT Component.
2019-07-03T03:45:22.560Z,1562125522.560 [SBIT](IMPORTANT): git: 2019-07-01
2019-07-03T03:45:22.561Z,1562125522.561 [SBIT](INFO): git hash: 66ee1f914ed66d399bd38d45ccca9e12ca50b60d
2019-07-03T03:45:22.561Z,1562125522.561 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-03T03:45:22.562Z,1562125522.562 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-07-03T03:45:22.563Z,1562125522.563 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-07-03T03:45:22.564Z,1562125522.564 [IBIT](INFO): Initialize IBIT Component.
2019-07-03T03:45:22.565Z,1562125522.565 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-03T03:45:22.566Z,1562125522.566 [logger ThreadHandler](INFO): Handler Thread ID is 896
2019-07-03T03:45:22.577Z,1562125522.577 [CBIT](DEBUG): Initialized mux pins.
2019-07-03T03:45:22.577Z,1562125522.577 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-03T03:45:22.585Z,1562125522.585 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 897
2019-07-03T03:45:22.586Z,1562125522.586 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-03T03:45:22.597Z,1562125522.597 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 898
2019-07-03T03:45:22.601Z,1562125522.601 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-03T03:45:22.601Z,1562125522.601 [CBIT](DEBUG): Initializing heartbeat.
2019-07-03T03:45:22.609Z,1562125522.609 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 899
2019-07-03T03:45:22.610Z,1562125522.610 [CTD_NeilBrown](INFO): Powering down
2019-07-03T03:45:22.649Z,1562125522.649 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 900
2019-07-03T03:45:22.650Z,1562125522.650 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-03T03:45:22.669Z,1562125522.669 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 901
2019-07-03T03:45:22.673Z,1562125522.673 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-03T03:45:22.673Z,1562125522.673 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-03T03:45:22.682Z,1562125522.682 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-03T03:45:22.682Z,1562125522.682 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-03T03:45:22.682Z,1562125522.682 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-03T03:45:22.682Z,1562125522.682 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-03T03:45:22.682Z,1562125522.682 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-03T03:45:22.682Z,1562125522.682 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-03T03:45:22.683Z,1562125522.683 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-03T03:45:22.683Z,1562125522.683 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-03T03:45:22.683Z,1562125522.683 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-03T03:45:22.683Z,1562125522.683 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-03T03:45:22.683Z,1562125522.683 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-03T03:45:22.683Z,1562125522.683 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-03T03:45:22.684Z,1562125522.684 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-03T03:45:22.684Z,1562125522.684 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-03T03:45:22.684Z,1562125522.684 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-03T03:45:22.684Z,1562125522.684 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-03T03:45:22.709Z,1562125522.709 [CBIT](DEBUG): Backplane powered.
2019-07-03T03:45:22.709Z,1562125522.709 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-03T03:45:22.711Z,1562125522.711 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-03T03:45:22.712Z,1562125522.712 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-03T03:45:22.712Z,1562125522.712 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-03T03:45:22.713Z,1562125522.713 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-03T03:45:22.773Z,1562125522.773 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-03T03:45:22.784Z,1562125522.784 [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-07-03T03:45:22.801Z,1562125522.801 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-03T03:45:22.907Z,1562125522.907 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-03T03:45:22.914Z,1562125522.914 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-03T03:45:22.915Z,1562125522.915 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-03T03:45:22.942Z,1562125522.942 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-03T03:45:22.944Z,1562125522.944 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-03T03:45:22.966Z,1562125522.966 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-03T03:45:22.985Z,1562125522.985 [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-07-03T03:45:22.991Z,1562125522.991 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,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-07-03T03:45:23.001Z,1562125523.001 [Radio_Surface](INFO): Powering up
2019-07-03T03:45:23.002Z,1562125523.002 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-07-03T03:45:23.114Z,1562125523.114 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-07-03T03:45:23.115Z,1562125523.115 [DUSBL_Hydroid](INFO): Powering up
2019-07-03T03:45:23.115Z,1562125523.115 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-07-03T03:45:23.185Z,1562125523.185 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-07-03T03:45:23.239Z,1562125523.239 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:45:23.245Z,1562125523.245 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-03T03:45:23.246Z,1562125523.246 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:45:23.253Z,1562125523.253 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-03T03:45:23.254Z,1562125523.254 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:45:23.261Z,1562125523.261 [MassServo](DEBUG): Initializing MassServo.
2019-07-03T03:45:23.262Z,1562125523.262 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:45:23.269Z,1562125523.269 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-03T03:45:23.270Z,1562125523.270 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:45:23.277Z,1562125523.277 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-03T03:45:23.421Z,1562125523.421 [Micromodem](INFO): Powering up
2019-07-03T03:45:23.421Z,1562125523.421 [Micromodem](DEBUG): Initializing Micromodem.
2019-07-03T03:45:24.161Z,1562125524.161 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-03T03:45:24.161Z,1562125524.161 [RudderServo](FAULT): Rudder failed to initialize
2019-07-03T03:45:24.161Z,1562125524.161 [RudderServo] Communications Fault, FailCount= 1
2019-07-03T03:45:24.161Z,1562125524.161 [RudderServo](ERROR): Communications Fault
2019-07-03T03:45:24.283Z,1562125524.283 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-03T03:45:24.454Z,1562125524.454 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-03T03:45:24.454Z,1562125524.454 [RudderServo](INFO): Powering down
2019-07-03T03:45:25.129Z,1562125525.129 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:45:25.250Z,1562125525.250 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-03T03:45:25.254Z,1562125525.254 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-03T03:45:25.254Z,1562125525.254 [RudderServo] No Fault, FailCount= 1
2019-07-03T03:45:28.371Z,1562125528.371 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-07-03T03:45:30.459Z,1562125530.459 [Micromodem](INFO): Nmea in: $CATMG,2019-07-03T03:45:28Z,RTC,RTC*78

2019-07-03T03:45:30.460Z,1562125530.460 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-07-03T03:45:28Z,RTC,RTC*78

2019-07-03T03:45:36.509Z,1562125536.509 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-07-03T03:45:39.731Z,1562125539.731 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-07-03T03:45:40.120Z,1562125540.120 [Micromodem](INFO): Nmea in: $CAERR,034539,NI  ,12,Unknown command*44

2019-07-03T03:45:40.120Z,1562125540.120 [Micromodem](ERROR): Got error from modem: $CAERR,034539,NI  ,12,Unknown command*44

2019-07-03T03:45:41.335Z,1562125541.335 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-07-03T03:45:41.753Z,1562125541.753 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-07-03T03:45:41.753Z,1562125541.753 [RDI_Pathfinder](ERROR): Failed to parse:
:RA   0.00,   0.00,   0.00,   0.00
2019-07-03T03:45:48.604Z,1562125548.604 [NAL9602](INFO): Powering up NAL9602
2019-07-03T03:45:51.027Z,1562125551.027 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-07-03T03:45:51.063Z,1562125551.063 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-03T03:45:51.071Z,1562125551.071 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-03T03:45:51.431Z,1562125551.431 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-07-03T03:45:51.431Z,1562125551.431 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-07-03T03:45:51.839Z,1562125551.839 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-07-03T03:45:51.839Z,1562125551.839 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-07-03T03:45:52.239Z,1562125552.239 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-07-03T03:45:52.239Z,1562125552.239 [Micromodem](INFO): Nmea out: $CCCFG,nav.nst,1*4D

2019-07-03T03:45:52.643Z,1562125552.643 [Micromodem](INFO): Nmea in: $CACFG,nav.nst,1*4F

2019-07-03T03:45:52.643Z,1562125552.643 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-07-03T03:45:53.047Z,1562125553.047 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-07-03T03:45:53.047Z,1562125553.047 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-07-03T03:45:53.575Z,1562125553.575 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-07-03T03:45:53.575Z,1562125553.575 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-07-03T03:45:53.971Z,1562125553.971 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-07-03T03:45:53.971Z,1562125553.971 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-07-03T03:45:54.379Z,1562125554.379 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-07-03T03:45:54.379Z,1562125554.379 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-07-03T03:45:54.779Z,1562125554.779 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-07-03T03:45:54.779Z,1562125554.779 [Micromodem](INFO): Nmea out: $CCCLK,2019,07,03,03,45,55*48

2019-07-03T03:45:55.183Z,1562125555.183 [Micromodem](INFO): Nmea in: $CACLK,2019,7,3,3,45,55*7A

2019-07-03T03:45:55.184Z,1562125555.184 [Micromodem](INFO): Nmea in: $CATMS,0,2019-07-03T03:45:56Z*79

2019-07-03T03:45:55.186Z,1562125555.186 [Micromodem](INFO): Nmea in: $CATMG,2019-07-03T03:45:56Z,USER_CMD,RTC*30

2019-07-03T03:45:59.640Z,1562125559.640 [NAL9602](INFO): NAL9602 initialized
2019-07-03T03:46:00.453Z,1562125560.453 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:02.141Z,1562125562.141 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.019774
CHAN A1 (24V): -0.025954
CHAN A2 (12V): -0.005882
CHAN A3 (5V): -0.001842
CHAN B0 (3.3V): 0.000078
CHAN B1 (3.15aV): -0.000169
CHAN B2 (3.15bV): 0.000395
CHAN B3 (GND): 0.001745
OPEN: 0.007059
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-03T03:46:05.737Z,1562125565.737 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2019-07-03T03:46:05.737Z,1562125565.737 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768-32768,V
2019-07-03T03:46:15.945Z,1562125575.945 [NAL9602](INFO): SBD MO Status=0, MOMSN=8002, MT Status=0, MTMSN=0
2019-07-03T03:46:15.945Z,1562125575.945 [NAL9602](INFO): No messages in MT queue
2019-07-03T03:46:16.765Z,1562125576.765 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:19.197Z,1562125579.197 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:22.013Z,1562125582.013 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:25.245Z,1562125585.245 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:28.077Z,1562125588.077 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:31.305Z,1562125591.305 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:34.205Z,1562125594.205 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:37.449Z,1562125597.449 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:40.277Z,1562125600.277 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:43.513Z,1562125603.513 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:44.355Z,1562125604.355 [SBIT](IMPORTANT): SBIT PASSED
2019-07-03T03:46:44.410Z,1562125604.410 [CommandLine](IMPORTANT): got command configSet list
2019-07-03T03:46:44.410Z,1562125604.410 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-03T03:46:44.411Z,1562125604.411 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=25 count;

2019-07-03T03:46:44.771Z,1562125604.771 [MissionManager](IMPORTANT): Started mission Startup
2019-07-03T03:46:44.771Z,1562125604.771 [Startup] Running Loop=1
2019-07-03T03:46:44.771Z,1562125604.771 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-03T03:46:44.772Z,1562125604.772 [Startup:A.GoToSurface] Running Loop=1
2019-07-03T03:46:44.772Z,1562125604.772 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-03T03:46:44.772Z,1562125604.772 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-03T03:46:44.773Z,1562125604.773 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-03T03:46:44.773Z,1562125604.773 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-03T03:46:44.774Z,1562125604.774 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-03T03:46:44.774Z,1562125604.774 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-03T03:46:44.775Z,1562125604.775 [Startup:StartupSatComms] Running Loop=1
2019-07-03T03:46:44.775Z,1562125604.775 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-03T03:46:44.775Z,1562125604.775 [Startup:StartupSatComms:A] Running Loop=1
2019-07-03T03:46:45.138Z,1562125605.138 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-03T03:46:46.341Z,1562125606.341 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:49.573Z,1562125609.573 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:52.401Z,1562125612.401 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:52.824Z,1562125612.824 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-07-03T03:46:52.824Z,1562125612.824 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,

2019-07-03T03:46:55.225Z,1562125615.225 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:46:58.053Z,1562125618.053 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:01.289Z,1562125621.289 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:04.117Z,1562125624.117 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:07.353Z,1562125627.353 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:10.177Z,1562125630.177 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:13.405Z,1562125633.405 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:16.233Z,1562125636.233 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:19.465Z,1562125639.465 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:22.293Z,1562125642.293 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:23.930Z,1562125643.930 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-07-03T03:47:25.525Z,1562125645.525 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:28.373Z,1562125648.373 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:31.181Z,1562125651.181 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:34.417Z,1562125654.417 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:37.245Z,1562125657.245 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:40.081Z,1562125660.081 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:43.309Z,1562125663.309 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:44.939Z,1562125664.939 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-03T03:46:44.8Z
2019-07-03T03:47:44.940Z,1562125664.940 [Startup:StartupSatComms:A] Stopped
2019-07-03T03:47:44.940Z,1562125664.940 [Startup:StartupSatComms:B] Running Loop=1
2019-07-03T03:47:45.338Z,1562125665.338 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-03T03:47:46.637Z,1562125666.637 [Startup:StartupSatComms:B] Stopped
2019-07-03T03:47:46.637Z,1562125666.637 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-03T03:47:46.637Z,1562125666.637 [Startup:StartupSatComms] Stopped
2019-07-03T03:47:46.637Z,1562125666.637 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-03T03:47:46.638Z,1562125666.638 [Startup](INFO): Completed Startup
2019-07-03T03:47:46.638Z,1562125666.638 [MissionManager](INFO): Startup is completed.
2019-07-03T03:47:46.638Z,1562125666.638 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-03T03:47:46.638Z,1562125666.638 [Startup] Stopped
2019-07-03T03:47:46.638Z,1562125666.638 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-03T03:47:46.638Z,1562125666.638 [Startup:A.GoToSurface] Stopped
2019-07-03T03:47:46.638Z,1562125666.638 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-03T03:47:46.729Z,1562125666.729 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:46.758Z,1562125666.758 [MissionManager](IMPORTANT): Started mission Default
2019-07-03T03:47:46.761Z,1562125666.761 [Default] Running Loop=1
2019-07-03T03:47:46.761Z,1562125666.761 [Default](DEBUG): Aggregate::initialize Default
2019-07-03T03:47:46.761Z,1562125666.761 [Default:B.GoToSurface] Running Loop=1
2019-07-03T03:47:46.761Z,1562125666.761 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-03T03:47:46.762Z,1562125666.762 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-03T03:47:46.762Z,1562125666.762 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-03T03:47:46.762Z,1562125666.762 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-03T03:47:46.762Z,1562125666.762 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-03T03:47:46.763Z,1562125666.763 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-03T03:47:46.763Z,1562125666.763 [Default:A.Wait] Running Loop=1
2019-07-03T03:47:46.763Z,1562125666.763 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-03T03:47:49.497Z,1562125669.497 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:52.329Z,1562125672.329 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:55.560Z,1562125675.560 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:47:58.401Z,1562125678.401 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:00.014Z,1562125680.014 [Default:A.Wait](INFO): Done Waiting.
2019-07-03T03:48:00.014Z,1562125680.014 [Default:A.Wait] Stopped
2019-07-03T03:48:00.014Z,1562125680.014 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-03T03:48:00.424Z,1562125680.424 [Default:CheckIn] Running Loop=1
2019-07-03T03:48:00.424Z,1562125680.424 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-03T03:48:00.424Z,1562125680.424 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-03T03:48:00.828Z,1562125680.828 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-03T03:48:01.617Z,1562125681.617 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:04.445Z,1562125684.445 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:07.681Z,1562125687.681 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:10.509Z,1562125690.509 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:13.333Z,1562125693.333 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:16.161Z,1562125696.161 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:19.401Z,1562125699.401 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:22.225Z,1562125702.225 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:22.755Z,1562125702.755 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-03T03:48:22.755Z,1562125702.755 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-03T03:48:22.778Z,1562125702.778 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-03T03:48:23.090Z,1562125703.090 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-03T03:48:23.090Z,1562125703.090 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-03T03:48:25.453Z,1562125705.453 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:28.281Z,1562125708.281 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:31.513Z,1562125711.513 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:34.341Z,1562125714.341 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:37.573Z,1562125717.573 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:40.401Z,1562125720.401 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:43.633Z,1562125723.633 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:46.461Z,1562125726.461 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:46.831Z,1562125726.831 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004920
2019-07-03T03:48:49.701Z,1562125729.701 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:52.528Z,1562125732.528 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:55.357Z,1562125735.357 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:48:58.177Z,1562125738.177 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:01.421Z,1562125741.421 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:04.237Z,1562125744.237 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:07.473Z,1562125747.473 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:10.301Z,1562125750.301 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:13.549Z,1562125753.549 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:16.361Z,1562125756.361 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:19.593Z,1562125759.593 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:22.449Z,1562125762.449 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:25.653Z,1562125765.653 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:28.481Z,1562125768.481 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:31.325Z,1562125771.325 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:34.541Z,1562125774.541 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:37.385Z,1562125777.385 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:40.193Z,1562125780.193 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:43.425Z,1562125783.425 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:46.256Z,1562125786.256 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:49.485Z,1562125789.485 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:52.313Z,1562125792.313 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:55.141Z,1562125795.141 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:49:58.385Z,1562125798.385 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:01.201Z,1562125801.201 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:02.828Z,1562125802.828 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-07-03T03:50:02.828Z,1562125802.828 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,
2019-07-03T03:50:04.433Z,1562125804.433 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:07.277Z,1562125807.277 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:10.493Z,1562125810.493 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:13.325Z,1562125813.325 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:16.157Z,1562125816.157 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:19.393Z,1562125819.393 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:50:19.777Z,1562125819.777 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,035006.00,A,3648.62706,N,12149.67983,W,0.719,294.78,030719,,,A*7F
2019-07-03T03:50:19.780Z,1562125819.780 [NAL9602](INFO): GPS fix at 20190703T035006: (36.810451, -121.827997)
2019-07-03T03:50:19.832Z,1562125819.832 [Default:CheckIn:Read_GPS] Stopped
2019-07-03T03:50:19.832Z,1562125819.832 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-03T03:50:20.236Z,1562125820.236 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-03T03:50:21.663Z,1562125821.663 [Micromodem](INFO): Outgoing frame #1, 64 bytes: C6241C5D040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567
2019-07-03T03:50:21.663Z,1562125821.663 [Micromodem](INFO): Outgoing frame #2, 64 bytes: 266CC0E6F1A517638CB0C0B8BE3619E02B8F4A169EC22D30546A87042BC836DF836B942BC3C4A9EFC1B6C4BDD91F97B2782B4B03CB56EA92D77C6909485B9FDE
2019-07-03T03:50:21.664Z,1562125821.664 [Micromodem](INFO): Outgoing frame #3, 64 bytes: C9BA76D6E11C7243AB9F1CB76D4E14F7CBE1C6B0B40F2F0A19DC25B10B3C6279A2D80F52F03F1275F5BE973EA20943C61E76D18516091C61B31E7EB6330E33DC
2019-07-03T03:50:21.664Z,1562125821.664 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-03T03:50:21.903Z,1562125821.903 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-07-03T03:50:22.255Z,1562125822.255 [Micromodem](INFO): Nmea in: $CADRQ,035022,1,9,0,64,1*48

2019-07-03T03:50:22.255Z,1562125822.255 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,C6241C5D040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*79

2019-07-03T03:50:22.691Z,1562125822.691 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-03T03:50:23.075Z,1562125823.075 [Micromodem](INFO): Nmea in: $CADRQ,035023,1,9,0,64,2*4A

2019-07-03T03:50:23.075Z,1562125823.075 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,266CC0E6F1A517638CB0C0B8BE3619E02B8F4A169EC22D30546A87042BC836DF836B942BC3C4A9EFC1B6C4BDD91F97B2782B4B03CB56EA92D77C6909485B9FDE*74

2019-07-03T03:50:23.483Z,1562125823.483 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-03T03:50:23.895Z,1562125823.895 [Micromodem](INFO): Nmea in: $CADRQ,035024,1,9,0,64,3*4C

2019-07-03T03:50:23.895Z,1562125823.895 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,C9BA76D6E11C7243AB9F1CB76D4E14F7CBE1C6B0B40F2F0A19DC25B10B3C6279A2D80F52F03F1275F5BE973EA20943C61E76D18516091C61B31E7EB6330E33DC*08

2019-07-03T03:50:24.286Z,1562125824.286 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-03T03:50:24.698Z,1562125824.698 [Micromodem](INFO): Nmea in: $CATXP,192*48

2019-07-03T03:50:28.334Z,1562125828.334 [Micromodem](INFO): Nmea in: $CATXF,192*5E

2019-07-03T03:50:28.732Z,1562125828.732 [Micromodem](INFO): Nmea in: $CAXST,6,20190703,035025.166780,3,0,200,4000,10000,1,1,9,1,3,3,3,192*41

2019-07-03T03:50:30.141Z,1562125830.141 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190703T034510/Courier0004.lzma
2019-07-03T03:50:30.946Z,1562125830.946 [DataOverHttps](INFO): Moved sent file to Logs/20190703T034510/Courier0004.lzma.bak
2019-07-03T03:50:30.947Z,1562125830.947 [DataOverHttps](INFO): SBD MOMSN=11423628
2019-07-03T03:50:46.610Z,1562125846.610 [DataOverHttps](INFO): Sending 218 bytes from file Logs/20190703T033803/Express0008.lzma
2019-07-03T03:50:47.414Z,1562125847.414 [DataOverHttps](INFO): Moved sent file to Logs/20190703T033803/Express0008.lzma.bak
2019-07-03T03:50:47.415Z,1562125847.415 [DataOverHttps](INFO): SBD MOMSN=11423632
2019-07-03T03:50:52.163Z,1562125852.163 [NAL9602](INFO): Powering down
2019-07-03T03:51:00.962Z,1562125860.962 [DataOverHttps](INFO): Sending 649 bytes from file Logs/20190703T034510/Express0001.lzma
2019-07-03T03:51:01.766Z,1562125861.766 [DataOverHttps](INFO): Moved sent file to Logs/20190703T034510/Express0001.lzma.bak
2019-07-03T03:51:01.766Z,1562125861.766 [DataOverHttps](INFO): SBD MOMSN=11423637
2019-07-03T03:51:15.525Z,1562125875.525 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20190703T034510/Express0005.lzma
2019-07-03T03:51:16.333Z,1562125876.333 [DataOverHttps](INFO): Moved sent file to Logs/20190703T034510/Express0005.lzma.bak
2019-07-03T03:51:16.333Z,1562125876.333 [DataOverHttps](INFO): SBD MOMSN=11423651
2019-07-03T03:51:18.481Z,1562125878.481 [Default:CheckIn:Read_Iridium] Stopped
2019-07-03T03:51:18.481Z,1562125878.481 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-03T03:51:18.481Z,1562125878.481 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-03T03:51:44.729Z,1562125904.729 [RDI_Pathfinder](ERROR): Failed to parse:
:8,-32768,-32768,V
2019-07-03T03:53:31.778Z,1562126011.778 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-07-03T03:53:31.779Z,1562126011.779 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19070221031934,35.0, -0.1,   0.0,1448.9A,  0.00,   0.00,   0.00,   0.00,   0.00
2019-07-03T03:53:42.340Z,1562126022.340 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-07-03T03:53:42.343Z,1562126022.343 [BPC1](INFO): Received data from all battery sticks.
2019-07-03T03:53:51.646Z,1562126031.646 [DataOverHttps](IMPORTANT): SBD MTMSN=20190703T035339
2019-07-03T03:53:56.957Z,1562126036.957 [DataOverHttps](INFO): Received command:configSet DUSBL_Hydroid.verbosity 3 count persist;configSet NAL9602.fastGPSFix 1 bool persist
2019-07-03T03:53:57.331Z,1562126037.331 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.verbosity 3.000000 count persist
2019-07-03T03:53:57.339Z,1562126037.339 [CommandLine](IMPORTANT): got command configSet NAL9602.fastGPSFix 1.000000 bool persist
2019-07-03T03:55:02.384Z,1562126102.384 [CommandLine](IMPORTANT): got command get Micromodem.loadAtStartup
2019-07-03T03:55:02.384Z,1562126102.384 [CommandLine](IMPORTANT): Micromodem.loadAtStartup 1 bool
2019-07-03T03:55:31.294Z,1562126131.294 [CommandLine](IMPORTANT): got command configSet HorizontalControl.rudDeadband 0.050000 degree persist
2019-07-03T03:55:57.007Z,1562126157.007 [CommandLine](IMPORTANT): got command configSet HorizontalControl.kpHeading 0.800000 none persist
2019-07-03T03:56:19.030Z,1562126179.030 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-07-03T03:56:19.030Z,1562126179.030 [Default:CheckIn:C.Wait] Stopped
2019-07-03T03:56:19.030Z,1562126179.030 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-03T03:56:19.030Z,1562126179.030 [Default:CheckIn:D] Running Loop=1
2019-07-03T03:56:19.445Z,1562126179.445 [Default:CheckIn:D] Stopped
2019-07-03T03:56:19.445Z,1562126179.445 [Default:CheckIn:E] Running Loop=1
2019-07-03T03:56:19.874Z,1562126179.874 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.544777 min 
2019-07-03T03:56:19.874Z,1562126179.874 [Default:CheckIn:E] Stopped
2019-07-03T03:56:19.874Z,1562126179.874 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-07-03T03:56:19.874Z,1562126179.874 [Default:CheckIn] Stopped
2019-07-03T03:56:19.874Z,1562126179.874 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-03T03:56:19.874Z,1562126179.874 [Default:CheckIn](INFO): Running loop #2
2019-07-03T03:56:19.875Z,1562126179.875 [Default:CheckIn] Running Loop=2
2019-07-03T03:56:19.875Z,1562126179.875 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-03T03:56:19.875Z,1562126179.875 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-03T03:56:20.615Z,1562126180.615 [NAL9602](INFO): Powering up
2019-07-03T03:56:24.418Z,1562126184.418 [CommandLine](IMPORTANT): got command configSet Express linearApproximation acoustic_contact_range 1.000000 meter persist
2019-07-03T03:56:31.523Z,1562126191.523 [NAL9602](INFO): NAL9602 initialized
2019-07-03T03:56:32.357Z,1562126192.357 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:56:47.688Z,1562126207.688 [NAL9602](INFO): SBD MO Status=0, MOMSN=8003, MT Status=0, MTMSN=0
2019-07-03T03:56:47.688Z,1562126207.688 [NAL9602](INFO): No messages in MT queue
2019-07-03T03:56:48.505Z,1562126208.505 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:56:49.700Z,1562126209.700 [CommandLine](IMPORTANT): got command configSet Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter persist
2019-07-03T03:56:51.333Z,1562126211.333 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:56:54.161Z,1562126214.161 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:56:56.989Z,1562126216.989 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:00.221Z,1562126220.221 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:03.069Z,1562126223.069 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:06.281Z,1562126226.281 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:09.113Z,1562126229.113 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:11.282Z,1562126231.282 [CommandLine](IMPORTANT): got command configSet list
2019-07-03T03:57:11.282Z,1562126231.282 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-03T03:57:11.283Z,1562126231.283 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=25 count;

2019-07-03T03:57:11.283Z,1562126231.283 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity=3 count;

2019-07-03T03:57:11.283Z,1562126231.283 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-07-03T03:57:11.283Z,1562126231.283 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-07-03T03:57:11.283Z,1562126231.283 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none;

2019-07-03T03:57:11.283Z,1562126231.283 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree;

2019-07-03T03:57:11.283Z,1562126231.283 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-07-03T03:57:12.349Z,1562126232.349 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:15.169Z,1562126235.169 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:18.405Z,1562126238.405 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:21.229Z,1562126241.229 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:24.061Z,1562126244.061 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:27.289Z,1562126247.289 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:30.121Z,1562126250.121 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:33.353Z,1562126253.353 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:36.181Z,1562126256.181 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:39.425Z,1562126259.425 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:42.241Z,1562126262.241 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:45.069Z,1562126265.069 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:48.297Z,1562126268.297 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:51.125Z,1562126271.125 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:54.361Z,1562126274.361 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:57:57.185Z,1562126277.185 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:58:00.417Z,1562126280.417 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:58:03.245Z,1562126283.245 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:58:05.058Z,1562126285.058 [DataOverHttps](IMPORTANT): SBD MTMSN=20190703T035752
2019-07-03T03:58:06.069Z,1562126286.069 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:58:09.305Z,1562126289.305 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:58:10.480Z,1562126290.480 [DataOverHttps](INFO): Received command:restart app
2019-07-03T03:58:10.500Z,1562126290.500 [CommandLine](IMPORTANT): got command restart application
2019-07-03T03:58:11.513Z,1562126291.513 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-07-03T03:58:11.513Z,1562126291.513 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:11.513Z,1562126291.513 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:11.713Z,1562126291.713 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-03T03:58:11.713Z,1562126291.713 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:11.714Z,1562126291.714 [CommandLine](INFO): Join timeout helper Thread ID is 938
2019-07-03T03:58:11.725Z,1562126291.725 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-03T03:58:11.725Z,1562126291.725 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:11.727Z,1562126291.727 [NavChartDb](INFO): Join timeout helper Thread ID is 939
2019-07-03T03:58:12.005Z,1562126292.005 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:12.005Z,1562126292.005 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.028Z,1562126292.028 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-07-03T03:58:12.028Z,1562126292.028 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.028Z,1562126292.028 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 940
2019-07-03T03:58:12.141Z,1562126292.141 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:58:12.293Z,1562126292.293 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:12.293Z,1562126292.293 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-03T03:58:12.294Z,1562126292.294 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.309Z,1562126292.309 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-07-03T03:58:12.309Z,1562126292.309 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.309Z,1562126292.309 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 941
2019-07-03T03:58:12.365Z,1562126292.365 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:12.365Z,1562126292.365 [CTD_NeilBrown](INFO): Powering down
2019-07-03T03:58:12.377Z,1562126292.377 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.389Z,1562126292.389 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-03T03:58:12.389Z,1562126292.389 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.389Z,1562126292.389 [Radio_Surface](INFO): Join timeout helper Thread ID is 942
2019-07-03T03:58:12.697Z,1562126292.697 [Radio_Surface](INFO): Powering down
2019-07-03T03:58:12.698Z,1562126292.698 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:12.698Z,1562126292.698 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.702Z,1562126292.702 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-03T03:58:12.702Z,1562126292.702 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.702Z,1562126292.702 [DataOverHttps](INFO): Join timeout helper Thread ID is 943
2019-07-03T03:58:12.901Z,1562126292.901 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:12.901Z,1562126292.901 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.928Z,1562126292.928 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-03T03:58:12.928Z,1562126292.928 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.929Z,1562126292.929 [logger](INFO): Join timeout helper Thread ID is 944
2019-07-03T03:58:12.961Z,1562126292.961 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:12.961Z,1562126292.961 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.970Z,1562126292.970 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-03T03:58:12.970Z,1562126292.970 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.970Z,1562126292.970 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-03T03:58:12.970Z,1562126292.970 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:12.970Z,1562126292.970 [controlThread](INFO): Join timeout helper Thread ID is 945
2019-07-03T03:58:12.980Z,1562126292.980 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:58:12.981Z,1562126292.981 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-03T03:58:12.981Z,1562126292.981 [AHRS_M2](INFO): Powering down
2019-07-03T03:58:13.054Z,1562126293.054 [DUSBL_Hydroid](INFO): Powering down
2019-07-03T03:58:13.145Z,1562126293.145 [Micromodem](INFO): Powering down
2019-07-03T03:58:13.241Z,1562126293.241 [NAL9602](INFO): Powering down
2019-07-03T03:58:13.313Z,1562126293.313 [RDI_Pathfinder](INFO): Powering down
2019-07-03T03:58:13.314Z,1562126293.314 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-03T03:58:13.315Z,1562126293.315 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-03T03:58:13.316Z,1562126293.316 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-03T03:58:13.316Z,1562126293.316 [MissionManager](INFO): Uninitializing Mission Default
2019-07-03T03:58:13.316Z,1562126293.316 [Default] Stopped
2019-07-03T03:58:13.316Z,1562126293.316 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-03T03:58:13.316Z,1562126293.316 [Default:B.GoToSurface] Stopped
2019-07-03T03:58:13.316Z,1562126293.316 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-03T03:58:13.316Z,1562126293.316 [Default:CheckIn] Stopped
2019-07-03T03:58:13.317Z,1562126293.317 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-03T03:58:13.317Z,1562126293.317 [Default:CheckIn:Read_GPS] Stopped
2019-07-03T03:58:13.319Z,1562126293.319 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-03T03:58:13.319Z,1562126293.319 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-03T03:58:13.320Z,1562126293.320 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-03T03:58:13.320Z,1562126293.320 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-03T03:58:13.320Z,1562126293.320 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-03T03:58:13.320Z,1562126293.320 [BuoyancyServo](INFO): Powering down
2019-07-03T03:58:13.333Z,1562126293.333 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-03T03:58:13.333Z,1562126293.333 [ElevatorServo](INFO): Powering down
2019-07-03T03:58:13.334Z,1562126293.334 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-03T03:58:13.334Z,1562126293.334 [MassServo](INFO): Powering down
2019-07-03T03:58:13.335Z,1562126293.335 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-03T03:58:13.335Z,1562126293.335 [RudderServo](INFO): Powering down
2019-07-03T03:58:13.336Z,1562126293.336 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-03T03:58:13.336Z,1562126293.336 [ThrusterServo](INFO): Powering down
2019-07-03T03:58:13.336Z,1562126293.336 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-03T03:58:13.337Z,1562126293.337 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-03T03:58:13.337Z,1562126293.337 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-03T03:58:13.337Z,1562126293.337 [CBIT](DEBUG): Powering off loads.
2019-07-03T03:58:13.349Z,1562126293.349 [CBIT](DEBUG): Disabling WDT.
2019-07-03T03:58:13.361Z,1562126293.361 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-03T03:58:13.362Z,1562126293.362 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:13.418Z,1562126293.418 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:13.427Z,1562126293.427 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:13.468Z,1562126293.468 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:13.470Z,1562126293.470 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:13.527Z,1562126293.527 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:58:13.596Z,1562126293.596 [logger ThreadHandler](INFO): Thread cancelled.