2019-07-03T03:38:03.244Z,1562125083.244 [Supervisor](DEBUG): Initializing supervisor.
2019-07-03T03:38:03.247Z,1562125083.247 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-03T03:38:03.247Z,1562125083.247 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-07-03T03:38:03.247Z,1562125083.247 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-03T03:38:03.248Z,1562125083.248 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-03T03:38:03.249Z,1562125083.249 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-07-03T03:38:03.251Z,1562125083.251 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-03T03:38:03.263Z,1562125083.263 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-03T03:38:03.264Z,1562125083.264 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-03T03:38:03.264Z,1562125083.264 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-07-03T03:38:03.265Z,1562125083.265 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-03T03:38:03.266Z,1562125083.266 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-03T03:38:03.266Z,1562125083.266 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-07-03T03:38:03.268Z,1562125083.268 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-03T03:38:03.269Z,1562125083.269 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-03T03:38:03.273Z,1562125083.273 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-03T03:38:03.689Z,1562125083.689 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-03T03:38:03.691Z,1562125083.691 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-03T03:38:03.788Z,1562125083.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-03T03:38:03.790Z,1562125083.790 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-03T03:38:04.100Z,1562125084.100 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-03T03:38:04.101Z,1562125084.101 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-03T03:38:04.239Z,1562125084.239 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-03T03:38:04.240Z,1562125084.240 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-03T03:38:04.428Z,1562125084.428 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-03T03:38:04.430Z,1562125084.430 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-03T03:38:04.870Z,1562125084.870 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-03T03:38:04.872Z,1562125084.872 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-03T03:38:05.075Z,1562125085.075 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-03T03:38:05.076Z,1562125085.076 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-03T03:38:05.218Z,1562125085.218 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-03T03:38:05.220Z,1562125085.220 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-03T03:38:05.409Z,1562125085.409 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-03T03:38:05.411Z,1562125085.411 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-03T03:38:05.506Z,1562125085.506 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-03T03:38:05.507Z,1562125085.507 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-03T03:38:05.802Z,1562125085.802 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-03T03:38:05.802Z,1562125085.802 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-03T03:38:05.883Z,1562125085.883 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-03T03:38:05.985Z,1562125085.985 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-03T03:38:05.986Z,1562125085.986 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-03T03:38:06.615Z,1562125086.615 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-03T03:38:07.190Z,1562125087.190 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-03T03:38:07.971Z,1562125087.971 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-03T03:38:07.973Z,1562125087.973 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-07-03T03:38:07.977Z,1562125087.977 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-07-03T03:38:08.182Z,1562125088.182 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-07-03T03:38:08.281Z,1562125088.281 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-07-03T03:38:08.379Z,1562125088.379 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-07-03T03:38:08.603Z,1562125088.603 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-03T03:38:08.604Z,1562125088.604 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-07-03T03:38:08.687Z,1562125088.687 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-07-03T03:38:08.780Z,1562125088.780 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-07-03T03:38:08.875Z,1562125088.875 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-07-03T03:38:08.959Z,1562125088.959 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-07-03T03:38:09.065Z,1562125089.065 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-07-03T03:38:09.240Z,1562125089.240 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-07-03T03:38:09.367Z,1562125089.367 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2019-07-03T03:38:09.370Z,1562125089.370 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-03T03:38:10.104Z,1562125090.104 [AHRS_M2] Loaded
2019-07-03T03:38:10.104Z,1562125090.104 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-07-03T03:38:10.245Z,1562125090.245 [DataOverHttps] Loaded
2019-07-03T03:38:10.246Z,1562125090.246 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-03T03:38:10.247Z,1562125090.247 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407654E0
2019-07-03T03:38:10.247Z,1562125090.247 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 889
2019-07-03T03:38:10.260Z,1562125090.260 [Depth_Keller] Loaded
2019-07-03T03:38:10.261Z,1562125090.261 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-03T03:38:10.265Z,1562125090.265 [DropWeight] Loaded
2019-07-03T03:38:10.266Z,1562125090.266 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-07-03T03:38:10.322Z,1562125090.322 [DUSBL_Hydroid] Loaded
2019-07-03T03:38:10.322Z,1562125090.322 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-07-03T03:38:10.371Z,1562125090.371 [Micromodem] Loaded
2019-07-03T03:38:10.371Z,1562125090.371 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-07-03T03:38:10.468Z,1562125090.468 [NAL9602] Loaded
2019-07-03T03:38:10.468Z,1562125090.468 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-03T03:38:10.484Z,1562125090.484 [Onboard] Loaded
2019-07-03T03:38:10.484Z,1562125090.484 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-03T03:38:10.490Z,1562125090.490 [PowerOnly] Loaded
2019-07-03T03:38:10.490Z,1562125090.490 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-07-03T03:38:10.497Z,1562125090.497 [Radio_Surface] Loaded
2019-07-03T03:38:10.497Z,1562125090.497 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-03T03:38:10.498Z,1562125090.498 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407954E0
2019-07-03T03:38:10.498Z,1562125090.498 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 890
2019-07-03T03:38:10.542Z,1562125090.542 [RDI_Pathfinder] Loaded
2019-07-03T03:38:10.543Z,1562125090.543 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-07-03T03:38:12.465Z,1562125092.465 [BPC1] Loaded
2019-07-03T03:38:12.465Z,1562125092.465 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-03T03:38:12.466Z,1562125092.466 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-03T03:38:12.467Z,1562125092.467 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-03T03:38:12.491Z,1562125092.491 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-03T03:38:12.491Z,1562125092.491 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-03T03:38:12.615Z,1562125092.615 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-03T03:38:12.615Z,1562125092.615 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-03T03:38:12.636Z,1562125092.636 [NavChart] Loaded
2019-07-03T03:38:12.636Z,1562125092.636 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-03T03:38:12.640Z,1562125092.640 [UniversalFixResidualReporter] Loaded
2019-07-03T03:38:12.640Z,1562125092.640 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-03T03:38:12.641Z,1562125092.641 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-03T03:38:12.642Z,1562125092.642 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-03T03:38:12.772Z,1562125092.772 [BuoyancyServo] Loaded
2019-07-03T03:38:12.772Z,1562125092.772 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-03T03:38:12.787Z,1562125092.787 [ElevatorServo] Loaded
2019-07-03T03:38:12.787Z,1562125092.787 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-03T03:38:12.802Z,1562125092.802 [MassServo] Loaded
2019-07-03T03:38:12.802Z,1562125092.802 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-03T03:38:12.818Z,1562125092.818 [RudderServo] Loaded
2019-07-03T03:38:12.818Z,1562125092.818 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-03T03:38:12.833Z,1562125092.833 [ThrusterServo] Loaded
2019-07-03T03:38:12.833Z,1562125092.833 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-03T03:38:12.834Z,1562125092.834 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-03T03:38:12.834Z,1562125092.834 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-03T03:38:13.410Z,1562125093.410 [CTD_NeilBrown] Loaded
2019-07-03T03:38:13.411Z,1562125093.411 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-07-03T03:38:13.412Z,1562125093.412 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E04E0
2019-07-03T03:38:13.412Z,1562125093.412 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 891
2019-07-03T03:38:13.457Z,1562125093.457 [WetLabsSeaOWL_UV_A] Loaded
2019-07-03T03:38:13.457Z,1562125093.457 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-07-03T03:38:13.458Z,1562125093.458 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409104E0
2019-07-03T03:38:13.459Z,1562125093.459 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 892
2019-07-03T03:38:13.459Z,1562125093.459 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-03T03:38:13.460Z,1562125093.460 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-03T03:38:13.801Z,1562125093.801 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-03T03:38:13.802Z,1562125093.802 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-03T03:38:13.858Z,1562125093.858 [DepthRateCalculator] Loaded
2019-07-03T03:38:13.858Z,1562125093.858 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-03T03:38:13.864Z,1562125093.864 [PitchRateCalculator] Loaded
2019-07-03T03:38:13.864Z,1562125093.864 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-03T03:38:13.876Z,1562125093.876 [SpeedCalculator] Loaded
2019-07-03T03:38:13.877Z,1562125093.877 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-03T03:38:13.897Z,1562125093.897 [TempGradientCalculator] Loaded
2019-07-03T03:38:13.898Z,1562125093.898 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-03T03:38:13.903Z,1562125093.903 [YawRateCalculator] Loaded
2019-07-03T03:38:13.904Z,1562125093.904 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-03T03:38:13.944Z,1562125093.944 [ElevatorOffsetCalculator] Loaded
2019-07-03T03:38:13.945Z,1562125093.945 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-03T03:38:13.945Z,1562125093.945 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-03T03:38:13.946Z,1562125093.946 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-03T03:38:14.107Z,1562125094.107 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-03T03:38:14.129Z,1562125094.129 [SBIT] Loaded
2019-07-03T03:38:14.129Z,1562125094.129 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-03T03:38:14.130Z,1562125094.130 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-03T03:38:14.142Z,1562125094.142 [IBIT] Loaded
2019-07-03T03:38:14.142Z,1562125094.142 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-03T03:38:14.145Z,1562125094.145 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-03T03:38:14.286Z,1562125094.286 [CBIT] Loaded
2019-07-03T03:38:14.287Z,1562125094.287 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-03T03:38:14.287Z,1562125094.287 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-03T03:38:14.288Z,1562125094.288 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-03T03:38:14.409Z,1562125094.409 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-03T03:38:14.410Z,1562125094.410 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-03T03:38:14.534Z,1562125094.534 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-03T03:38:14.535Z,1562125094.535 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-03T03:38:14.623Z,1562125094.623 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-03T03:38:14.708Z,1562125094.708 [VerticalControl] Loaded
2019-07-03T03:38:14.708Z,1562125094.708 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-03T03:38:14.709Z,1562125094.709 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-03T03:38:14.765Z,1562125094.765 [HorizontalControl] Loaded
2019-07-03T03:38:14.766Z,1562125094.766 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-03T03:38:14.766Z,1562125094.766 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-03T03:38:14.768Z,1562125094.768 [SpeedControl] Loaded
2019-07-03T03:38:14.768Z,1562125094.768 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-03T03:38:14.769Z,1562125094.769 [LoopControl](DEBUG): Construct LoopControl.
2019-07-03T03:38:14.770Z,1562125094.770 [LoopControl] Loaded
2019-07-03T03:38:14.770Z,1562125094.770 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-03T03:38:14.770Z,1562125094.770 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-03T03:38:14.771Z,1562125094.771 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-03T03:38:14.819Z,1562125094.819 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-03T03:38:14.823Z,1562125094.823 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-03T03:38:14.824Z,1562125094.824 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-03T03:38:14.830Z,1562125094.830 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-03T03:38:14.831Z,1562125094.831 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AEC4E0
2019-07-03T03:38:14.832Z,1562125094.832 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 893
2019-07-03T03:38:14.836Z,1562125094.836 [Supervisor](INFO): Main Thread ID is 802
2019-07-03T03:38:14.836Z,1562125094.836 [Supervisor](DEBUG): Running supervisor.
2019-07-03T03:38:14.837Z,1562125094.837 [CommandLine ThreadHandler](INFO): Handler Thread ID is 894
2019-07-03T03:38:14.839Z,1562125094.839 [controlThread ThreadHandler](INFO): Handler Thread ID is 895
2019-07-03T03:38:14.840Z,1562125094.840 [controlThread](DEBUG): Initializing ControlThread
2019-07-03T03:38:14.848Z,1562125094.848 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-03T03:38:14.848Z,1562125094.848 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-03T03:38:14.850Z,1562125094.850 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-03T03:38:14.850Z,1562125094.850 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-03T03:38:14.850Z,1562125094.850 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-03T03:38:14.851Z,1562125094.851 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-03T03:38:14.851Z,1562125094.851 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-03T03:38:14.851Z,1562125094.851 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-03T03:38:14.852Z,1562125094.852 [SBIT](INFO): Initialize SBIT Component.
2019-07-03T03:38:14.852Z,1562125094.852 [SBIT](IMPORTANT): git: 2019-07-01
2019-07-03T03:38:14.853Z,1562125094.853 [SBIT](INFO): git hash: 66ee1f914ed66d399bd38d45ccca9e12ca50b60d
2019-07-03T03:38:14.853Z,1562125094.853 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-03T03:38:14.854Z,1562125094.854 [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:38:14.855Z,1562125094.855 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-07-03T03:38:14.856Z,1562125094.856 [IBIT](INFO): Initialize IBIT Component.
2019-07-03T03:38:14.857Z,1562125094.857 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-03T03:38:14.858Z,1562125094.858 [logger ThreadHandler](INFO): Handler Thread ID is 896
2019-07-03T03:38:14.869Z,1562125094.869 [CBIT](DEBUG): Initialized mux pins.
2019-07-03T03:38:14.869Z,1562125094.869 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2019-07-03T03:38:14.869Z,1562125094.869 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-03T03:38:14.877Z,1562125094.877 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 897
2019-07-03T03:38:14.878Z,1562125094.878 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-03T03:38:14.889Z,1562125094.889 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 898
2019-07-03T03:38:14.893Z,1562125094.893 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2019-07-03T03:38:14.893Z,1562125094.893 [CBIT](DEBUG): Initializing heartbeat.
2019-07-03T03:38:14.901Z,1562125094.901 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 899
2019-07-03T03:38:14.902Z,1562125094.902 [CTD_NeilBrown](INFO): Powering down
2019-07-03T03:38:14.937Z,1562125094.937 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 900
2019-07-03T03:38:14.938Z,1562125094.938 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-03T03:38:14.959Z,1562125094.959 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 901
2019-07-03T03:38:14.965Z,1562125094.965 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-03T03:38:14.965Z,1562125094.965 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-03T03:38:14.970Z,1562125094.970 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-03T03:38:14.970Z,1562125094.970 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-03T03:38:14.971Z,1562125094.971 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-03T03:38:14.971Z,1562125094.971 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-03T03:38:14.971Z,1562125094.971 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-03T03:38:14.971Z,1562125094.971 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-03T03:38:14.971Z,1562125094.971 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-03T03:38:14.971Z,1562125094.971 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-03T03:38:14.972Z,1562125094.972 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-03T03:38:14.972Z,1562125094.972 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-03T03:38:14.972Z,1562125094.972 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-03T03:38:14.972Z,1562125094.972 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-03T03:38:14.972Z,1562125094.972 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-03T03:38:14.972Z,1562125094.972 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-03T03:38:14.973Z,1562125094.973 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-03T03:38:14.973Z,1562125094.973 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-03T03:38:15.001Z,1562125095.001 [CBIT](DEBUG): Backplane powered.
2019-07-03T03:38:15.001Z,1562125095.001 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-03T03:38:15.003Z,1562125095.003 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-03T03:38:15.004Z,1562125095.004 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-03T03:38:15.004Z,1562125095.004 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-03T03:38:15.005Z,1562125095.005 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-03T03:38:15.028Z,1562125095.028 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-03T03:38:15.043Z,1562125095.043 [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:38:15.044Z,1562125095.044 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-03T03:38:15.132Z,1562125095.132 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-03T03:38:15.133Z,1562125095.133 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-03T03:38:15.135Z,1562125095.135 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-03T03:38:15.192Z,1562125095.192 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-03T03:38:15.195Z,1562125095.195 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-03T03:38:15.215Z,1562125095.215 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-03T03:38:15.235Z,1562125095.235 [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:38:15.240Z,1562125095.240 [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:38:15.261Z,1562125095.261 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-07-03T03:38:15.293Z,1562125095.293 [Radio_Surface](INFO): Powering up
2019-07-03T03:38:15.363Z,1562125095.363 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-07-03T03:38:15.364Z,1562125095.364 [DUSBL_Hydroid](INFO): Powering up
2019-07-03T03:38:15.364Z,1562125095.364 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-07-03T03:38:15.429Z,1562125095.429 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-07-03T03:38:15.489Z,1562125095.489 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:38:15.497Z,1562125095.497 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-03T03:38:15.498Z,1562125095.498 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:38:15.505Z,1562125095.505 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-03T03:38:15.506Z,1562125095.506 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:38:15.514Z,1562125095.514 [MassServo](DEBUG): Initializing MassServo.
2019-07-03T03:38:15.514Z,1562125095.514 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:38:15.521Z,1562125095.521 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-03T03:38:15.522Z,1562125095.522 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:38:15.529Z,1562125095.529 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-03T03:38:15.531Z,1562125095.531 [CommandLine](FAULT): Scheduling is paused
2019-07-03T03:38:15.532Z,1562125095.532 [CBIT](INFO): Critical error at 20190703T033814
2019-07-03T03:38:15.532Z,1562125095.532 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-07-03T03:38:15.668Z,1562125095.668 [Micromodem](INFO): Powering up
2019-07-03T03:38:15.669Z,1562125095.669 [Micromodem](DEBUG): Initializing Micromodem.
2019-07-03T03:38:16.417Z,1562125096.417 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-03T03:38:16.417Z,1562125096.417 [RudderServo](FAULT): Rudder failed to initialize
2019-07-03T03:38:16.417Z,1562125096.417 [RudderServo] Communications Fault, FailCount= 1
2019-07-03T03:38:16.417Z,1562125096.417 [RudderServo](ERROR): Communications Fault
2019-07-03T03:38:16.528Z,1562125096.528 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-03T03:38:16.698Z,1562125096.698 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-03T03:38:16.698Z,1562125096.698 [RudderServo](INFO): Powering down
2019-07-03T03:38:17.373Z,1562125097.373 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-03T03:38:17.497Z,1562125097.497 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-03T03:38:17.501Z,1562125097.501 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-03T03:38:17.501Z,1562125097.501 [RudderServo] No Fault, FailCount= 1
2019-07-03T03:38:20.616Z,1562125100.616 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-07-03T03:38:22.636Z,1562125102.636 [Micromodem](INFO): Nmea in: $CATMG,2019-07-03T03:38:09Z,RTC,RTC*71

2019-07-03T03:38:22.636Z,1562125102.636 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-07-03T03:38:09Z,RTC,RTC*71

2019-07-03T03:38:28.688Z,1562125108.688 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-07-03T03:38:31.907Z,1562125111.907 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-07-03T03:38:32.296Z,1562125112.296 [Micromodem](INFO): Nmea in: $CAERR,033821,NI  ,12,Unknown command*47

2019-07-03T03:38:32.296Z,1562125112.296 [Micromodem](ERROR): Got error from modem: $CAERR,033821,NI  ,12,Unknown command*47

2019-07-03T03:38:33.510Z,1562125113.510 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-07-03T03:38:40.780Z,1562125120.780 [NAL9602](INFO): Powering up NAL9602
2019-07-03T03:38:42.012Z,1562125122.012 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2019-07-03T03:38:42.012Z,1562125122.012 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768-32BE,-32768,-32768,-32768,V
2019-07-03T03:38:43.203Z,1562125123.203 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-07-03T03:38:43.251Z,1562125123.251 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-03T03:38:43.255Z,1562125123.255 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-03T03:38:43.609Z,1562125123.609 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-07-03T03:38:43.611Z,1562125123.611 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-07-03T03:38:44.015Z,1562125124.015 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

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

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

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

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

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

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

2019-07-03T03:38:45.223Z,1562125125.223 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-07-03T03:38:45.703Z,1562125125.703 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-07-03T03:38:45.703Z,1562125125.703 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-07-03T03:38:46.103Z,1562125126.103 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-07-03T03:38:46.103Z,1562125126.103 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-07-03T03:38:46.511Z,1562125126.511 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-07-03T03:38:46.511Z,1562125126.511 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

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

2019-07-03T03:38:46.912Z,1562125126.912 [Micromodem](INFO): Nmea out: $CCCLK,2019,07,03,03,38,47*41

2019-07-03T03:38:47.315Z,1562125127.315 [Micromodem](INFO): Nmea in: $CACLK,2019,7,3,3,38,47*73

2019-07-03T03:38:48.123Z,1562125128.123 [Micromodem](INFO): Nmea in: $CATMS,0,2019-07-03T03:38:48Z*7C

2019-07-03T03:38:48.150Z,1562125128.150 [Micromodem](INFO): Nmea in: $CATMG,2019-07-03T03:38:48Z,USER_CMD,RTC*35

2019-07-03T03:38:51.779Z,1562125131.779 [NAL9602](INFO): NAL9602 initialized
2019-07-03T03:38:52.585Z,1562125132.585 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:38:54.277Z,1562125134.277 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.019676
CHAN A1 (24V): -0.026451
CHAN A2 (12V): -0.006176
CHAN A3 (5V): -0.002057
CHAN B0 (3.3V): 0.000167
CHAN B1 (3.15aV): 0.000149
CHAN B2 (3.15bV): 0.000546
CHAN B3 (GND): 0.002050
OPEN: 0.007157
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-03T03:39:19.049Z,1562125159.049 [NAL9602](INFO): SBD MO Status=2, MOMSN=8001, MT Status=2, MTMSN=0
2019-07-03T03:39:19.049Z,1562125159.049 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-03T03:39:29.643Z,1562125169.643 [NAL9602](INFO): SBD MO Status=0, MOMSN=8001, MT Status=0, MTMSN=0
2019-07-03T03:39:29.643Z,1562125169.643 [NAL9602](INFO): No messages in MT queue
2019-07-03T03:39:30.445Z,1562125170.445 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:33.269Z,1562125173.269 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:36.093Z,1562125176.093 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:36.555Z,1562125176.555 [SBIT](IMPORTANT): SBIT PASSED
2019-07-03T03:39:36.614Z,1562125176.614 [CommandLine](IMPORTANT): got command configSet list
2019-07-03T03:39:36.614Z,1562125176.614 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-03T03:39:36.618Z,1562125176.618 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=35 count;

2019-07-03T03:39:36.618Z,1562125176.618 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity=3 count;

2019-07-03T03:39:36.618Z,1562125176.618 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-07-03T03:39:36.618Z,1562125176.618 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-07-03T03:39:36.618Z,1562125176.618 [CommandLine](IMPORTANT): HorizontalControl.kiHeading=0.001 reciprocal_second;

2019-07-03T03:39:36.619Z,1562125176.619 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none;

2019-07-03T03:39:36.619Z,1562125176.619 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree;

2019-07-03T03:39:36.619Z,1562125176.619 [CommandLine](IMPORTANT): Micromodem.loadAtStartup=1 bool;

2019-07-03T03:39:36.619Z,1562125176.619 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-07-03T03:39:36.968Z,1562125176.968 [MissionManager](IMPORTANT): Started mission Startup
2019-07-03T03:39:36.969Z,1562125176.969 [Startup] Running Loop=1
2019-07-03T03:39:36.970Z,1562125176.970 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-03T03:39:36.970Z,1562125176.970 [Startup:A.GoToSurface] Running Loop=1
2019-07-03T03:39:36.970Z,1562125176.970 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-03T03:39:36.972Z,1562125176.972 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-03T03:39:36.974Z,1562125176.974 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-03T03:39:36.975Z,1562125176.975 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-03T03:39:36.977Z,1562125176.977 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-03T03:39:36.978Z,1562125176.978 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-03T03:39:36.983Z,1562125176.983 [Startup:StartupSatComms] Running Loop=1
2019-07-03T03:39:36.983Z,1562125176.983 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-03T03:39:36.983Z,1562125176.983 [Startup:StartupSatComms:A] Running Loop=1
2019-07-03T03:39:37.345Z,1562125177.345 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-03T03:39:39.333Z,1562125179.333 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:42.153Z,1562125182.153 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:44.985Z,1562125184.985 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:48.213Z,1562125188.213 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:51.045Z,1562125191.045 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:54.273Z,1562125194.273 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:39:57.109Z,1562125197.109 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:00.333Z,1562125200.333 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:03.161Z,1562125203.161 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:05.989Z,1562125205.989 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:09.229Z,1562125209.229 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:12.053Z,1562125212.053 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:15.289Z,1562125215.289 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:18.109Z,1562125218.109 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:20.937Z,1562125220.937 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:24.173Z,1562125224.173 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:25.821Z,1562125225.821 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-07-03T03:40:25.822Z,1562125225.822 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +2.30,        +1.93,    2   +0.72,   0.00,116.00
2019-07-03T03:40:27.013Z,1562125227.013 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:30.229Z,1562125230.229 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:33.061Z,1562125233.061 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:36.293Z,1562125236.293 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:37.137Z,1562125237.137 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-03T03:39:36.0Z
2019-07-03T03:40:37.137Z,1562125237.137 [Startup:StartupSatComms:A] Stopped
2019-07-03T03:40:37.137Z,1562125237.137 [Startup:StartupSatComms:B] Running Loop=1
2019-07-03T03:40:37.530Z,1562125237.530 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-03T03:40:38.881Z,1562125238.881 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 1B231C5D000000005D00000400530000000000000000151D80030C5669BF31555EAE1409A708CE248A68C21DA52C4E73F36187A65AD4C201EFDF0AC4C23C5EE2
2019-07-03T03:40:38.881Z,1562125238.881 [Micromodem](INFO): Outgoing frame #2, 43 bytes: 37334F06F9F49C8022F78EE58C2605D5FACB063C71B5FE4533BA02326B2A1403878E6EA79858D82C4E3770
2019-07-03T03:40:38.881Z,1562125238.881 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-07-03T03:40:39.019Z,1562125239.019 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-07-03T03:40:39.363Z,1562125239.363 [Micromodem](INFO): Nmea in: $CADRQ,034039,1,9,0,64,1*43

2019-07-03T03:40:39.364Z,1562125239.364 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,1B231C5D000000005D00000400530000000000000000151D80030C5669BF31555EAE1409A708CE248A68C21DA52C4E73F36187A65AD4C201EFDF0AC4C23C5EE2*0A

2019-07-03T03:40:39.381Z,1562125239.381 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:39.767Z,1562125239.767 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-03T03:40:40.171Z,1562125240.171 [Micromodem](INFO): Nmea in: $CADRQ,034039,1,9,0,64,2*40

2019-07-03T03:40:40.172Z,1562125240.172 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,37334F06F9F49C8022F78EE58C2605D5FACB063C71B5FE4533BA02326B2A1403878E6EA79858D82C4E3770*0F

2019-07-03T03:40:40.583Z,1562125240.583 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,43*74

2019-07-03T03:40:40.979Z,1562125240.979 [Micromodem](INFO): Nmea in: $CATXP,107*44

2019-07-03T03:40:42.213Z,1562125242.213 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:43.425Z,1562125243.425 [Micromodem](INFO): Nmea in: $CATXF,107*52

2019-07-03T03:40:44.728Z,1562125244.728 [Micromodem](INFO): Nmea in: $CAXST,6,20190703,034040.482498,3,0,200,4000,10000,1,1,9,1,2,2,3,107*4A

2019-07-03T03:40:45.141Z,1562125245.141 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:48.373Z,1562125248.373 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:51.201Z,1562125251.201 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:54.033Z,1562125254.033 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:40:57.265Z,1562125257.265 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:00.092Z,1562125260.092 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:03.333Z,1562125263.333 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:06.149Z,1562125266.149 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:09.385Z,1562125269.385 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:12.209Z,1562125272.209 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:15.037Z,1562125275.037 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:15.067Z,1562125275.067 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-03T03:41:15.067Z,1562125275.067 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-03T03:41:15.093Z,1562125275.093 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-03T03:41:15.474Z,1562125275.474 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-03T03:41:15.474Z,1562125275.474 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-03T03:41:18.277Z,1562125278.277 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:21.101Z,1562125281.101 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:24.329Z,1562125284.329 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:27.161Z,1562125287.161 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:30.397Z,1562125290.397 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:33.221Z,1562125293.221 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:36.045Z,1562125296.045 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:37.293Z,1562125297.293 [Startup:StartupSatComms:B](INFO): Timed out from 2019-07-03T03:40:37.1Z
2019-07-03T03:41:37.293Z,1562125297.293 [Startup:StartupSatComms:B] Stopped
2019-07-03T03:41:37.293Z,1562125297.293 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-03T03:41:37.293Z,1562125297.293 [Startup:StartupSatComms] Stopped
2019-07-03T03:41:37.293Z,1562125297.293 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-03T03:41:37.294Z,1562125297.294 [Startup](INFO): Completed Startup
2019-07-03T03:41:37.294Z,1562125297.294 [MissionManager](INFO): Startup is completed.
2019-07-03T03:41:37.294Z,1562125297.294 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-03T03:41:37.295Z,1562125297.295 [Startup] Stopped
2019-07-03T03:41:37.295Z,1562125297.295 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-03T03:41:37.295Z,1562125297.295 [Startup:A.GoToSurface] Stopped
2019-07-03T03:41:37.295Z,1562125297.295 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-03T03:41:37.798Z,1562125297.798 [MissionManager](IMPORTANT): Started mission Default
2019-07-03T03:41:37.798Z,1562125297.798 [Default] Running Loop=1
2019-07-03T03:41:37.798Z,1562125297.798 [Default](DEBUG): Aggregate::initialize Default
2019-07-03T03:41:37.798Z,1562125297.798 [Default:B.GoToSurface] Running Loop=1
2019-07-03T03:41:37.798Z,1562125297.798 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-03T03:41:37.799Z,1562125297.799 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-03T03:41:37.799Z,1562125297.799 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-03T03:41:37.799Z,1562125297.799 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-03T03:41:37.799Z,1562125297.799 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-03T03:41:37.800Z,1562125297.800 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-03T03:41:37.800Z,1562125297.800 [Default:A.Wait] Running Loop=1
2019-07-03T03:41:37.800Z,1562125297.800 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-03T03:41:39.277Z,1562125299.277 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:42.105Z,1562125302.105 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:45.307Z,1562125305.307 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004885
2019-07-03T03:41:45.341Z,1562125305.341 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:48.169Z,1562125308.169 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:51.136Z,1562125311.136 [Default:A.Wait](INFO): Done Waiting.
2019-07-03T03:41:51.136Z,1562125311.136 [Default:A.Wait] Stopped
2019-07-03T03:41:51.136Z,1562125311.136 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-03T03:41:51.397Z,1562125311.397 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:51.452Z,1562125311.452 [Default:CheckIn] Running Loop=1
2019-07-03T03:41:51.452Z,1562125311.452 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-03T03:41:51.452Z,1562125311.452 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-03T03:41:51.878Z,1562125311.878 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-03T03:41:54.229Z,1562125314.229 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:41:57.057Z,1562125317.057 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:42:00.289Z,1562125320.289 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:42:03.117Z,1562125323.117 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:42:06.345Z,1562125326.345 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:42:09.173Z,1562125329.173 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:42:12.405Z,1562125332.405 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:42:15.233Z,1562125335.233 [NAL9602](DEBUG): Fix Requested
2019-07-03T03:42:15.637Z,1562125335.637 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,034202.00,A,3648.61448,N,12149.64758,W,0.525,42.79,030719,,,A*4C
2019-07-03T03:42:15.640Z,1562125335.640 [NAL9602](INFO): GPS fix at 20190703T034202: (36.810241, -121.827460)
2019-07-03T03:42:15.700Z,1562125335.700 [Default:CheckIn:Read_GPS] Stopped
2019-07-03T03:42:15.700Z,1562125335.700 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-03T03:42:16.111Z,1562125336.111 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-03T03:42:16.578Z,1562125336.578 [Micromodem](ERROR): Buffer fill timout failure.
2019-07-03T03:42:18.187Z,1562125338.187 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 1B231C5D000000005D00000400530000000000000000151D80030C5669BF31555EAE1409A708CE248A68C21DA52C4E73F36187A65AD4C201EFDF0AC4C23C5EE2
2019-07-03T03:42:18.188Z,1562125338.188 [Micromodem](INFO): Outgoing frame #2, 43 bytes: 37334F06F9F49C8022F78EE58C2605D5FACB063C71B5FE4533BA02326B2A1403878E6EA79858D82C4E3770
2019-07-03T03:42:18.188Z,1562125338.188 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-07-03T03:42:18.847Z,1562125338.847 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-07-03T03:42:19.191Z,1562125339.191 [Micromodem](INFO): Nmea in: $CADRQ,034218,1,9,0,64,1*42

2019-07-03T03:42:19.191Z,1562125339.191 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,1B231C5D000000005D00000400530000000000000000151D80030C5669BF31555EAE1409A708CE248A68C21DA52C4E73F36187A65AD4C201EFDF0AC4C23C5EE2*0A

2019-07-03T03:42:19.602Z,1562125339.602 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-03T03:42:19.999Z,1562125339.999 [Micromodem](INFO): Nmea in: $CADRQ,034219,1,9,0,64,2*40

2019-07-03T03:42:19.999Z,1562125339.999 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,37334F06F9F49C8022F78EE58C2605D5FACB063C71B5FE4533BA02326B2A1403878E6EA79858D82C4E3770*0F

2019-07-03T03:42:20.415Z,1562125340.415 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,43*74

2019-07-03T03:42:20.819Z,1562125340.819 [Micromodem](INFO): Nmea in: $CATXP,107*44

2019-07-03T03:42:23.231Z,1562125343.231 [Micromodem](INFO): Nmea in: $CATXF,107*52

2019-07-03T03:42:23.664Z,1562125343.664 [Micromodem](INFO): Nmea in: $CAXST,6,20190703,034220.315309,3,0,200,4000,10000,1,1,9,1,2,2,3,107*48

2019-07-03T03:42:24.100Z,1562125344.100 [DataOverHttps](INFO): Sending 99 bytes from file Logs/20190703T033803/Courier0000.lzma
2019-07-03T03:42:24.914Z,1562125344.914 [DataOverHttps](INFO): Moved sent file to Logs/20190703T033803/Courier0000.lzma.bak
2019-07-03T03:42:24.915Z,1562125344.915 [DataOverHttps](INFO): SBD MOMSN=11423589
2019-07-03T03:42:38.261Z,1562125358.261 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190703T033803/Courier0004.lzma
2019-07-03T03:42:39.066Z,1562125359.066 [DataOverHttps](INFO): Moved sent file to Logs/20190703T033803/Courier0004.lzma.bak
2019-07-03T03:42:39.067Z,1562125359.067 [DataOverHttps](INFO): SBD MOMSN=11423593
2019-07-03T03:42:49.088Z,1562125369.088 [NAL9602](INFO): Powering down
2019-07-03T03:42:54.314Z,1562125374.314 [DataOverHttps](INFO): Sending 909 bytes from file Logs/20190703T033803/Express0001.lzma
2019-07-03T03:42:55.118Z,1562125375.118 [DataOverHttps](INFO): Moved sent file to Logs/20190703T033803/Express0001.lzma.bak
2019-07-03T03:42:55.119Z,1562125375.119 [DataOverHttps](INFO): SBD MOMSN=11423597
2019-07-03T03:43:08.533Z,1562125388.533 [DataOverHttps](INFO): Sending 210 bytes from file Logs/20190703T033803/Express0005.lzma
2019-07-03T03:43:09.338Z,1562125389.338 [DataOverHttps](INFO): Moved sent file to Logs/20190703T033803/Express0005.lzma.bak
2019-07-03T03:43:09.339Z,1562125389.339 [DataOverHttps](INFO): SBD MOMSN=11423621
2019-07-03T03:43:11.464Z,1562125391.464 [Default:CheckIn:Read_Iridium] Stopped
2019-07-03T03:43:11.464Z,1562125391.464 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-03T03:43:11.465Z,1562125391.465 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-03T03:43:59.650Z,1562125439.650 [DataOverHttps](IMPORTANT): SBD MTMSN=20190703T034347
2019-07-03T03:44:05.285Z,1562125445.285 [DataOverHttps](INFO): Received command:configSet DUSBL_Hydroid.detectionThreshold 25 count persist;restart sys
2019-07-03T03:44:05.570Z,1562125445.570 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.detectionThreshold 25.000000 count persist
2019-07-03T03:44:05.574Z,1562125445.574 [CommandLine](IMPORTANT): got command restart system
2019-07-03T03:44:07.693Z,1562125447.693 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:07.693Z,1562125447.693 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:07.810Z,1562125447.810 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-03T03:44:07.810Z,1562125447.810 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:07.811Z,1562125447.811 [CommandLine](INFO): Join timeout helper Thread ID is 932
2019-07-03T03:44:07.811Z,1562125447.811 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-03T03:44:07.811Z,1562125447.811 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:07.812Z,1562125447.812 [NavChartDb](INFO): Join timeout helper Thread ID is 933
2019-07-03T03:44:08.033Z,1562125448.033 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:08.033Z,1562125448.033 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.037Z,1562125448.037 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-07-03T03:44:08.037Z,1562125448.037 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.037Z,1562125448.037 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 934
2019-07-03T03:44:08.069Z,1562125448.069 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:08.069Z,1562125448.069 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-03T03:44:08.070Z,1562125448.070 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.077Z,1562125448.077 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-07-03T03:44:08.077Z,1562125448.077 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.077Z,1562125448.077 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 935
2019-07-03T03:44:08.153Z,1562125448.153 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:08.153Z,1562125448.153 [CTD_NeilBrown](INFO): Powering down
2019-07-03T03:44:08.165Z,1562125448.165 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.177Z,1562125448.177 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-03T03:44:08.177Z,1562125448.177 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.177Z,1562125448.177 [Radio_Surface](INFO): Join timeout helper Thread ID is 936
2019-07-03T03:44:08.469Z,1562125448.469 [Radio_Surface](INFO): Powering down
2019-07-03T03:44:08.470Z,1562125448.470 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:08.470Z,1562125448.470 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.482Z,1562125448.482 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-03T03:44:08.482Z,1562125448.482 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.482Z,1562125448.482 [DataOverHttps](INFO): Join timeout helper Thread ID is 937
2019-07-03T03:44:08.513Z,1562125448.513 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:08.513Z,1562125448.513 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.523Z,1562125448.523 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-03T03:44:08.523Z,1562125448.523 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.523Z,1562125448.523 [logger](INFO): Join timeout helper Thread ID is 938
2019-07-03T03:44:08.533Z,1562125448.533 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:08.533Z,1562125448.533 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.542Z,1562125448.542 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-03T03:44:08.542Z,1562125448.542 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.542Z,1562125448.542 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-03T03:44:08.542Z,1562125448.542 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:08.542Z,1562125448.542 [controlThread](INFO): Join timeout helper Thread ID is 939
2019-07-03T03:44:08.657Z,1562125448.657 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-03T03:44:08.657Z,1562125448.657 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-03T03:44:08.658Z,1562125448.658 [AHRS_M2](INFO): Powering down
2019-07-03T03:44:08.730Z,1562125448.730 [DUSBL_Hydroid](INFO): Powering down
2019-07-03T03:44:08.821Z,1562125448.821 [Micromodem](INFO): Powering down
2019-07-03T03:44:08.917Z,1562125448.917 [NAL9602](INFO): Powering down
2019-07-03T03:44:08.989Z,1562125448.989 [RDI_Pathfinder](INFO): Powering down
2019-07-03T03:44:08.991Z,1562125448.991 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-03T03:44:08.992Z,1562125448.992 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-03T03:44:08.992Z,1562125448.992 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-03T03:44:08.993Z,1562125448.993 [MissionManager](INFO): Uninitializing Mission Default
2019-07-03T03:44:08.993Z,1562125448.993 [Default] Stopped
2019-07-03T03:44:08.993Z,1562125448.993 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-03T03:44:08.993Z,1562125448.993 [Default:B.GoToSurface] Stopped
2019-07-03T03:44:08.993Z,1562125448.993 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-03T03:44:08.993Z,1562125448.993 [Default:CheckIn] Stopped
2019-07-03T03:44:08.993Z,1562125448.993 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-03T03:44:08.993Z,1562125448.993 [Default:CheckIn:C.Wait] Stopped
2019-07-03T03:44:08.994Z,1562125448.994 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-03T03:44:08.996Z,1562125448.996 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-03T03:44:08.996Z,1562125448.996 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-03T03:44:08.997Z,1562125448.997 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-03T03:44:08.997Z,1562125448.997 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-03T03:44:08.997Z,1562125448.997 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-03T03:44:08.997Z,1562125448.997 [BuoyancyServo](INFO): Powering down
2019-07-03T03:44:09.009Z,1562125449.009 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-03T03:44:09.009Z,1562125449.009 [ElevatorServo](INFO): Powering down
2019-07-03T03:44:09.010Z,1562125449.010 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-03T03:44:09.010Z,1562125449.010 [MassServo](INFO): Powering down
2019-07-03T03:44:09.011Z,1562125449.011 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-03T03:44:09.011Z,1562125449.011 [RudderServo](INFO): Powering down
2019-07-03T03:44:09.012Z,1562125449.012 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-03T03:44:09.012Z,1562125449.012 [ThrusterServo](INFO): Powering down
2019-07-03T03:44:09.013Z,1562125449.013 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-03T03:44:09.013Z,1562125449.013 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-03T03:44:09.014Z,1562125449.014 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-03T03:44:09.014Z,1562125449.014 [CBIT](DEBUG): Powering off loads.
2019-07-03T03:44:09.025Z,1562125449.025 [CBIT](DEBUG): Disabling WDT.
2019-07-03T03:44:09.037Z,1562125449.037 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-03T03:44:09.038Z,1562125449.038 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:09.082Z,1562125449.082 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:09.092Z,1562125449.092 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:09.136Z,1562125449.136 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:09.138Z,1562125449.138 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:09.200Z,1562125449.200 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-03T03:44:09.275Z,1562125449.275 [logger ThreadHandler](INFO): Thread cancelled.