2019-05-21T14:29:06.427Z,1558448946.427 [Supervisor](DEBUG): Initializing supervisor.
2019-05-21T14:29:06.430Z,1558448946.430 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-21T14:29:06.430Z,1558448946.430 [SyncHandler](INFO): Protected caller Thread ID is 3980
2019-05-21T14:29:06.431Z,1558448946.431 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-21T14:29:06.432Z,1558448946.432 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-21T14:29:06.432Z,1558448946.432 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3981
2019-05-21T14:29:06.435Z,1558448946.435 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-21T14:29:06.650Z,1558448946.650 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-21T14:29:06.651Z,1558448946.651 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-21T14:29:06.651Z,1558448946.651 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3982
2019-05-21T14:29:06.652Z,1558448946.652 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-21T14:29:06.653Z,1558448946.653 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-21T14:29:06.653Z,1558448946.653 [logger ThreadHandler](INFO): Protected caller Thread ID is 3983
2019-05-21T14:29:06.655Z,1558448946.655 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-21T14:29:06.656Z,1558448946.656 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-21T14:29:06.657Z,1558448946.657 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-21T14:29:07.077Z,1558448947.077 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-21T14:29:07.078Z,1558448947.078 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-21T14:29:07.178Z,1558448947.178 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-21T14:29:07.178Z,1558448947.178 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-21T14:29:07.503Z,1558448947.503 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-21T14:29:07.503Z,1558448947.503 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-21T14:29:07.647Z,1558448947.647 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-21T14:29:07.648Z,1558448947.648 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-21T14:29:07.840Z,1558448947.840 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-21T14:29:07.840Z,1558448947.840 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-21T14:29:08.295Z,1558448948.295 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-21T14:29:08.295Z,1558448948.295 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-21T14:29:08.506Z,1558448948.506 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-21T14:29:08.506Z,1558448948.506 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-21T14:29:08.653Z,1558448948.653 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-21T14:29:08.654Z,1558448948.654 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-21T14:29:08.848Z,1558448948.848 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-21T14:29:08.849Z,1558448948.849 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-21T14:29:08.946Z,1558448948.946 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-21T14:29:08.947Z,1558448948.947 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-21T14:29:09.267Z,1558448949.267 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-21T14:29:09.268Z,1558448949.268 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-21T14:29:09.350Z,1558448949.350 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-21T14:29:09.454Z,1558448949.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-21T14:29:09.455Z,1558448949.455 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-21T14:29:10.044Z,1558448950.044 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-21T14:29:10.045Z,1558448950.045 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-21T14:29:10.433Z,1558448950.433 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-21T14:29:10.435Z,1558448950.435 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-21T14:29:10.436Z,1558448950.436 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-21T14:29:10.646Z,1558448950.646 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-21T14:29:10.747Z,1558448950.747 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-21T14:29:10.847Z,1558448950.847 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-21T14:29:11.075Z,1558448951.075 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-21T14:29:11.075Z,1558448951.075 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-21T14:29:11.161Z,1558448951.161 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-21T14:29:11.257Z,1558448951.257 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-21T14:29:11.355Z,1558448951.355 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-21T14:29:11.448Z,1558448951.448 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-21T14:29:11.634Z,1558448951.634 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-21T14:29:11.981Z,1558448951.981 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-21T14:29:12.527Z,1558448952.527 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/LOGIN/
2019-05-21T14:29:12.527Z,1558448952.527 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-21T14:29:12.542Z,1558448952.542 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-21T14:29:12.912Z,1558448952.912 [AHRS_M2] Loaded
2019-05-21T14:29:12.912Z,1558448952.912 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-21T14:29:12.984Z,1558448952.984 [DataOverHttps] Loaded
2019-05-21T14:29:12.985Z,1558448952.985 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-21T14:29:12.986Z,1558448952.986 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407604E0
2019-05-21T14:29:12.986Z,1558448952.986 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 4062
2019-05-21T14:29:12.999Z,1558448952.999 [Depth_Keller] Loaded
2019-05-21T14:29:12.999Z,1558448952.999 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-21T14:29:13.004Z,1558448953.004 [DropWeight] Loaded
2019-05-21T14:29:13.004Z,1558448953.004 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-21T14:29:13.060Z,1558448953.060 [DUSBL_Hydroid] Loaded
2019-05-21T14:29:13.060Z,1558448953.060 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-21T14:29:13.106Z,1558448953.106 [Micromodem] Loaded
2019-05-21T14:29:13.106Z,1558448953.106 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-21T14:29:13.202Z,1558448953.202 [NAL9602] Loaded
2019-05-21T14:29:13.202Z,1558448953.202 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-21T14:29:13.218Z,1558448953.218 [Onboard] Loaded
2019-05-21T14:29:13.218Z,1558448953.218 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-21T14:29:13.224Z,1558448953.224 [PowerOnly] Loaded
2019-05-21T14:29:13.224Z,1558448953.224 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-21T14:29:13.230Z,1558448953.230 [Radio_Surface] Loaded
2019-05-21T14:29:13.231Z,1558448953.231 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-21T14:29:13.232Z,1558448953.232 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407904E0
2019-05-21T14:29:13.232Z,1558448953.232 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 4063
2019-05-21T14:29:13.275Z,1558448953.275 [RDI_Pathfinder] Loaded
2019-05-21T14:29:13.275Z,1558448953.275 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-21T14:29:14.754Z,1558448954.754 [BPC1] Loaded
2019-05-21T14:29:14.755Z,1558448954.755 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-21T14:29:14.755Z,1558448954.755 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-21T14:29:14.756Z,1558448954.756 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-21T14:29:14.768Z,1558448954.768 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-21T14:29:14.769Z,1558448954.769 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-21T14:29:14.872Z,1558448954.872 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-21T14:29:14.872Z,1558448954.872 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-21T14:29:14.892Z,1558448954.892 [NavChart] Loaded
2019-05-21T14:29:14.893Z,1558448954.893 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-21T14:29:14.896Z,1558448954.896 [UniversalFixResidualReporter] Loaded
2019-05-21T14:29:14.897Z,1558448954.897 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-21T14:29:14.897Z,1558448954.897 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-21T14:29:14.898Z,1558448954.898 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-21T14:29:15.002Z,1558448955.002 [BuoyancyServo] Loaded
2019-05-21T14:29:15.003Z,1558448955.003 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-21T14:29:15.017Z,1558448955.017 [ElevatorServo] Loaded
2019-05-21T14:29:15.018Z,1558448955.018 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-21T14:29:15.032Z,1558448955.032 [MassServo] Loaded
2019-05-21T14:29:15.032Z,1558448955.032 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-21T14:29:15.048Z,1558448955.048 [RudderServo] Loaded
2019-05-21T14:29:15.048Z,1558448955.048 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-21T14:29:15.063Z,1558448955.063 [ThrusterServo] Loaded
2019-05-21T14:29:15.063Z,1558448955.063 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-21T14:29:15.063Z,1558448955.063 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-21T14:29:15.064Z,1558448955.064 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-21T14:29:15.308Z,1558448955.308 [CTD_NeilBrown] Loaded
2019-05-21T14:29:15.308Z,1558448955.308 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-21T14:29:15.309Z,1558448955.309 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D24E0
2019-05-21T14:29:15.310Z,1558448955.310 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 4064
2019-05-21T14:29:15.353Z,1558448955.353 [WetLabsSeaOWL_UV_A] Loaded
2019-05-21T14:29:15.354Z,1558448955.354 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-21T14:29:15.355Z,1558448955.355 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409024E0
2019-05-21T14:29:15.355Z,1558448955.355 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 4065
2019-05-21T14:29:15.356Z,1558448955.356 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-21T14:29:15.356Z,1558448955.356 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-21T14:29:15.639Z,1558448955.639 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-21T14:29:15.639Z,1558448955.639 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-21T14:29:15.679Z,1558448955.679 [DepthRateCalculator] Loaded
2019-05-21T14:29:15.679Z,1558448955.679 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-21T14:29:15.685Z,1558448955.685 [PitchRateCalculator] Loaded
2019-05-21T14:29:15.685Z,1558448955.685 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-21T14:29:15.697Z,1558448955.697 [SpeedCalculator] Loaded
2019-05-21T14:29:15.698Z,1558448955.698 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-21T14:29:15.718Z,1558448955.718 [TempGradientCalculator] Loaded
2019-05-21T14:29:15.718Z,1558448955.718 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-21T14:29:15.724Z,1558448955.724 [YawRateCalculator] Loaded
2019-05-21T14:29:15.724Z,1558448955.724 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-21T14:29:15.763Z,1558448955.763 [ElevatorOffsetCalculator] Loaded
2019-05-21T14:29:15.764Z,1558448955.764 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-21T14:29:15.764Z,1558448955.764 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-21T14:29:15.765Z,1558448955.765 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-21T14:29:15.896Z,1558448955.896 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-21T14:29:15.917Z,1558448955.917 [SBIT] Loaded
2019-05-21T14:29:15.918Z,1558448955.918 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-21T14:29:15.918Z,1558448955.918 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-21T14:29:15.930Z,1558448955.930 [IBIT] Loaded
2019-05-21T14:29:15.930Z,1558448955.930 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-21T14:29:15.933Z,1558448955.933 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-21T14:29:16.068Z,1558448956.068 [CBIT] Loaded
2019-05-21T14:29:16.069Z,1558448956.069 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-21T14:29:16.069Z,1558448956.069 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-21T14:29:16.070Z,1558448956.070 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-21T14:29:16.138Z,1558448956.138 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-21T14:29:16.139Z,1558448956.139 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-21T14:29:16.233Z,1558448956.233 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-21T14:29:16.234Z,1558448956.234 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-21T14:29:16.298Z,1558448956.298 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-21T14:29:16.380Z,1558448956.380 [VerticalControl] Loaded
2019-05-21T14:29:16.381Z,1558448956.381 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-21T14:29:16.381Z,1558448956.381 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-21T14:29:16.438Z,1558448956.438 [HorizontalControl] Loaded
2019-05-21T14:29:16.438Z,1558448956.438 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-21T14:29:16.438Z,1558448956.438 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-21T14:29:16.440Z,1558448956.440 [SpeedControl] Loaded
2019-05-21T14:29:16.440Z,1558448956.440 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-21T14:29:16.441Z,1558448956.441 [LoopControl](DEBUG): Construct LoopControl.
2019-05-21T14:29:16.442Z,1558448956.442 [LoopControl] Loaded
2019-05-21T14:29:16.442Z,1558448956.442 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-21T14:29:16.442Z,1558448956.442 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-21T14:29:16.443Z,1558448956.443 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-21T14:29:16.590Z,1558448956.590 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-21T14:29:16.594Z,1558448956.594 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-21T14:29:16.595Z,1558448956.595 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-21T14:29:16.601Z,1558448956.601 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-21T14:29:16.602Z,1558448956.602 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD94E0
2019-05-21T14:29:16.603Z,1558448956.603 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 4066
2019-05-21T14:29:16.607Z,1558448956.607 [Supervisor](INFO): Main Thread ID is 3979
2019-05-21T14:29:16.607Z,1558448956.607 [Supervisor](DEBUG): Running supervisor.
2019-05-21T14:29:16.608Z,1558448956.608 [CommandLine ThreadHandler](INFO): Handler Thread ID is 4067
2019-05-21T14:29:16.610Z,1558448956.610 [controlThread ThreadHandler](INFO): Handler Thread ID is 4068
2019-05-21T14:29:16.610Z,1558448956.610 [controlThread](DEBUG): Initializing ControlThread
2019-05-21T14:29:16.621Z,1558448956.621 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-21T14:29:16.621Z,1558448956.621 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-21T14:29:16.622Z,1558448956.622 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-21T14:29:16.623Z,1558448956.623 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-21T14:29:16.623Z,1558448956.623 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-21T14:29:16.623Z,1558448956.623 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-21T14:29:16.624Z,1558448956.624 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-21T14:29:16.624Z,1558448956.624 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-21T14:29:16.625Z,1558448956.625 [SBIT](INFO): Initialize SBIT Component.
2019-05-21T14:29:16.625Z,1558448956.625 [SBIT](IMPORTANT): git: 2019-05-01-9-g5be6d91
2019-05-21T14:29:16.625Z,1558448956.625 [SBIT](INFO): git hash: 5be6d91bfd1d3ef858080230e47d423d1f938b96
2019-05-21T14:29:16.626Z,1558448956.626 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-21T14:29:16.627Z,1558448956.627 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-05-21T14:29:16.628Z,1558448956.628 [SBIT](INFO): Beginning SBIT in 52.000000 seconds.
2019-05-21T14:29:16.628Z,1558448956.628 [IBIT](INFO): Initialize IBIT Component.
2019-05-21T14:29:16.629Z,1558448956.629 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-21T14:29:16.630Z,1558448956.630 [logger ThreadHandler](INFO): Handler Thread ID is 4069
2019-05-21T14:29:16.641Z,1558448956.641 [CBIT](DEBUG): Initialized mux pins.
2019-05-21T14:29:16.641Z,1558448956.641 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-21T14:29:16.649Z,1558448956.649 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 4070
2019-05-21T14:29:16.650Z,1558448956.650 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-21T14:29:16.661Z,1558448956.661 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 4071
2019-05-21T14:29:16.665Z,1558448956.665 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-21T14:29:16.665Z,1558448956.665 [CBIT](DEBUG): Initializing heartbeat.
2019-05-21T14:29:16.681Z,1558448956.681 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 4072
2019-05-21T14:29:16.682Z,1558448956.682 [CTD_NeilBrown](INFO): Powering down
2019-05-21T14:29:16.717Z,1558448956.717 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 4073
2019-05-21T14:29:16.718Z,1558448956.718 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-21T14:29:16.737Z,1558448956.737 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-21T14:29:16.737Z,1558448956.737 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-21T14:29:16.741Z,1558448956.741 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 4074
2019-05-21T14:29:16.745Z,1558448956.745 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-21T14:29:16.745Z,1558448956.745 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-21T14:29:16.745Z,1558448956.745 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-21T14:29:16.745Z,1558448956.745 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-21T14:29:16.745Z,1558448956.745 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-21T14:29:16.745Z,1558448956.745 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-21T14:29:16.746Z,1558448956.746 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-21T14:29:16.746Z,1558448956.746 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-21T14:29:16.746Z,1558448956.746 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-21T14:29:16.746Z,1558448956.746 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-21T14:29:16.746Z,1558448956.746 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-21T14:29:16.747Z,1558448956.747 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-21T14:29:16.747Z,1558448956.747 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-21T14:29:16.747Z,1558448956.747 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-21T14:29:16.747Z,1558448956.747 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-21T14:29:16.747Z,1558448956.747 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-21T14:29:16.773Z,1558448956.773 [CBIT](DEBUG): Backplane powered.
2019-05-21T14:29:16.773Z,1558448956.773 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-21T14:29:16.775Z,1558448956.775 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-21T14:29:16.775Z,1558448956.775 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-21T14:29:16.776Z,1558448956.776 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-21T14:29:16.777Z,1558448956.777 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-21T14:29:16.786Z,1558448956.786 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-21T14:29:16.809Z,1558448956.809 [MissionManager](DEBUG):
2019-05-21T14:29:16.810Z,1558448956.810 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-21T14:29:16.883Z,1558448956.883 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-21T14:29:16.884Z,1558448956.884 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-21T14:29:16.894Z,1558448956.894 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-21T14:29:16.920Z,1558448956.920 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-21T14:29:16.923Z,1558448956.923 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-21T14:29:16.936Z,1558448956.936 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-21T14:29:16.940Z,1558448956.940 [MissionManager](DEBUG):
0
Wait a moment to see if the scheduler starts a new mission before
starting to actually run Default.
13
Burn on
Dropped weight due to communications timeout.
5
Default mission has been running for
Restarting logs and Default mission.
restart logs
2019-05-21T14:29:16.957Z,1558448956.957 [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-05-21T14:29:16.967Z,1558448956.967 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-21T14:29:17.006Z,1558448957.006 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-21T14:29:17.007Z,1558448957.007 [DUSBL_Hydroid](INFO): Powering up
2019-05-21T14:29:17.007Z,1558448957.007 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-21T14:29:17.025Z,1558448957.025 [Micromodem](INFO): Start
2019-05-21T14:29:17.065Z,1558448957.065 [Radio_Surface](INFO): Powering up
2019-05-21T14:29:17.081Z,1558448957.081 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-21T14:29:17.103Z,1558448957.103 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:29:17.109Z,1558448957.109 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-21T14:29:17.110Z,1558448957.110 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:29:17.117Z,1558448957.117 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-21T14:29:17.118Z,1558448957.118 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:29:17.125Z,1558448957.125 [MassServo](DEBUG): Initializing MassServo.
2019-05-21T14:29:17.126Z,1558448957.126 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:29:17.133Z,1558448957.133 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-21T14:29:17.134Z,1558448957.134 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:29:17.142Z,1558448957.142 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-21T14:29:17.382Z,1558448957.382 [Micromodem](INFO): Starting
2019-05-21T14:29:17.383Z,1558448957.383 [Micromodem](INFO): Powering up
2019-05-21T14:29:17.383Z,1558448957.383 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-21T14:29:17.417Z,1558448957.417 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-21T14:29:17.775Z,1558448957.775 [Micromodem](INFO): Starting
2019-05-21T14:29:18.178Z,1558448958.178 [Micromodem](INFO): Starting
2019-05-21T14:29:18.582Z,1558448958.582 [Micromodem](INFO): Starting
2019-05-21T14:29:18.986Z,1558448958.986 [Micromodem](INFO): Starting
2019-05-21T14:29:19.390Z,1558448959.390 [Micromodem](INFO): Starting
2019-05-21T14:29:19.794Z,1558448959.794 [Micromodem](INFO): Starting
2019-05-21T14:29:20.266Z,1558448960.266 [Micromodem](INFO): Starting
2019-05-21T14:29:20.626Z,1558448960.626 [Micromodem](INFO): Starting
2019-05-21T14:29:21.042Z,1558448961.042 [Micromodem](INFO): Starting
2019-05-21T14:29:21.486Z,1558448961.486 [Micromodem](INFO): Starting
2019-05-21T14:29:21.850Z,1558448961.850 [Micromodem](INFO): Starting
2019-05-21T14:29:22.254Z,1558448962.254 [Micromodem](INFO): Starting
2019-05-21T14:29:22.255Z,1558448962.255 [Micromodem](INFO): Starting
2019-05-21T14:29:22.255Z,1558448962.255 [Micromodem](DEBUG): Nmea buf: $CCCFG,ALL,0*33
2019-05-21T14:29:22.256Z,1558448962.256 [Micromodem](INFO): cmdSentTime_.elapsed() = 202005310308
2019-05-21T14:29:22.256Z,1558448962.256 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33
2019-05-21T14:29:22.256Z,1558448962.256 [Micromodem](DEBUG): Nmea buf: $CCCFG,SRC,1*31
2019-05-21T14:29:22.257Z,1558448962.257 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:22.258Z,1558448962.258 [Micromodem](DEBUG): Nmea buf: $CCCFG,nav.dt.txtrig_gpio4,1*64
2019-05-21T14:29:22.260Z,1558448962.260 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:22.261Z,1558448962.261 [Micromodem](DEBUG): Nmea buf: $CCCFG,BND,1*3B
2019-05-21T14:29:22.263Z,1558448962.263 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:22.658Z,1558448962.658 [Micromodem](INFO): Starting
2019-05-21T14:29:22.660Z,1558448962.660 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:23.062Z,1558448963.062 [Micromodem](INFO): Starting
2019-05-21T14:29:23.064Z,1558448963.064 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:23.466Z,1558448963.466 [Micromodem](INFO): Starting
2019-05-21T14:29:23.468Z,1558448963.468 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:23.870Z,1558448963.870 [Micromodem](INFO): Starting
2019-05-21T14:29:23.872Z,1558448963.872 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:24.274Z,1558448964.274 [Micromodem](INFO): Starting
2019-05-21T14:29:24.275Z,1558448964.275 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:24.678Z,1558448964.678 [Micromodem](INFO): Starting
2019-05-21T14:29:24.679Z,1558448964.679 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:25.070Z,1558448965.070 [Micromodem](INFO): Starting
2019-05-21T14:29:25.071Z,1558448965.071 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:25.485Z,1558448965.485 [Micromodem](INFO): Starting
2019-05-21T14:29:25.486Z,1558448965.486 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:25.870Z,1558448965.870 [Micromodem](INFO): Starting
2019-05-21T14:29:25.871Z,1558448965.871 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:26.275Z,1558448966.275 [Micromodem](INFO): Starting
2019-05-21T14:29:26.275Z,1558448966.275 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:26.674Z,1558448966.674 [Micromodem](INFO): Starting
2019-05-21T14:29:26.675Z,1558448966.675 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:27.074Z,1558448967.074 [Micromodem](INFO): Starting
2019-05-21T14:29:27.075Z,1558448967.075 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:27.534Z,1558448967.534 [Micromodem](INFO): Starting
2019-05-21T14:29:27.535Z,1558448967.535 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:27.874Z,1558448967.874 [Micromodem](INFO): Starting
2019-05-21T14:29:27.875Z,1558448967.875 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:28.278Z,1558448968.278 [Micromodem](INFO): Starting
2019-05-21T14:29:28.279Z,1558448968.279 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:28.682Z,1558448968.682 [Micromodem](INFO): Starting
2019-05-21T14:29:28.683Z,1558448968.683 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:29.086Z,1558448969.086 [Micromodem](INFO): Starting
2019-05-21T14:29:29.087Z,1558448969.087 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:29.490Z,1558448969.490 [Micromodem](INFO): Starting
2019-05-21T14:29:29.491Z,1558448969.491 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:29.894Z,1558448969.894 [Micromodem](INFO): Starting
2019-05-21T14:29:29.895Z,1558448969.895 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:30.298Z,1558448970.298 [Micromodem](INFO): Starting
2019-05-21T14:29:30.299Z,1558448970.299 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:30.325Z,1558448970.325 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-21T14:29:30.702Z,1558448970.702 [Micromodem](INFO): Starting
2019-05-21T14:29:30.703Z,1558448970.703 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:31.106Z,1558448971.106 [Micromodem](INFO): Starting
2019-05-21T14:29:31.107Z,1558448971.107 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:31.434Z,1558448971.434 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004479
2019-05-21T14:29:31.511Z,1558448971.511 [Micromodem](INFO): Starting
2019-05-21T14:29:31.511Z,1558448971.511 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:31.914Z,1558448971.914 [Micromodem](INFO): Starting
2019-05-21T14:29:31.915Z,1558448971.915 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:32.322Z,1558448972.322 [Micromodem](INFO): Starting
2019-05-21T14:29:32.323Z,1558448972.323 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:32.723Z,1558448972.723 [Micromodem](INFO): Starting
2019-05-21T14:29:32.724Z,1558448972.724 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:33.128Z,1558448973.128 [Micromodem](INFO): Starting
2019-05-21T14:29:33.131Z,1558448973.131 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:33.530Z,1558448973.530 [Micromodem](INFO): Starting
2019-05-21T14:29:33.531Z,1558448973.531 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:33.531Z,1558448973.531 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33
2019-05-21T14:29:33.934Z,1558448973.934 [Micromodem](INFO): Starting
2019-05-21T14:29:33.936Z,1558448973.936 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:34.338Z,1558448974.338 [Micromodem](INFO): Starting
2019-05-21T14:29:34.339Z,1558448974.339 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:34.744Z,1558448974.744 [Micromodem](INFO): Starting
2019-05-21T14:29:34.744Z,1558448974.744 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:35.147Z,1558448975.147 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-21T14:29:35.161Z,1558448975.161 [Micromodem](INFO): Starting
2019-05-21T14:29:35.162Z,1558448975.162 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:35.550Z,1558448975.550 [Micromodem](INFO): Starting
2019-05-21T14:29:35.551Z,1558448975.551 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:35.569Z,1558448975.569 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-21T14:29:35.569Z,1558448975.569 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190521075.0, -0.1, 0.0,1448.9, 0
2019-05-21T14:29:35.958Z,1558448975.958 [Micromodem](INFO): Starting
2019-05-21T14:29:35.958Z,1558448975.958 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:36.358Z,1558448976.358 [Micromodem](INFO): Starting
2019-05-21T14:29:36.359Z,1558448976.359 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:36.762Z,1558448976.762 [Micromodem](INFO): Starting
2019-05-21T14:29:36.763Z,1558448976.763 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:37.170Z,1558448977.170 [Micromodem](INFO): Starting
2019-05-21T14:29:37.171Z,1558448977.171 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:37.570Z,1558448977.570 [Micromodem](INFO): Starting
2019-05-21T14:29:37.571Z,1558448977.571 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:37.974Z,1558448977.974 [Micromodem](INFO): Starting
2019-05-21T14:29:37.975Z,1558448977.975 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:38.378Z,1558448978.378 [Micromodem](INFO): Starting
2019-05-21T14:29:38.378Z,1558448978.378 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:38.782Z,1558448978.782 [Micromodem](INFO): Starting
2019-05-21T14:29:38.783Z,1558448978.783 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:39.186Z,1558448979.186 [Micromodem](INFO): Starting
2019-05-21T14:29:39.187Z,1558448979.187 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:39.594Z,1558448979.594 [Micromodem](INFO): Starting
2019-05-21T14:29:39.594Z,1558448979.594 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:39.994Z,1558448979.994 [Micromodem](INFO): Starting
2019-05-21T14:29:39.995Z,1558448979.995 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:40.398Z,1558448980.398 [Micromodem](INFO): Starting
2019-05-21T14:29:40.399Z,1558448980.399 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:40.802Z,1558448980.802 [Micromodem](INFO): Starting
2019-05-21T14:29:40.803Z,1558448980.803 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:41.206Z,1558448981.206 [Micromodem](INFO): Starting
2019-05-21T14:29:41.207Z,1558448981.207 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:41.610Z,1558448981.610 [Micromodem](INFO): Starting
2019-05-21T14:29:41.611Z,1558448981.611 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:42.018Z,1558448982.018 [Micromodem](INFO): Starting
2019-05-21T14:29:42.019Z,1558448982.019 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:42.418Z,1558448982.418 [Micromodem](INFO): Starting
2019-05-21T14:29:42.420Z,1558448982.420 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:42.822Z,1558448982.822 [Micromodem](INFO): Starting
2019-05-21T14:29:42.823Z,1558448982.823 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:43.226Z,1558448983.226 [Micromodem](INFO): Starting
2019-05-21T14:29:43.227Z,1558448983.227 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:43.228Z,1558448983.228 [NAL9602](INFO): Powering up NAL9602
2019-05-21T14:29:43.630Z,1558448983.630 [Micromodem](INFO): Starting
2019-05-21T14:29:43.631Z,1558448983.631 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:44.034Z,1558448984.034 [Micromodem](INFO): Starting
2019-05-21T14:29:44.035Z,1558448984.035 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:44.442Z,1558448984.442 [Micromodem](INFO): Starting
2019-05-21T14:29:44.443Z,1558448984.443 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:44.846Z,1558448984.846 [Micromodem](INFO): Starting
2019-05-21T14:29:44.847Z,1558448984.847 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:44.847Z,1558448984.847 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33
2019-05-21T14:29:45.254Z,1558448985.254 [Micromodem](INFO): Starting
2019-05-21T14:29:45.256Z,1558448985.256 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:45.650Z,1558448985.650 [Micromodem](INFO): Starting
2019-05-21T14:29:45.651Z,1558448985.651 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:46.054Z,1558448986.054 [Micromodem](INFO): Starting
2019-05-21T14:29:46.055Z,1558448986.055 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:46.458Z,1558448986.458 [Micromodem](INFO): Starting
2019-05-21T14:29:46.459Z,1558448986.459 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:46.862Z,1558448986.862 [Micromodem](INFO): Starting
2019-05-21T14:29:46.863Z,1558448986.863 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:47.266Z,1558448987.266 [Micromodem](INFO): Starting
2019-05-21T14:29:47.266Z,1558448987.266 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:47.670Z,1558448987.670 [Micromodem](INFO): Starting
2019-05-21T14:29:47.671Z,1558448987.671 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:48.074Z,1558448988.074 [Micromodem](INFO): Starting
2019-05-21T14:29:48.074Z,1558448988.074 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:48.478Z,1558448988.478 [Micromodem](INFO): Starting
2019-05-21T14:29:48.479Z,1558448988.479 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:48.882Z,1558448988.882 [Micromodem](INFO): Starting
2019-05-21T14:29:48.883Z,1558448988.883 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:49.286Z,1558448989.286 [Micromodem](INFO): Starting
2019-05-21T14:29:49.287Z,1558448989.287 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:49.690Z,1558448989.690 [Micromodem](INFO): Starting
2019-05-21T14:29:49.691Z,1558448989.691 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:50.094Z,1558448990.094 [Micromodem](INFO): Starting
2019-05-21T14:29:50.095Z,1558448990.095 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:50.498Z,1558448990.498 [Micromodem](INFO): Starting
2019-05-21T14:29:50.499Z,1558448990.499 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:50.902Z,1558448990.902 [Micromodem](INFO): Starting
2019-05-21T14:29:50.903Z,1558448990.903 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:51.312Z,1558448991.312 [Micromodem](INFO): Starting
2019-05-21T14:29:51.312Z,1558448991.312 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:51.710Z,1558448991.710 [Micromodem](INFO): Starting
2019-05-21T14:29:51.711Z,1558448991.711 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:52.114Z,1558448992.114 [Micromodem](INFO): Starting
2019-05-21T14:29:52.115Z,1558448992.115 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:52.518Z,1558448992.518 [Micromodem](INFO): Starting
2019-05-21T14:29:52.519Z,1558448992.519 [Micromodem](INFO): cmdSentTime_.elapsed() = 202005310308
2019-05-21T14:29:52.519Z,1558448992.519 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31
2019-05-21T14:29:52.922Z,1558448992.922 [Micromodem](INFO): Starting
2019-05-21T14:29:52.923Z,1558448992.923 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:53.326Z,1558448993.326 [Micromodem](INFO): Starting
2019-05-21T14:29:53.328Z,1558448993.328 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:53.730Z,1558448993.730 [Micromodem](INFO): Starting
2019-05-21T14:29:53.731Z,1558448993.731 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:54.138Z,1558448994.138 [Micromodem](INFO): Starting
2019-05-21T14:29:54.139Z,1558448994.139 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:54.139Z,1558448994.139 [NAL9602](INFO): NAL9602 initialized
2019-05-21T14:29:54.538Z,1558448994.538 [Micromodem](INFO): Starting
2019-05-21T14:29:54.539Z,1558448994.539 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:54.942Z,1558448994.942 [Micromodem](INFO): Starting
2019-05-21T14:29:54.943Z,1558448994.943 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:54.957Z,1558448994.957 [NAL9602](DEBUG): Fix Requested
2019-05-21T14:29:55.346Z,1558448995.346 [Micromodem](INFO): Starting
2019-05-21T14:29:55.347Z,1558448995.347 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:55.750Z,1558448995.750 [Micromodem](INFO): Starting
2019-05-21T14:29:55.751Z,1558448995.751 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:56.154Z,1558448996.154 [Micromodem](INFO): Starting
2019-05-21T14:29:56.155Z,1558448996.155 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:56.558Z,1558448996.558 [Micromodem](INFO): Starting
2019-05-21T14:29:56.559Z,1558448996.559 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:56.962Z,1558448996.962 [Micromodem](INFO): Starting
2019-05-21T14:29:56.963Z,1558448996.963 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:57.370Z,1558448997.370 [Micromodem](INFO): Starting
2019-05-21T14:29:57.370Z,1558448997.370 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:57.774Z,1558448997.774 [Micromodem](INFO): Starting
2019-05-21T14:29:57.774Z,1558448997.774 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:58.181Z,1558448998.181 [Micromodem](INFO): Starting
2019-05-21T14:29:58.181Z,1558448998.181 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:58.317Z,1558448998.317 [CommandLine](IMPORTANT): got command quit
2019-05-21T14:29:58.578Z,1558448998.578 [Micromodem](INFO): Starting
2019-05-21T14:29:58.578Z,1558448998.578 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:58.982Z,1558448998.982 [Micromodem](INFO): Starting
2019-05-21T14:29:58.983Z,1558448998.983 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:59.321Z,1558448999.321 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-21T14:29:59.321Z,1558448999.321 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:29:59.321Z,1558448999.321 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:29:59.386Z,1558448999.386 [Micromodem](INFO): Starting
2019-05-21T14:29:59.387Z,1558448999.387 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:29:59.445Z,1558448999.445 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2019-05-21T14:29:59.445Z,1558448999.445 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:29:59.446Z,1558448999.446 [CommandLine](INFO): Join timeout helper Thread ID is 4084
2019-05-21T14:29:59.465Z,1558448999.465 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-21T14:29:59.465Z,1558448999.465 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:29:59.465Z,1558448999.465 [NavChartDb](INFO): Join timeout helper Thread ID is 4085
2019-05-21T14:29:59.790Z,1558448999.790 [Micromodem](INFO): Starting
2019-05-21T14:29:59.791Z,1558448999.791 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:30:00.210Z,1558449000.210 [Micromodem](INFO): Starting
2019-05-21T14:30:00.211Z,1558449000.211 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:30:00.344Z,1558449000.344 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:30:00.344Z,1558449000.344 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.349Z,1558449000.349 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-21T14:30:00.349Z,1558449000.349 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.349Z,1558449000.349 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 4086
2019-05-21T14:30:00.369Z,1558449000.369 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:30:00.369Z,1558449000.369 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-21T14:30:00.370Z,1558449000.370 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.377Z,1558449000.377 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-21T14:30:00.377Z,1558449000.377 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.377Z,1558449000.377 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 4087
2019-05-21T14:30:00.545Z,1558449000.545 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:30:00.545Z,1558449000.545 [CTD_NeilBrown](INFO): Powering down
2019-05-21T14:30:00.557Z,1558449000.557 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.557Z,1558449000.557 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-21T14:30:00.557Z,1558449000.557 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.558Z,1558449000.558 [Radio_Surface](INFO): Join timeout helper Thread ID is 4088
2019-05-21T14:30:00.618Z,1558449000.618 [Micromodem](INFO): Starting
2019-05-21T14:30:00.618Z,1558449000.618 [Micromodem](INFO): cmdSentTime_.elapsed() = 197001010000
2019-05-21T14:30:00.721Z,1558449000.721 [Radio_Surface](INFO): Powering down
2019-05-21T14:30:00.722Z,1558449000.722 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:30:00.722Z,1558449000.722 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.734Z,1558449000.734 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-21T14:30:00.734Z,1558449000.734 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.734Z,1558449000.734 [DataOverHttps](INFO): Join timeout helper Thread ID is 4089
2019-05-21T14:30:00.933Z,1558449000.933 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:30:00.936Z,1558449000.936 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.953Z,1558449000.953 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-21T14:30:00.954Z,1558449000.954 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.954Z,1558449000.954 [logger](INFO): Join timeout helper Thread ID is 4090
2019-05-21T14:30:00.989Z,1558449000.989 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:30:00.989Z,1558449000.989 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.994Z,1558449000.994 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-21T14:30:00.994Z,1558449000.994 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.994Z,1558449000.994 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-21T14:30:00.994Z,1558449000.994 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:00.994Z,1558449000.994 [controlThread](INFO): Join timeout helper Thread ID is 4091
2019-05-21T14:30:00.995Z,1558449000.995 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:30:00.995Z,1558449000.995 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-21T14:30:00.995Z,1558449000.995 [AHRS_M2](INFO): Powering down
2019-05-21T14:30:01.065Z,1558449001.065 [DUSBL_Hydroid](INFO): Powering down
2019-05-21T14:30:01.158Z,1558449001.158 [Micromodem](INFO): uninitialize
2019-05-21T14:30:01.158Z,1558449001.158 [Micromodem](INFO): Powering down
2019-05-21T14:30:01.293Z,1558449001.293 [NAL9602](INFO): Powering down
2019-05-21T14:30:01.365Z,1558449001.365 [RDI_Pathfinder](INFO): Powering down
2019-05-21T14:30:01.367Z,1558449001.367 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-21T14:30:01.367Z,1558449001.367 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-21T14:30:01.368Z,1558449001.368 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-21T14:30:01.368Z,1558449001.368 [MissionManager](INFO): Uninitializing Mission Default
2019-05-21T14:30:01.371Z,1558449001.371 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-21T14:30:01.372Z,1558449001.372 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-21T14:30:01.372Z,1558449001.372 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-21T14:30:01.372Z,1558449001.372 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-21T14:30:01.373Z,1558449001.373 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-21T14:30:01.373Z,1558449001.373 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-21T14:30:01.373Z,1558449001.373 [BuoyancyServo](INFO): Powering down
2019-05-21T14:30:01.385Z,1558449001.385 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-21T14:30:01.385Z,1558449001.385 [ElevatorServo](INFO): Powering down
2019-05-21T14:30:01.404Z,1558449001.404 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-21T14:30:01.404Z,1558449001.404 [MassServo](INFO): Powering down
2019-05-21T14:30:01.405Z,1558449001.405 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-21T14:30:01.405Z,1558449001.405 [RudderServo](INFO): Powering down
2019-05-21T14:30:01.406Z,1558449001.406 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-21T14:30:01.406Z,1558449001.406 [ThrusterServo](INFO): Powering down
2019-05-21T14:30:01.407Z,1558449001.407 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-21T14:30:01.407Z,1558449001.407 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-21T14:30:01.407Z,1558449001.407 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-21T14:30:01.407Z,1558449001.407 [CBIT](DEBUG): Powering off loads.
2019-05-21T14:30:01.421Z,1558449001.421 [CBIT](DEBUG): Disabling WDT.
2019-05-21T14:30:01.433Z,1558449001.433 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-21T14:30:01.434Z,1558449001.434 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:01.489Z,1558449001.489 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:01.498Z,1558449001.498 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:01.654Z,1558449001.654 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:01.656Z,1558449001.656 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:01.711Z,1558449001.711 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:30:01.766Z,1558449001.766 [logger ThreadHandler](INFO): Thread cancelled.