2019-05-21T14:32:57.666Z,1558449177.666 [Supervisor](DEBUG): Initializing supervisor.
2019-05-21T14:32:57.668Z,1558449177.668 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-21T14:32:57.669Z,1558449177.669 [SyncHandler](INFO): Protected caller Thread ID is 5106
2019-05-21T14:32:57.669Z,1558449177.669 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-21T14:32:57.670Z,1558449177.670 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-21T14:32:57.671Z,1558449177.671 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5107
2019-05-21T14:32:57.673Z,1558449177.673 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-21T14:32:57.782Z,1558449177.782 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-21T14:32:57.783Z,1558449177.783 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-21T14:32:57.784Z,1558449177.784 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5108
2019-05-21T14:32:57.785Z,1558449177.785 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-21T14:32:57.786Z,1558449177.786 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-21T14:32:57.786Z,1558449177.786 [logger ThreadHandler](INFO): Protected caller Thread ID is 5109
2019-05-21T14:32:57.788Z,1558449177.788 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-21T14:32:57.788Z,1558449177.788 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-21T14:32:57.790Z,1558449177.790 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-21T14:32:58.214Z,1558449178.214 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-21T14:32:58.214Z,1558449178.214 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-21T14:32:58.313Z,1558449178.313 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-21T14:32:58.314Z,1558449178.314 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-21T14:32:58.640Z,1558449178.640 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-21T14:32:58.641Z,1558449178.641 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-21T14:32:58.784Z,1558449178.784 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-21T14:32:58.785Z,1558449178.785 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-21T14:32:58.978Z,1558449178.978 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-21T14:32:58.979Z,1558449178.979 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-21T14:32:59.436Z,1558449179.436 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-21T14:32:59.437Z,1558449179.437 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-21T14:32:59.648Z,1558449179.648 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-21T14:32:59.649Z,1558449179.649 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-21T14:32:59.796Z,1558449179.796 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-21T14:32:59.797Z,1558449179.797 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-21T14:32:59.992Z,1558449179.992 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-21T14:32:59.993Z,1558449179.993 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-21T14:33:00.091Z,1558449180.091 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-21T14:33:00.091Z,1558449180.091 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-21T14:33:00.413Z,1558449180.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-21T14:33:00.413Z,1558449180.413 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-21T14:33:00.496Z,1558449180.496 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-21T14:33:00.601Z,1558449180.601 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-21T14:33:00.601Z,1558449180.601 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-21T14:33:01.194Z,1558449181.194 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-21T14:33:01.195Z,1558449181.195 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-21T14:33:01.585Z,1558449181.585 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-21T14:33:01.587Z,1558449181.587 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-21T14:33:01.588Z,1558449181.588 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-21T14:33:01.797Z,1558449181.797 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-21T14:33:01.899Z,1558449181.899 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-21T14:33:01.999Z,1558449181.999 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-21T14:33:02.227Z,1558449182.227 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-21T14:33:02.228Z,1558449182.228 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-21T14:33:02.316Z,1558449182.316 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-21T14:33:02.427Z,1558449182.427 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-21T14:33:02.772Z,1558449182.772 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-21T14:33:02.864Z,1558449182.864 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-21T14:33:03.012Z,1558449183.012 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-21T14:33:03.198Z,1558449183.198 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-21T14:33:03.331Z,1558449183.331 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/LOGIN/
2019-05-21T14:33:03.332Z,1558449183.332 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-21T14:33:03.347Z,1558449183.347 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-21T14:33:03.732Z,1558449183.732 [AHRS_M2] Loaded
2019-05-21T14:33:03.732Z,1558449183.732 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-21T14:33:03.805Z,1558449183.805 [DataOverHttps] Loaded
2019-05-21T14:33:03.805Z,1558449183.805 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-21T14:33:03.806Z,1558449183.806 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407604E0
2019-05-21T14:33:03.807Z,1558449183.807 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5188
2019-05-21T14:33:03.820Z,1558449183.820 [Depth_Keller] Loaded
2019-05-21T14:33:03.820Z,1558449183.820 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-21T14:33:03.825Z,1558449183.825 [DropWeight] Loaded
2019-05-21T14:33:03.825Z,1558449183.825 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-21T14:33:03.883Z,1558449183.883 [DUSBL_Hydroid] Loaded
2019-05-21T14:33:03.883Z,1558449183.883 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-21T14:33:03.931Z,1558449183.931 [Micromodem] Loaded
2019-05-21T14:33:03.932Z,1558449183.932 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-21T14:33:04.031Z,1558449184.031 [NAL9602] Loaded
2019-05-21T14:33:04.031Z,1558449184.031 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-21T14:33:04.047Z,1558449184.047 [Onboard] Loaded
2019-05-21T14:33:04.047Z,1558449184.047 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-21T14:33:04.053Z,1558449184.053 [PowerOnly] Loaded
2019-05-21T14:33:04.054Z,1558449184.054 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-21T14:33:04.060Z,1558449184.060 [Radio_Surface] Loaded
2019-05-21T14:33:04.061Z,1558449184.061 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-21T14:33:04.062Z,1558449184.062 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407904E0
2019-05-21T14:33:04.062Z,1558449184.062 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5189
2019-05-21T14:33:04.107Z,1558449184.107 [RDI_Pathfinder] Loaded
2019-05-21T14:33:04.107Z,1558449184.107 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-21T14:33:05.635Z,1558449185.635 [BPC1] Loaded
2019-05-21T14:33:05.635Z,1558449185.635 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-21T14:33:05.636Z,1558449185.636 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-21T14:33:05.636Z,1558449185.636 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-21T14:33:05.649Z,1558449185.649 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-21T14:33:05.650Z,1558449185.650 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-21T14:33:05.757Z,1558449185.757 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-21T14:33:05.757Z,1558449185.757 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-21T14:33:05.779Z,1558449185.779 [NavChart] Loaded
2019-05-21T14:33:05.779Z,1558449185.779 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-21T14:33:05.783Z,1558449185.783 [UniversalFixResidualReporter] Loaded
2019-05-21T14:33:05.783Z,1558449185.783 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-21T14:33:05.784Z,1558449185.784 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-21T14:33:05.784Z,1558449185.784 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-21T14:33:05.894Z,1558449185.894 [BuoyancyServo] Loaded
2019-05-21T14:33:05.894Z,1558449185.894 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-21T14:33:05.909Z,1558449185.909 [ElevatorServo] Loaded
2019-05-21T14:33:05.909Z,1558449185.909 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-21T14:33:05.925Z,1558449185.925 [MassServo] Loaded
2019-05-21T14:33:05.925Z,1558449185.925 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-21T14:33:05.940Z,1558449185.940 [RudderServo] Loaded
2019-05-21T14:33:05.940Z,1558449185.940 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-21T14:33:05.955Z,1558449185.955 [ThrusterServo] Loaded
2019-05-21T14:33:05.956Z,1558449185.956 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-21T14:33:05.956Z,1558449185.956 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-21T14:33:05.957Z,1558449185.957 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-21T14:33:06.213Z,1558449186.213 [CTD_NeilBrown] Loaded
2019-05-21T14:33:06.213Z,1558449186.213 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-21T14:33:06.214Z,1558449186.214 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D24E0
2019-05-21T14:33:06.214Z,1558449186.214 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5190
2019-05-21T14:33:06.260Z,1558449186.260 [WetLabsSeaOWL_UV_A] Loaded
2019-05-21T14:33:06.260Z,1558449186.260 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-21T14:33:06.261Z,1558449186.261 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409024E0
2019-05-21T14:33:06.261Z,1558449186.261 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 5191
2019-05-21T14:33:06.262Z,1558449186.262 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-21T14:33:06.262Z,1558449186.262 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-21T14:33:06.560Z,1558449186.560 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-21T14:33:06.560Z,1558449186.560 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-21T14:33:06.602Z,1558449186.602 [DepthRateCalculator] Loaded
2019-05-21T14:33:06.602Z,1558449186.602 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-21T14:33:06.608Z,1558449186.608 [PitchRateCalculator] Loaded
2019-05-21T14:33:06.608Z,1558449186.608 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-21T14:33:06.621Z,1558449186.621 [SpeedCalculator] Loaded
2019-05-21T14:33:06.621Z,1558449186.621 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-21T14:33:06.643Z,1558449186.643 [TempGradientCalculator] Loaded
2019-05-21T14:33:06.643Z,1558449186.643 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-21T14:33:06.649Z,1558449186.649 [YawRateCalculator] Loaded
2019-05-21T14:33:06.649Z,1558449186.649 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-21T14:33:06.690Z,1558449186.690 [ElevatorOffsetCalculator] Loaded
2019-05-21T14:33:06.690Z,1558449186.690 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-21T14:33:06.691Z,1558449186.691 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-21T14:33:06.691Z,1558449186.691 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-21T14:33:06.830Z,1558449186.830 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-21T14:33:06.852Z,1558449186.852 [SBIT] Loaded
2019-05-21T14:33:06.853Z,1558449186.853 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-21T14:33:06.853Z,1558449186.853 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-21T14:33:06.865Z,1558449186.865 [IBIT] Loaded
2019-05-21T14:33:06.866Z,1558449186.866 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-21T14:33:06.869Z,1558449186.869 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-21T14:33:07.009Z,1558449187.009 [CBIT] Loaded
2019-05-21T14:33:07.009Z,1558449187.009 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-21T14:33:07.009Z,1558449187.009 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-21T14:33:07.010Z,1558449187.010 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-21T14:33:07.081Z,1558449187.081 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-21T14:33:07.082Z,1558449187.082 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-21T14:33:07.181Z,1558449187.181 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-21T14:33:07.181Z,1558449187.181 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-21T14:33:07.249Z,1558449187.249 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-21T14:33:07.334Z,1558449187.334 [VerticalControl] Loaded
2019-05-21T14:33:07.335Z,1558449187.335 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-21T14:33:07.335Z,1558449187.335 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-21T14:33:07.393Z,1558449187.393 [HorizontalControl] Loaded
2019-05-21T14:33:07.394Z,1558449187.394 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-21T14:33:07.394Z,1558449187.394 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-21T14:33:07.396Z,1558449187.396 [SpeedControl] Loaded
2019-05-21T14:33:07.396Z,1558449187.396 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-21T14:33:07.397Z,1558449187.397 [LoopControl](DEBUG): Construct LoopControl.
2019-05-21T14:33:07.398Z,1558449187.398 [LoopControl] Loaded
2019-05-21T14:33:07.398Z,1558449187.398 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-21T14:33:07.398Z,1558449187.398 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-21T14:33:07.399Z,1558449187.399 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-21T14:33:07.425Z,1558449187.425 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-21T14:33:07.441Z,1558449187.441 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-21T14:33:07.473Z,1558449187.473 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-21T14:33:07.479Z,1558449187.479 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-21T14:33:07.481Z,1558449187.481 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD94E0
2019-05-21T14:33:07.481Z,1558449187.481 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5192
2019-05-21T14:33:07.493Z,1558449187.493 [Supervisor](INFO): Main Thread ID is 5105
2019-05-21T14:33:07.493Z,1558449187.493 [Supervisor](DEBUG): Running supervisor.
2019-05-21T14:33:07.494Z,1558449187.494 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5193
2019-05-21T14:33:07.513Z,1558449187.513 [controlThread ThreadHandler](INFO): Handler Thread ID is 5194
2019-05-21T14:33:07.514Z,1558449187.514 [controlThread](DEBUG): Initializing ControlThread
2019-05-21T14:33:07.520Z,1558449187.520 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-21T14:33:07.520Z,1558449187.520 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-21T14:33:07.522Z,1558449187.522 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-21T14:33:07.522Z,1558449187.522 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-21T14:33:07.523Z,1558449187.523 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-21T14:33:07.523Z,1558449187.523 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-21T14:33:07.524Z,1558449187.524 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-21T14:33:07.524Z,1558449187.524 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-21T14:33:07.525Z,1558449187.525 [SBIT](INFO): Initialize SBIT Component.
2019-05-21T14:33:07.525Z,1558449187.525 [SBIT](IMPORTANT): git: 2019-05-01-9-g5be6d91
2019-05-21T14:33:07.525Z,1558449187.525 [SBIT](INFO): git hash: 5be6d91bfd1d3ef858080230e47d423d1f938b96
2019-05-21T14:33:07.526Z,1558449187.526 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-21T14:33:07.527Z,1558449187.527 [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:33:07.528Z,1558449187.528 [SBIT](INFO): Beginning SBIT in 52.000000 seconds.
2019-05-21T14:33:07.529Z,1558449187.529 [IBIT](INFO): Initialize IBIT Component.
2019-05-21T14:33:07.530Z,1558449187.530 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-21T14:33:07.533Z,1558449187.533 [logger ThreadHandler](INFO): Handler Thread ID is 5195
2019-05-21T14:33:07.541Z,1558449187.541 [CBIT](DEBUG): Initialized mux pins.
2019-05-21T14:33:07.541Z,1558449187.541 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-21T14:33:07.545Z,1558449187.545 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5196
2019-05-21T14:33:07.547Z,1558449187.547 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-21T14:33:07.553Z,1558449187.553 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5197
2019-05-21T14:33:07.555Z,1558449187.555 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5198
2019-05-21T14:33:07.556Z,1558449187.556 [CTD_NeilBrown](INFO): Powering down
2019-05-21T14:33:07.565Z,1558449187.565 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-21T14:33:07.565Z,1558449187.565 [CBIT](DEBUG): Initializing heartbeat.
2019-05-21T14:33:07.577Z,1558449187.577 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 5199
2019-05-21T14:33:07.578Z,1558449187.578 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-21T14:33:07.583Z,1558449187.583 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5200
2019-05-21T14:33:07.587Z,1558449187.587 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-21T14:33:07.587Z,1558449187.587 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-21T14:33:07.587Z,1558449187.587 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-21T14:33:07.587Z,1558449187.587 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-21T14:33:07.587Z,1558449187.587 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-21T14:33:07.588Z,1558449187.588 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-21T14:33:07.588Z,1558449187.588 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-21T14:33:07.588Z,1558449187.588 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-21T14:33:07.588Z,1558449187.588 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-21T14:33:07.588Z,1558449187.588 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-21T14:33:07.589Z,1558449187.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-21T14:33:07.589Z,1558449187.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-21T14:33:07.589Z,1558449187.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-21T14:33:07.589Z,1558449187.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-21T14:33:07.589Z,1558449187.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-21T14:33:07.590Z,1558449187.590 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-21T14:33:07.637Z,1558449187.637 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-21T14:33:07.637Z,1558449187.637 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-21T14:33:07.673Z,1558449187.673 [CBIT](DEBUG): Backplane powered.
2019-05-21T14:33:07.673Z,1558449187.673 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-21T14:33:07.675Z,1558449187.675 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-21T14:33:07.676Z,1558449187.676 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-21T14:33:07.676Z,1558449187.676 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-21T14:33:07.677Z,1558449187.677 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-21T14:33:07.687Z,1558449187.687 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-21T14:33:07.698Z,1558449187.698 [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-05-21T14:33:07.698Z,1558449187.698 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-21T14:33:07.779Z,1558449187.779 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-21T14:33:07.780Z,1558449187.780 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-21T14:33:07.794Z,1558449187.794 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-21T14:33:07.837Z,1558449187.837 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-21T14:33:07.840Z,1558449187.840 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-21T14:33:07.861Z,1558449187.861 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-21T14:33:07.865Z,1558449187.865 [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-05-21T14:33:07.869Z,1558449187.869 [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:33:07.889Z,1558449187.889 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-21T14:33:07.942Z,1558449187.942 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-21T14:33:07.942Z,1558449187.942 [DUSBL_Hydroid](INFO): Powering up
2019-05-21T14:33:07.943Z,1558449187.943 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-21T14:33:07.957Z,1558449187.957 [Radio_Surface](INFO): Powering up
2019-05-21T14:33:07.977Z,1558449187.977 [Micromodem](INFO): Start
2019-05-21T14:33:08.033Z,1558449188.033 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-21T14:33:08.051Z,1558449188.051 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:33:08.057Z,1558449188.057 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-21T14:33:08.058Z,1558449188.058 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:33:08.065Z,1558449188.065 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-21T14:33:08.066Z,1558449188.066 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:33:08.073Z,1558449188.073 [MassServo](DEBUG): Initializing MassServo.
2019-05-21T14:33:08.074Z,1558449188.074 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:33:08.081Z,1558449188.081 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-21T14:33:08.082Z,1558449188.082 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:33:08.089Z,1558449188.089 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-21T14:33:08.295Z,1558449188.295 [Micromodem](INFO): Starting
2019-05-21T14:33:08.295Z,1558449188.295 [Micromodem](INFO): Powering up
2019-05-21T14:33:08.295Z,1558449188.295 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-21T14:33:08.329Z,1558449188.329 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-21T14:33:08.687Z,1558449188.687 [Micromodem](INFO): Starting
2019-05-21T14:33:09.013Z,1558449189.013 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-21T14:33:09.013Z,1558449189.013 [RudderServo](FAULT): Rudder failed to initialize
2019-05-21T14:33:09.013Z,1558449189.013 [RudderServo] Communications Fault, FailCount= 1
2019-05-21T14:33:09.013Z,1558449189.013 [RudderServo](ERROR): Communications Fault
2019-05-21T14:33:09.124Z,1558449189.124 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-21T14:33:09.134Z,1558449189.134 [Micromodem](INFO): Starting
2019-05-21T14:33:09.306Z,1558449189.306 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-21T14:33:09.306Z,1558449189.306 [RudderServo](INFO): Powering down
2019-05-21T14:33:09.538Z,1558449189.538 [Micromodem](INFO): Starting
2019-05-21T14:33:09.942Z,1558449189.942 [Micromodem](INFO): Starting
2019-05-21T14:33:09.969Z,1558449189.969 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:33:10.090Z,1558449190.090 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-21T14:33:10.094Z,1558449190.094 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-21T14:33:10.094Z,1558449190.094 [RudderServo] No Fault, FailCount= 1
2019-05-21T14:33:10.346Z,1558449190.346 [Micromodem](INFO): Starting
2019-05-21T14:33:10.750Z,1558449190.750 [Micromodem](INFO): Starting
2019-05-21T14:33:11.222Z,1558449191.222 [Micromodem](INFO): Starting
2019-05-21T14:33:11.582Z,1558449191.582 [Micromodem](INFO): Starting
2019-05-21T14:33:11.986Z,1558449191.986 [Micromodem](INFO): Starting
2019-05-21T14:33:12.451Z,1558449192.451 [Micromodem](INFO): Starting
2019-05-21T14:33:12.806Z,1558449192.806 [Micromodem](INFO): Starting
2019-05-21T14:33:13.210Z,1558449193.210 [Micromodem](INFO): Starting
2019-05-21T14:33:13.211Z,1558449193.211 [Micromodem](INFO): Starting
2019-05-21T14:33:13.213Z,1558449193.213 [Micromodem](DEBUG): Nmea buf: $CCCFG,ALL,0*33

2019-05-21T14:33:13.214Z,1558449193.214 [Micromodem](INFO): cmdSentTime_.elapsed() = 1590894733.213450
2019-05-21T14:33:13.214Z,1558449193.214 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-05-21T14:33:13.214Z,1558449193.214 [Micromodem](DEBUG): Nmea buf: $CCCFG,SRC,1*31

2019-05-21T14:33:13.215Z,1558449193.215 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.000289
2019-05-21T14:33:13.215Z,1558449193.215 [Micromodem](DEBUG): Nmea buf: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-21T14:33:13.215Z,1558449193.215 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.000783
2019-05-21T14:33:13.215Z,1558449193.215 [Micromodem](DEBUG): Nmea buf: $CCCFG,BND,1*3B

2019-05-21T14:33:13.216Z,1558449193.216 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.001237
2019-05-21T14:33:13.614Z,1558449193.614 [Micromodem](INFO): Starting
2019-05-21T14:33:13.616Z,1558449193.616 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.401219
2019-05-21T14:33:14.034Z,1558449194.034 [Micromodem](INFO): Starting
2019-05-21T14:33:14.035Z,1558449194.035 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.820401
2019-05-21T14:33:14.450Z,1558449194.450 [Micromodem](INFO): Starting
2019-05-21T14:33:14.451Z,1558449194.451 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.236419
2019-05-21T14:33:14.854Z,1558449194.854 [Micromodem](INFO): Starting
2019-05-21T14:33:14.855Z,1558449194.855 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.640512
2019-05-21T14:33:15.258Z,1558449195.258 [Micromodem](INFO): Starting
2019-05-21T14:33:15.259Z,1558449195.259 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.044424
2019-05-21T14:33:15.666Z,1558449195.666 [Micromodem](INFO): Starting
2019-05-21T14:33:15.667Z,1558449195.667 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.452376
2019-05-21T14:33:16.054Z,1558449196.054 [Micromodem](INFO): Starting
2019-05-21T14:33:16.055Z,1558449196.055 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.840524
2019-05-21T14:33:16.462Z,1558449196.462 [Micromodem](INFO): Starting
2019-05-21T14:33:16.463Z,1558449196.463 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.248494
2019-05-21T14:33:16.854Z,1558449196.854 [Micromodem](INFO): Starting
2019-05-21T14:33:16.855Z,1558449196.855 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.640411
2019-05-21T14:33:17.260Z,1558449197.260 [Micromodem](INFO): Starting
2019-05-21T14:33:17.260Z,1558449197.260 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.045576
2019-05-21T14:33:17.654Z,1558449197.654 [Micromodem](INFO): Starting
2019-05-21T14:33:17.655Z,1558449197.655 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.440483
2019-05-21T14:33:18.054Z,1558449198.054 [Micromodem](INFO): Starting
2019-05-21T14:33:18.055Z,1558449198.055 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.840414
2019-05-21T14:33:18.467Z,1558449198.467 [Micromodem](INFO): Starting
2019-05-21T14:33:18.467Z,1558449198.467 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.253043
2019-05-21T14:33:18.858Z,1558449198.858 [Micromodem](INFO): Starting
2019-05-21T14:33:18.859Z,1558449198.859 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.644535
2019-05-21T14:33:19.262Z,1558449199.262 [Micromodem](INFO): Starting
2019-05-21T14:33:19.263Z,1558449199.263 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.048423
2019-05-21T14:33:19.666Z,1558449199.666 [Micromodem](INFO): Starting
2019-05-21T14:33:19.667Z,1558449199.667 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.452421
2019-05-21T14:33:20.070Z,1558449200.070 [Micromodem](INFO): Starting
2019-05-21T14:33:20.071Z,1558449200.071 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.856546
2019-05-21T14:33:20.474Z,1558449200.474 [Micromodem](INFO): Starting
2019-05-21T14:33:20.475Z,1558449200.475 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.260217
2019-05-21T14:33:20.562Z,1558449200.562 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004607
2019-05-21T14:33:20.878Z,1558449200.878 [Micromodem](INFO): Starting
2019-05-21T14:33:20.879Z,1558449200.879 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.664427
2019-05-21T14:33:21.282Z,1558449201.282 [Micromodem](INFO): Starting
2019-05-21T14:33:21.283Z,1558449201.283 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.068537
2019-05-21T14:33:21.309Z,1558449201.309 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-21T14:33:21.686Z,1558449201.686 [Micromodem](INFO): Starting
2019-05-21T14:33:21.687Z,1558449201.687 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.472446
2019-05-21T14:33:22.090Z,1558449202.090 [Micromodem](INFO): Starting
2019-05-21T14:33:22.091Z,1558449202.091 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.876224
2019-05-21T14:33:22.494Z,1558449202.494 [Micromodem](INFO): Starting
2019-05-21T14:33:22.495Z,1558449202.495 [Micromodem](INFO): cmdSentTime_.elapsed() = 1590894742.495154
2019-05-21T14:33:22.496Z,1558449202.496 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-05-21T14:33:22.898Z,1558449202.898 [Micromodem](INFO): Starting
2019-05-21T14:33:22.899Z,1558449202.899 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.403481
2019-05-21T14:33:23.306Z,1558449203.306 [Micromodem](INFO): Starting
2019-05-21T14:33:23.308Z,1558449203.308 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.811562
2019-05-21T14:33:23.710Z,1558449203.710 [Micromodem](INFO): Starting
2019-05-21T14:33:23.711Z,1558449203.711 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.214843
2019-05-21T14:33:24.134Z,1558449204.134 [Micromodem](INFO): Starting
2019-05-21T14:33:24.136Z,1558449204.136 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.639213
2019-05-21T14:33:24.518Z,1558449204.518 [Micromodem](INFO): Starting
2019-05-21T14:33:24.519Z,1558449204.519 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.022566
2019-05-21T14:33:24.919Z,1558449204.919 [Micromodem](INFO): Starting
2019-05-21T14:33:24.919Z,1558449204.919 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.423061
2019-05-21T14:33:25.323Z,1558449205.323 [Micromodem](INFO): Starting
2019-05-21T14:33:25.324Z,1558449205.324 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.828008
2019-05-21T14:33:25.728Z,1558449205.728 [Micromodem](INFO): Starting
2019-05-21T14:33:25.728Z,1558449205.728 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.232110
2019-05-21T14:33:26.147Z,1558449206.147 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-21T14:33:26.162Z,1558449206.162 [Micromodem](INFO): Starting
2019-05-21T14:33:26.163Z,1558449206.163 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.666815
2019-05-21T14:33:26.538Z,1558449206.538 [Micromodem](INFO): Starting
2019-05-21T14:33:26.539Z,1558449206.539 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.042582
2019-05-21T14:33:26.942Z,1558449206.942 [Micromodem](INFO): Starting
2019-05-21T14:33:26.942Z,1558449206.942 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.446329
2019-05-21T14:33:27.342Z,1558449207.342 [Micromodem](INFO): Starting
2019-05-21T14:33:27.343Z,1558449207.343 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.846661
2019-05-21T14:33:27.746Z,1558449207.746 [Micromodem](INFO): Starting
2019-05-21T14:33:27.747Z,1558449207.747 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.250581
2019-05-21T14:33:28.150Z,1558449208.150 [Micromodem](INFO): Starting
2019-05-21T14:33:28.151Z,1558449208.151 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.654633
2019-05-21T14:33:28.554Z,1558449208.554 [Micromodem](INFO): Starting
2019-05-21T14:33:28.555Z,1558449208.555 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.058574
2019-05-21T14:33:28.958Z,1558449208.958 [Micromodem](INFO): Starting
2019-05-21T14:33:28.959Z,1558449208.959 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.462567
2019-05-21T14:33:29.366Z,1558449209.366 [Micromodem](INFO): Starting
2019-05-21T14:33:29.366Z,1558449209.366 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.870327
2019-05-21T14:33:29.766Z,1558449209.766 [Micromodem](INFO): Starting
2019-05-21T14:33:29.766Z,1558449209.766 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.270476
2019-05-21T14:33:30.170Z,1558449210.170 [Micromodem](INFO): Starting
2019-05-21T14:33:30.171Z,1558449210.171 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.674562
2019-05-21T14:33:30.574Z,1558449210.574 [Micromodem](INFO): Starting
2019-05-21T14:33:30.575Z,1558449210.575 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.078555
2019-05-21T14:33:30.978Z,1558449210.978 [Micromodem](INFO): Starting
2019-05-21T14:33:30.978Z,1558449210.978 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.482476
2019-05-21T14:33:31.382Z,1558449211.382 [Micromodem](INFO): Starting
2019-05-21T14:33:31.383Z,1558449211.383 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.886563
2019-05-21T14:33:31.790Z,1558449211.790 [Micromodem](INFO): Starting
2019-05-21T14:33:31.790Z,1558449211.790 [Micromodem](INFO): cmdSentTime_.elapsed() = 9.294339
2019-05-21T14:33:32.196Z,1558449212.196 [Micromodem](INFO): Starting
2019-05-21T14:33:32.197Z,1558449212.197 [Micromodem](INFO): cmdSentTime_.elapsed() = 1590894752.196638
2019-05-21T14:33:32.197Z,1558449212.197 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-21T14:33:32.594Z,1558449212.594 [Micromodem](INFO): Starting
2019-05-21T14:33:32.595Z,1558449212.595 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.397090
2019-05-21T14:33:32.998Z,1558449212.998 [Micromodem](INFO): Starting
2019-05-21T14:33:32.999Z,1558449212.999 [Micromodem](ERROR): Response from modem failed NMEA checksum: CRE,431,OPRC,.10.0.4647

2019-05-21T14:33:32.999Z,1558449212.999 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.801051
2019-05-21T14:33:33.415Z,1558449213.415 [Micromodem](INFO): Starting
2019-05-21T14:33:33.415Z,1558449213.415 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.216905
2019-05-21T14:33:33.806Z,1558449213.806 [Micromodem](INFO): Starting
2019-05-21T14:33:33.807Z,1558449213.807 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.608378
2019-05-21T14:33:34.223Z,1558449214.223 [Micromodem](INFO): Starting
2019-05-21T14:33:34.223Z,1558449214.223 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.024941
2019-05-21T14:33:34.224Z,1558449214.224 [NAL9602](INFO): Powering up NAL9602
2019-05-21T14:33:34.622Z,1558449214.622 [Micromodem](INFO): Starting
2019-05-21T14:33:34.623Z,1558449214.623 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.424579
2019-05-21T14:33:35.018Z,1558449215.018 [Micromodem](INFO): Starting
2019-05-21T14:33:35.019Z,1558449215.019 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.820546
2019-05-21T14:33:35.426Z,1558449215.426 [Micromodem](INFO): Starting
2019-05-21T14:33:35.427Z,1558449215.427 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.228358
2019-05-21T14:33:35.826Z,1558449215.826 [Micromodem](INFO): Starting
2019-05-21T14:33:35.827Z,1558449215.827 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.628493
2019-05-21T14:33:36.230Z,1558449216.230 [Micromodem](INFO): Starting
2019-05-21T14:33:36.231Z,1558449216.231 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.032404
2019-05-21T14:33:36.634Z,1558449216.634 [Micromodem](INFO): Starting
2019-05-21T14:33:36.634Z,1558449216.634 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.436290
2019-05-21T14:33:37.046Z,1558449217.046 [Micromodem](INFO): Starting
2019-05-21T14:33:37.047Z,1558449217.047 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.848629
2019-05-21T14:33:37.442Z,1558449217.442 [Micromodem](INFO): Starting
2019-05-21T14:33:37.442Z,1558449217.442 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.244188
2019-05-21T14:33:37.846Z,1558449217.846 [Micromodem](INFO): Starting
2019-05-21T14:33:37.847Z,1558449217.847 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.648393
2019-05-21T14:33:38.250Z,1558449218.250 [Micromodem](INFO): Starting
2019-05-21T14:33:38.251Z,1558449218.251 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.052483
2019-05-21T14:33:38.654Z,1558449218.654 [Micromodem](INFO): Starting
2019-05-21T14:33:38.655Z,1558449218.655 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.456384
2019-05-21T14:33:39.058Z,1558449219.058 [Micromodem](INFO): Starting
2019-05-21T14:33:39.059Z,1558449219.059 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.860383
2019-05-21T14:33:39.468Z,1558449219.468 [Micromodem](INFO): Starting
2019-05-21T14:33:39.470Z,1558449219.470 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.271234
2019-05-21T14:33:39.866Z,1558449219.866 [Micromodem](INFO): Starting
2019-05-21T14:33:39.867Z,1558449219.867 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.668384
2019-05-21T14:33:40.270Z,1558449220.270 [Micromodem](INFO): Starting
2019-05-21T14:33:40.271Z,1558449220.271 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.072405
2019-05-21T14:33:40.675Z,1558449220.675 [Micromodem](INFO): Starting
2019-05-21T14:33:40.675Z,1558449220.675 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.476925
2019-05-21T14:33:41.078Z,1558449221.078 [Micromodem](INFO): Starting
2019-05-21T14:33:41.079Z,1558449221.079 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.880391
2019-05-21T14:33:41.482Z,1558449221.482 [Micromodem](INFO): Starting
2019-05-21T14:33:41.483Z,1558449221.483 [Micromodem](INFO): cmdSentTime_.elapsed() = 9.284389
2019-05-21T14:33:41.886Z,1558449221.886 [Micromodem](INFO): Starting
2019-05-21T14:33:41.887Z,1558449221.887 [Micromodem](INFO): cmdSentTime_.elapsed() = 9.688482
2019-05-21T14:33:42.290Z,1558449222.290 [Micromodem](INFO): Starting
2019-05-21T14:33:42.291Z,1558449222.291 [Micromodem](INFO): cmdSentTime_.elapsed() = 1590894762.290876
2019-05-21T14:33:42.291Z,1558449222.291 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-05-21T14:33:42.694Z,1558449222.694 [Micromodem](INFO): Starting
2019-05-21T14:33:42.695Z,1558449222.695 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.403503
2019-05-21T14:33:43.102Z,1558449223.102 [Micromodem](INFO): Starting
2019-05-21T14:33:43.104Z,1558449223.104 [Micromodem](INFO): cmdSentTime_.elapsed() = 0.811955
2019-05-21T14:33:43.502Z,1558449223.502 [Micromodem](INFO): Starting
2019-05-21T14:33:43.503Z,1558449223.503 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.210960
2019-05-21T14:33:43.906Z,1558449223.906 [Micromodem](INFO): Starting
2019-05-21T14:33:43.907Z,1558449223.907 [Micromodem](INFO): cmdSentTime_.elapsed() = 1.614821
2019-05-21T14:33:44.310Z,1558449224.310 [Micromodem](INFO): Starting
2019-05-21T14:33:44.311Z,1558449224.311 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.018921
2019-05-21T14:33:44.714Z,1558449224.714 [Micromodem](INFO): Starting
2019-05-21T14:33:44.714Z,1558449224.714 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.422632
2019-05-21T14:33:45.137Z,1558449225.137 [Micromodem](INFO): Starting
2019-05-21T14:33:45.138Z,1558449225.138 [Micromodem](INFO): cmdSentTime_.elapsed() = 2.845759
2019-05-21T14:33:45.140Z,1558449225.140 [NAL9602](INFO): NAL9602 initialized
2019-05-21T14:33:45.522Z,1558449225.522 [Micromodem](INFO): Starting
2019-05-21T14:33:45.523Z,1558449225.523 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.230925
2019-05-21T14:33:45.930Z,1558449225.930 [Micromodem](INFO): Starting
2019-05-21T14:33:45.931Z,1558449225.931 [Micromodem](INFO): cmdSentTime_.elapsed() = 3.638806
2019-05-21T14:33:45.945Z,1558449225.945 [NAL9602](DEBUG): Fix Requested
2019-05-21T14:33:46.334Z,1558449226.334 [Micromodem](INFO): Starting
2019-05-21T14:33:46.334Z,1558449226.334 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.042592
2019-05-21T14:33:46.738Z,1558449226.738 [Micromodem](INFO): Starting
2019-05-21T14:33:46.739Z,1558449226.739 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.446876
2019-05-21T14:33:47.142Z,1558449227.142 [Micromodem](INFO): Starting
2019-05-21T14:33:47.142Z,1558449227.142 [Micromodem](INFO): cmdSentTime_.elapsed() = 4.850593
2019-05-21T14:33:47.550Z,1558449227.550 [Micromodem](INFO): Starting
2019-05-21T14:33:47.551Z,1558449227.551 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.258829
2019-05-21T14:33:47.946Z,1558449227.946 [Micromodem](INFO): Starting
2019-05-21T14:33:47.947Z,1558449227.947 [Micromodem](INFO): cmdSentTime_.elapsed() = 5.654920
2019-05-21T14:33:48.350Z,1558449228.350 [Micromodem](INFO): Starting
2019-05-21T14:33:48.350Z,1558449228.350 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.058627
2019-05-21T14:33:48.758Z,1558449228.758 [Micromodem](INFO): Starting
2019-05-21T14:33:48.758Z,1558449228.758 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.466574
2019-05-21T14:33:49.162Z,1558449229.162 [Micromodem](INFO): Starting
2019-05-21T14:33:49.162Z,1558449229.162 [Micromodem](INFO): cmdSentTime_.elapsed() = 6.870699
2019-05-21T14:33:49.562Z,1558449229.562 [Micromodem](INFO): Starting
2019-05-21T14:33:49.562Z,1558449229.562 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.270615
2019-05-21T14:33:49.966Z,1558449229.966 [Micromodem](INFO): Starting
2019-05-21T14:33:49.966Z,1558449229.966 [Micromodem](INFO): cmdSentTime_.elapsed() = 7.674610
2019-05-21T14:33:50.370Z,1558449230.370 [Micromodem](INFO): Starting
2019-05-21T14:33:50.371Z,1558449230.371 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.078909
2019-05-21T14:33:50.774Z,1558449230.774 [Micromodem](INFO): Starting
2019-05-21T14:33:50.774Z,1558449230.774 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.482629
2019-05-21T14:33:51.182Z,1558449231.182 [Micromodem](INFO): Starting
2019-05-21T14:33:51.182Z,1558449231.182 [Micromodem](INFO): cmdSentTime_.elapsed() = 8.890683
2019-05-21T14:33:51.599Z,1558449231.599 [Micromodem](INFO): Starting
2019-05-21T14:33:51.600Z,1558449231.600 [Micromodem](INFO): cmdSentTime_.elapsed() = 9.307970
2019-05-21T14:33:51.986Z,1558449231.986 [Micromodem](INFO): Starting
2019-05-21T14:33:51.987Z,1558449231.987 [Micromodem](INFO): cmdSentTime_.elapsed() = 9.694808
2019-05-21T14:33:52.402Z,1558449232.402 [Micromodem](INFO): Starting
2019-05-21T14:33:52.806Z,1558449232.806 [Micromodem](INFO): Starting
2019-05-21T14:33:53.206Z,1558449233.206 [Micromodem](INFO): Starting
2019-05-21T14:33:53.606Z,1558449233.606 [Micromodem](INFO): Starting
2019-05-21T14:33:54.006Z,1558449234.006 [Micromodem](INFO): Starting
2019-05-21T14:33:54.410Z,1558449234.410 [Micromodem](INFO): Starting
2019-05-21T14:33:54.814Z,1558449234.814 [Micromodem](INFO): Starting
2019-05-21T14:33:55.218Z,1558449235.218 [Micromodem](INFO): Starting
2019-05-21T14:33:55.622Z,1558449235.622 [Micromodem](INFO): Starting
2019-05-21T14:33:56.034Z,1558449236.034 [Micromodem](INFO): Starting
2019-05-21T14:33:56.430Z,1558449236.430 [Micromodem](INFO): Starting
2019-05-21T14:33:56.834Z,1558449236.834 [Micromodem](INFO): Starting
2019-05-21T14:33:57.238Z,1558449237.238 [Micromodem](INFO): Starting
2019-05-21T14:33:57.642Z,1558449237.642 [Micromodem](INFO): Starting
2019-05-21T14:33:58.046Z,1558449238.046 [Micromodem](INFO): Starting
2019-05-21T14:33:58.450Z,1558449238.450 [Micromodem](INFO): Starting
2019-05-21T14:33:58.854Z,1558449238.854 [Micromodem](INFO): Starting
2019-05-21T14:33:59.258Z,1558449239.258 [Micromodem](INFO): Starting
2019-05-21T14:33:59.670Z,1558449239.670 [Micromodem](INFO): Starting
2019-05-21T14:34:00.066Z,1558449240.066 [Micromodem](INFO): Starting
2019-05-21T14:34:00.115Z,1558449240.115 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-21T14:34:00.123Z,1558449240.123 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-21T14:34:00.507Z,1558449240.507 [Micromodem](INFO): Starting
2019-05-21T14:34:00.878Z,1558449240.878 [Micromodem](INFO): Starting
2019-05-21T14:34:01.278Z,1558449241.278 [Micromodem](INFO): Starting
2019-05-21T14:34:01.280Z,1558449241.280 [NAL9602](INFO): SBD MO Status=2, MOMSN=4823, MT Status=2, MTMSN=0
2019-05-21T14:34:01.281Z,1558449241.281 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-21T14:34:01.682Z,1558449241.682 [Micromodem](INFO): Starting
2019-05-21T14:34:02.086Z,1558449242.086 [Micromodem](INFO): Starting
2019-05-21T14:34:02.612Z,1558449242.612 [Micromodem](INFO): Starting
2019-05-21T14:34:03.014Z,1558449243.014 [Micromodem](INFO): Starting
2019-05-21T14:34:03.422Z,1558449243.422 [Micromodem](INFO): Starting
2019-05-21T14:34:03.834Z,1558449243.834 [Micromodem](INFO): Starting
2019-05-21T14:34:04.226Z,1558449244.226 [Micromodem](INFO): Starting
2019-05-21T14:34:04.634Z,1558449244.634 [Micromodem](INFO): Starting
2019-05-21T14:34:05.034Z,1558449245.034 [Micromodem](INFO): Starting
2019-05-21T14:34:05.438Z,1558449245.438 [Micromodem](INFO): Starting
2019-05-21T14:34:05.842Z,1558449245.842 [Micromodem](INFO): Starting
2019-05-21T14:34:06.246Z,1558449246.246 [Micromodem](INFO): Starting
2019-05-21T14:34:06.650Z,1558449246.650 [Micromodem](INFO): Starting
2019-05-21T14:34:07.058Z,1558449247.058 [Micromodem](INFO): Starting
2019-05-21T14:34:07.458Z,1558449247.458 [Micromodem](INFO): Starting
2019-05-21T14:34:07.862Z,1558449247.862 [Micromodem](INFO): Starting
2019-05-21T14:34:08.274Z,1558449248.274 [Micromodem](INFO): Starting
2019-05-21T14:34:08.674Z,1558449248.674 [Micromodem](INFO): Starting
2019-05-21T14:34:08.685Z,1558449248.685 [CommandLine](IMPORTANT): got command quit
2019-05-21T14:34:09.074Z,1558449249.074 [Micromodem](INFO): Starting
2019-05-21T14:34:09.492Z,1558449249.492 [Micromodem](INFO): Starting
2019-05-21T14:34:09.689Z,1558449249.689 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-21T14:34:09.689Z,1558449249.689 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:09.689Z,1558449249.689 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:09.821Z,1558449249.821 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-21T14:34:09.821Z,1558449249.821 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:09.822Z,1558449249.822 [CommandLine](INFO): Join timeout helper Thread ID is 5213
2019-05-21T14:34:09.822Z,1558449249.822 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-21T14:34:09.822Z,1558449249.822 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:09.823Z,1558449249.823 [NavChartDb](INFO): Join timeout helper Thread ID is 5214
2019-05-21T14:34:09.857Z,1558449249.857 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:09.857Z,1558449249.857 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:09.861Z,1558449249.861 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-21T14:34:09.861Z,1558449249.861 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:09.861Z,1558449249.861 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 5215
2019-05-21T14:34:09.886Z,1558449249.886 [Micromodem](INFO): Starting
2019-05-21T14:34:10.229Z,1558449250.229 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:10.229Z,1558449250.229 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-21T14:34:10.230Z,1558449250.230 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.245Z,1558449250.245 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-21T14:34:10.245Z,1558449250.245 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.245Z,1558449250.245 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5216
2019-05-21T14:34:10.294Z,1558449250.294 [Micromodem](INFO): Starting
2019-05-21T14:34:10.413Z,1558449250.413 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:10.413Z,1558449250.413 [CTD_NeilBrown](INFO): Powering down
2019-05-21T14:34:10.425Z,1558449250.425 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.433Z,1558449250.433 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-21T14:34:10.433Z,1558449250.433 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.433Z,1558449250.433 [Radio_Surface](INFO): Join timeout helper Thread ID is 5217
2019-05-21T14:34:10.585Z,1558449250.585 [Radio_Surface](INFO): Powering down
2019-05-21T14:34:10.586Z,1558449250.586 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:10.586Z,1558449250.586 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.594Z,1558449250.594 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-21T14:34:10.594Z,1558449250.594 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.594Z,1558449250.594 [DataOverHttps](INFO): Join timeout helper Thread ID is 5218
2019-05-21T14:34:10.690Z,1558449250.690 [Micromodem](INFO): Starting
2019-05-21T14:34:10.869Z,1558449250.869 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:10.869Z,1558449250.869 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.877Z,1558449250.877 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-21T14:34:10.878Z,1558449250.878 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.878Z,1558449250.878 [logger](INFO): Join timeout helper Thread ID is 5219
2019-05-21T14:34:10.913Z,1558449250.913 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:10.913Z,1558449250.913 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.921Z,1558449250.921 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-21T14:34:10.922Z,1558449250.922 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.922Z,1558449250.922 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-21T14:34:10.922Z,1558449250.922 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:10.922Z,1558449250.922 [controlThread](INFO): Join timeout helper Thread ID is 5220
2019-05-21T14:34:11.085Z,1558449251.085 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:34:11.085Z,1558449251.085 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-21T14:34:11.085Z,1558449251.085 [AHRS_M2](INFO): Powering down
2019-05-21T14:34:11.159Z,1558449251.159 [DUSBL_Hydroid](INFO): Powering down
2019-05-21T14:34:11.253Z,1558449251.253 [Micromodem](INFO): uninitialize
2019-05-21T14:34:11.253Z,1558449251.253 [Micromodem](INFO): Powering down
2019-05-21T14:34:11.369Z,1558449251.369 [NAL9602](INFO): Powering down
2019-05-21T14:34:11.441Z,1558449251.441 [RDI_Pathfinder](INFO): Powering down
2019-05-21T14:34:11.443Z,1558449251.443 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-21T14:34:11.444Z,1558449251.444 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-21T14:34:11.444Z,1558449251.444 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-21T14:34:11.445Z,1558449251.445 [MissionManager](INFO): Uninitializing Mission Default
2019-05-21T14:34:11.447Z,1558449251.447 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-21T14:34:11.448Z,1558449251.448 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-21T14:34:11.448Z,1558449251.448 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-21T14:34:11.449Z,1558449251.449 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-21T14:34:11.449Z,1558449251.449 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-21T14:34:11.449Z,1558449251.449 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-21T14:34:11.449Z,1558449251.449 [BuoyancyServo](INFO): Powering down
2019-05-21T14:34:11.461Z,1558449251.461 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-21T14:34:11.461Z,1558449251.461 [ElevatorServo](INFO): Powering down
2019-05-21T14:34:11.462Z,1558449251.462 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-21T14:34:11.462Z,1558449251.462 [MassServo](INFO): Powering down
2019-05-21T14:34:11.463Z,1558449251.463 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-21T14:34:11.463Z,1558449251.463 [RudderServo](INFO): Powering down
2019-05-21T14:34:11.463Z,1558449251.463 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-21T14:34:11.464Z,1558449251.464 [ThrusterServo](INFO): Powering down
2019-05-21T14:34:11.464Z,1558449251.464 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-21T14:34:11.465Z,1558449251.465 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-21T14:34:11.465Z,1558449251.465 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-21T14:34:11.465Z,1558449251.465 [CBIT](DEBUG): Powering off loads.
2019-05-21T14:34:11.477Z,1558449251.477 [CBIT](DEBUG): Disabling WDT.
2019-05-21T14:34:11.489Z,1558449251.489 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-21T14:34:11.489Z,1558449251.489 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:11.542Z,1558449251.542 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:11.550Z,1558449251.550 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:11.707Z,1558449251.707 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:11.709Z,1558449251.709 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:11.764Z,1558449251.764 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:34:11.821Z,1558449251.821 [logger ThreadHandler](INFO): Thread cancelled.