2019-05-07T01:12:29.305Z,1557191549.305 [Supervisor](DEBUG): Initializing supervisor.
2019-05-07T01:12:29.308Z,1557191549.308 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-07T01:12:29.308Z,1557191549.308 [SyncHandler](INFO): Protected caller Thread ID is 1241
2019-05-07T01:12:29.309Z,1557191549.309 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-07T01:12:29.310Z,1557191549.310 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-07T01:12:29.311Z,1557191549.311 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1242
2019-05-07T01:12:29.313Z,1557191549.313 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-07T01:12:29.326Z,1557191549.326 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-07T01:12:29.327Z,1557191549.327 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-07T01:12:29.327Z,1557191549.327 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1243
2019-05-07T01:12:29.328Z,1557191549.328 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-07T01:12:29.329Z,1557191549.329 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-07T01:12:29.329Z,1557191549.329 [logger ThreadHandler](INFO): Protected caller Thread ID is 1244
2019-05-07T01:12:29.331Z,1557191549.331 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-07T01:12:29.332Z,1557191549.332 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-07T01:12:29.333Z,1557191549.333 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-07T01:12:29.759Z,1557191549.759 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-07T01:12:29.759Z,1557191549.759 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-07T01:12:29.857Z,1557191549.857 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-07T01:12:29.857Z,1557191549.857 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-07T01:12:30.184Z,1557191550.184 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-07T01:12:30.184Z,1557191550.184 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-07T01:12:30.330Z,1557191550.330 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-07T01:12:30.330Z,1557191550.330 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-07T01:12:30.523Z,1557191550.523 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-07T01:12:30.523Z,1557191550.523 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-07T01:12:30.982Z,1557191550.982 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-07T01:12:30.983Z,1557191550.983 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-07T01:12:31.194Z,1557191551.194 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-07T01:12:31.194Z,1557191551.194 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-07T01:12:31.340Z,1557191551.340 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-07T01:12:31.341Z,1557191551.341 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-07T01:12:31.536Z,1557191551.536 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-07T01:12:31.536Z,1557191551.536 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-07T01:12:31.632Z,1557191551.632 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-07T01:12:31.633Z,1557191551.633 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-07T01:12:31.963Z,1557191551.963 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-07T01:12:31.964Z,1557191551.964 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-07T01:12:32.173Z,1557191552.173 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-07T01:12:32.473Z,1557191552.473 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-07T01:12:32.474Z,1557191552.474 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-07T01:12:33.250Z,1557191553.250 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-07T01:12:33.250Z,1557191553.250 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-07T01:12:33.645Z,1557191553.645 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-07T01:12:33.647Z,1557191553.647 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-07T01:12:33.648Z,1557191553.648 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-07T01:12:33.857Z,1557191553.857 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-07T01:12:33.957Z,1557191553.957 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-07T01:12:34.055Z,1557191554.055 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-07T01:12:34.284Z,1557191554.284 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-07T01:12:34.284Z,1557191554.284 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-07T01:12:34.368Z,1557191554.368 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-07T01:12:34.461Z,1557191554.461 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-07T01:12:34.558Z,1557191554.558 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-07T01:12:34.641Z,1557191554.641 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-07T01:12:34.752Z,1557191554.752 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-07T01:12:34.930Z,1557191554.930 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-07T01:12:35.066Z,1557191555.066 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-07T01:12:35.066Z,1557191555.066 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-07T01:12:35.079Z,1557191555.079 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-07T01:12:35.474Z,1557191555.474 [AHRS_M2] Loaded
2019-05-07T01:12:35.474Z,1557191555.474 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-07T01:12:35.547Z,1557191555.547 [DataOverHttps] Loaded
2019-05-07T01:12:35.547Z,1557191555.547 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-07T01:12:35.549Z,1557191555.549 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-07T01:12:35.549Z,1557191555.549 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1323
2019-05-07T01:12:35.562Z,1557191555.562 [Depth_Keller] Loaded
2019-05-07T01:12:35.563Z,1557191555.563 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-07T01:12:35.568Z,1557191555.568 [DropWeight] Loaded
2019-05-07T01:12:35.568Z,1557191555.568 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-07T01:12:35.626Z,1557191555.626 [DUSBL_Hydroid] Loaded
2019-05-07T01:12:35.626Z,1557191555.626 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-07T01:12:35.667Z,1557191555.667 [Micromodem] Loaded
2019-05-07T01:12:35.667Z,1557191555.667 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-07T01:12:35.768Z,1557191555.768 [NAL9602] Loaded
2019-05-07T01:12:35.768Z,1557191555.768 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-07T01:12:35.784Z,1557191555.784 [Onboard] Loaded
2019-05-07T01:12:35.784Z,1557191555.784 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-07T01:12:35.790Z,1557191555.790 [PowerOnly] Loaded
2019-05-07T01:12:35.790Z,1557191555.790 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-07T01:12:35.797Z,1557191555.797 [Radio_Surface] Loaded
2019-05-07T01:12:35.797Z,1557191555.797 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-07T01:12:35.798Z,1557191555.798 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-07T01:12:35.799Z,1557191555.799 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1324
2019-05-07T01:12:35.844Z,1557191555.844 [RDI_Pathfinder] Loaded
2019-05-07T01:12:35.844Z,1557191555.844 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-07T01:12:37.688Z,1557191557.688 [BPC1] Loaded
2019-05-07T01:12:37.689Z,1557191557.689 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-07T01:12:37.689Z,1557191557.689 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-07T01:12:37.690Z,1557191557.690 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-07T01:12:37.703Z,1557191557.703 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-07T01:12:37.703Z,1557191557.703 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-07T01:12:37.812Z,1557191557.812 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-07T01:12:37.812Z,1557191557.812 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-07T01:12:37.833Z,1557191557.833 [NavChart] Loaded
2019-05-07T01:12:37.833Z,1557191557.833 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-07T01:12:37.837Z,1557191557.837 [UniversalFixResidualReporter] Loaded
2019-05-07T01:12:37.837Z,1557191557.837 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-07T01:12:37.838Z,1557191557.838 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-07T01:12:37.838Z,1557191557.838 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-07T01:12:37.950Z,1557191557.950 [BuoyancyServo] Loaded
2019-05-07T01:12:37.950Z,1557191557.950 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-07T01:12:37.966Z,1557191557.966 [ElevatorServo] Loaded
2019-05-07T01:12:37.966Z,1557191557.966 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-07T01:12:37.981Z,1557191557.981 [MassServo] Loaded
2019-05-07T01:12:37.981Z,1557191557.981 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-07T01:12:37.997Z,1557191557.997 [RudderServo] Loaded
2019-05-07T01:12:37.997Z,1557191557.997 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-07T01:12:38.012Z,1557191558.012 [ThrusterServo] Loaded
2019-05-07T01:12:38.012Z,1557191558.012 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-07T01:12:38.013Z,1557191558.013 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-07T01:12:38.013Z,1557191558.013 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-07T01:12:38.267Z,1557191558.267 [CTD_NeilBrown] Loaded
2019-05-07T01:12:38.268Z,1557191558.268 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-07T01:12:38.269Z,1557191558.269 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-07T01:12:38.269Z,1557191558.269 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1325
2019-05-07T01:12:38.314Z,1557191558.314 [WetLabsSeaOWL_UV_A] Loaded
2019-05-07T01:12:38.315Z,1557191558.315 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-07T01:12:38.316Z,1557191558.316 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-07T01:12:38.316Z,1557191558.316 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1326
2019-05-07T01:12:38.317Z,1557191558.317 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-07T01:12:38.317Z,1557191558.317 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-07T01:12:38.619Z,1557191558.619 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-07T01:12:38.619Z,1557191558.619 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-07T01:12:38.660Z,1557191558.660 [DepthRateCalculator] Loaded
2019-05-07T01:12:38.661Z,1557191558.661 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-07T01:12:38.666Z,1557191558.666 [PitchRateCalculator] Loaded
2019-05-07T01:12:38.667Z,1557191558.667 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-07T01:12:38.679Z,1557191558.679 [SpeedCalculator] Loaded
2019-05-07T01:12:38.680Z,1557191558.680 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-07T01:12:38.701Z,1557191558.701 [TempGradientCalculator] Loaded
2019-05-07T01:12:38.701Z,1557191558.701 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-07T01:12:38.707Z,1557191558.707 [YawRateCalculator] Loaded
2019-05-07T01:12:38.707Z,1557191558.707 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-07T01:12:38.749Z,1557191558.749 [ElevatorOffsetCalculator] Loaded
2019-05-07T01:12:38.749Z,1557191558.749 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-07T01:12:38.749Z,1557191558.749 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-07T01:12:38.750Z,1557191558.750 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-07T01:12:38.891Z,1557191558.891 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-07T01:12:38.913Z,1557191558.913 [SBIT] Loaded
2019-05-07T01:12:38.913Z,1557191558.913 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-07T01:12:38.914Z,1557191558.914 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-07T01:12:38.926Z,1557191558.926 [IBIT] Loaded
2019-05-07T01:12:38.926Z,1557191558.926 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-07T01:12:38.929Z,1557191558.929 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-07T01:12:39.070Z,1557191559.070 [CBIT] Loaded
2019-05-07T01:12:39.070Z,1557191559.070 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-07T01:12:39.071Z,1557191559.071 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-07T01:12:39.071Z,1557191559.071 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-07T01:12:39.143Z,1557191559.143 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-07T01:12:39.143Z,1557191559.143 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-07T01:12:39.245Z,1557191559.245 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-07T01:12:39.246Z,1557191559.246 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-07T01:12:39.314Z,1557191559.314 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-07T01:12:39.400Z,1557191559.400 [VerticalControl] Loaded
2019-05-07T01:12:39.400Z,1557191559.400 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-07T01:12:39.401Z,1557191559.401 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-07T01:12:39.460Z,1557191559.460 [HorizontalControl] Loaded
2019-05-07T01:12:39.460Z,1557191559.460 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-07T01:12:39.461Z,1557191559.461 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-07T01:12:39.463Z,1557191559.463 [SpeedControl] Loaded
2019-05-07T01:12:39.463Z,1557191559.463 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-07T01:12:39.464Z,1557191559.464 [LoopControl](DEBUG): Construct LoopControl.
2019-05-07T01:12:39.464Z,1557191559.464 [LoopControl] Loaded
2019-05-07T01:12:39.465Z,1557191559.465 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-07T01:12:39.465Z,1557191559.465 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-07T01:12:39.466Z,1557191559.466 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-07T01:12:39.493Z,1557191559.493 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-07T01:12:39.496Z,1557191559.496 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-07T01:12:39.497Z,1557191559.497 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-07T01:12:39.504Z,1557191559.504 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-07T01:12:39.505Z,1557191559.505 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-07T01:12:39.505Z,1557191559.505 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1327
2019-05-07T01:12:39.510Z,1557191559.510 [Supervisor](INFO): Main Thread ID is 802
2019-05-07T01:12:39.510Z,1557191559.510 [Supervisor](DEBUG): Running supervisor.
2019-05-07T01:12:39.510Z,1557191559.510 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1328
2019-05-07T01:12:39.513Z,1557191559.513 [controlThread ThreadHandler](INFO): Handler Thread ID is 1329
2019-05-07T01:12:39.513Z,1557191559.513 [controlThread](DEBUG): Initializing ControlThread
2019-05-07T01:12:39.522Z,1557191559.522 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-07T01:12:39.523Z,1557191559.523 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-07T01:12:39.524Z,1557191559.524 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-07T01:12:39.524Z,1557191559.524 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-07T01:12:39.524Z,1557191559.524 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-07T01:12:39.524Z,1557191559.524 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-07T01:12:39.525Z,1557191559.525 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-07T01:12:39.525Z,1557191559.525 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-07T01:12:39.526Z,1557191559.526 [SBIT](INFO): Initialize SBIT Component.
2019-05-07T01:12:39.526Z,1557191559.526 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-07T01:12:39.526Z,1557191559.526 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-07T01:12:39.527Z,1557191559.527 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-07T01:12:39.528Z,1557191559.528 [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-07T01:12:39.529Z,1557191559.529 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-07T01:12:39.530Z,1557191559.530 [IBIT](INFO): Initialize IBIT Component.
2019-05-07T01:12:39.531Z,1557191559.531 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-07T01:12:39.531Z,1557191559.531 [logger ThreadHandler](INFO): Handler Thread ID is 1330
2019-05-07T01:12:39.542Z,1557191559.542 [CBIT](DEBUG): Initialized mux pins.
2019-05-07T01:12:39.542Z,1557191559.542 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-07T01:12:39.551Z,1557191559.551 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1331
2019-05-07T01:12:39.552Z,1557191559.552 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-07T01:12:39.563Z,1557191559.563 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1332
2019-05-07T01:12:39.566Z,1557191559.566 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-07T01:12:39.566Z,1557191559.566 [CBIT](DEBUG): Initializing heartbeat.
2019-05-07T01:12:39.583Z,1557191559.583 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1333
2019-05-07T01:12:39.584Z,1557191559.583 [CTD_NeilBrown](INFO): Powering down
2019-05-07T01:12:39.619Z,1557191559.619 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1334
2019-05-07T01:12:39.619Z,1557191559.619 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T01:12:39.638Z,1557191559.638 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-07T01:12:39.638Z,1557191559.638 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-07T01:12:39.639Z,1557191559.639 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1335
2019-05-07T01:12:39.642Z,1557191559.642 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-07T01:12:39.642Z,1557191559.642 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-07T01:12:39.643Z,1557191559.643 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-07T01:12:39.643Z,1557191559.643 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-07T01:12:39.643Z,1557191559.643 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-07T01:12:39.643Z,1557191559.643 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-07T01:12:39.643Z,1557191559.643 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-07T01:12:39.644Z,1557191559.644 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-07T01:12:39.644Z,1557191559.644 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-07T01:12:39.644Z,1557191559.644 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-07T01:12:39.644Z,1557191559.644 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-07T01:12:39.644Z,1557191559.644 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-07T01:12:39.645Z,1557191559.645 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-07T01:12:39.645Z,1557191559.645 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-07T01:12:39.645Z,1557191559.645 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-07T01:12:39.645Z,1557191559.645 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-07T01:12:39.674Z,1557191559.674 [CBIT](DEBUG): Backplane powered.
2019-05-07T01:12:39.675Z,1557191559.675 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-07T01:12:39.676Z,1557191559.676 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-07T01:12:39.677Z,1557191559.677 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-07T01:12:39.677Z,1557191559.677 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-07T01:12:39.678Z,1557191559.678 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-07T01:12:39.688Z,1557191559.688 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T01:12:39.719Z,1557191559.719 [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-07T01:12:39.719Z,1557191559.719 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-07T01:12:39.790Z,1557191559.790 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-07T01:12:39.791Z,1557191559.791 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-07T01:12:39.793Z,1557191559.793 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T01:12:39.836Z,1557191559.836 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-07T01:12:39.839Z,1557191559.839 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-07T01:12:39.861Z,1557191559.861 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-07T01:12:39.864Z,1557191559.864 [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-07T01:12:39.874Z,1557191559.874 [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-07T01:12:39.886Z,1557191559.886 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-07T01:12:39.956Z,1557191559.956 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-07T01:12:39.957Z,1557191559.957 [DUSBL_Hydroid](INFO): Powering up
2019-05-07T01:12:39.957Z,1557191559.957 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-07T01:12:39.966Z,1557191559.966 [Radio_Surface](INFO): Powering up
2019-05-07T01:12:40.039Z,1557191560.039 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T01:12:40.065Z,1557191560.065 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:12:40.079Z,1557191560.079 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-07T01:12:40.080Z,1557191560.080 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:12:40.091Z,1557191560.091 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-07T01:12:40.091Z,1557191560.091 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:12:40.099Z,1557191560.099 [MassServo](DEBUG): Initializing MassServo.
2019-05-07T01:12:40.099Z,1557191560.099 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:12:40.107Z,1557191560.107 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T01:12:40.107Z,1557191560.107 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:12:40.115Z,1557191560.115 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-07T01:12:40.304Z,1557191560.304 [Micromodem](INFO): Powering up
2019-05-07T01:12:40.304Z,1557191560.304 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-07T01:12:40.342Z,1557191560.342 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T01:12:41.038Z,1557191561.038 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-07T01:12:41.038Z,1557191561.038 [RudderServo](FAULT): Rudder failed to initialize
2019-05-07T01:12:41.039Z,1557191561.039 [RudderServo] Communications Fault, FailCount= 1
2019-05-07T01:12:41.039Z,1557191561.039 [RudderServo](ERROR): Communications Fault
2019-05-07T01:12:41.150Z,1557191561.150 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-07T01:12:41.311Z,1557191561.311 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T01:12:41.312Z,1557191561.312 [RudderServo](INFO): Powering down
2019-05-07T01:12:41.994Z,1557191561.994 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:12:42.115Z,1557191562.115 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T01:12:42.120Z,1557191562.120 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-07T01:12:42.120Z,1557191562.120 [RudderServo] No Fault, FailCount= 1
2019-05-07T01:12:53.350Z,1557191573.350 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T01:12:54.250Z,1557191574.250 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-05-07T01:12:54.250Z,1557191574.250 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-05-07T01:12:54.251Z,1557191574.251 [RDI_Pathfinder](ERROR): Communications Fault
2019-05-07T01:12:54.251Z,1557191574.251 [RDI_Pathfinder](ERROR): Failed to parse:
2019-05-07T01:12:54.307Z,1557191574.307 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-05-07T01:12:54.618Z,1557191574.618 [RDI_Pathfinder](INFO): Powering down
2019-05-07T01:12:55.443Z,1557191575.443 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-05-07T01:12:55.443Z,1557191575.443 [RDI_Pathfinder] No Fault, FailCount= 1
2019-05-07T01:12:58.172Z,1557191578.172 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-07T01:13:05.849Z,1557191585.849 [NAL9602](INFO): Powering up NAL9602
2019-05-07T01:13:07.464Z,1557191587.464 [Micromodem](ERROR): Response from modem unexpected: $CADQF,195,1*5D

2019-05-07T01:13:07.865Z,1557191587.865 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T01:13:08.273Z,1557191588.273 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507011306.194143,05,191,10,0101,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,195,0.00,-999,9760,4000*51

2019-05-07T01:13:08.702Z,1557191588.702 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T01:13:16.753Z,1557191596.753 [NAL9602](INFO): NAL9602 initialized
2019-05-07T01:13:17.574Z,1557191597.574 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:13:18.016Z,1557191598.016 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-07T01:13:18.016Z,1557191598.016 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,     ,        +0.00,        +0.00,   0.00,  9.00
2019-05-07T01:13:24.088Z,1557191604.088 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-07T01:13:24.096Z,1557191604.096 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-07T01:13:34.818Z,1557191614.818 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.022678
CHAN A1 (24V): -0.026254
CHAN A2 (12V): -0.006512
CHAN A3 (5V): -0.002048
CHAN B0 (3.3V): -0.000227
CHAN B1 (3.15aV): 0.000230
CHAN B2 (3.15bV): 0.000555
CHAN B3 (GND): 0.001994
OPEN: 0.006418
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-07T01:13:43.017Z,1557191623.017 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T01:14:17.476Z,1557191657.476 [SBIT](IMPORTANT): SBIT PASSED
2019-05-07T01:14:17.564Z,1557191657.564 [CommandLine](IMPORTANT): got command configSet list
2019-05-07T01:14:17.564Z,1557191657.564 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-07T01:14:17.565Z,1557191657.565 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-07T01:14:17.565Z,1557191657.565 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-07T01:14:17.565Z,1557191657.565 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-07T01:14:17.565Z,1557191657.565 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-07T01:14:17.565Z,1557191657.565 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-07T01:14:17.566Z,1557191657.566 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-07T01:14:17.884Z,1557191657.884 [MissionManager](IMPORTANT): Started mission Startup
2019-05-07T01:14:17.885Z,1557191657.885 [Startup] Running Loop=1
2019-05-07T01:14:17.885Z,1557191657.885 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-07T01:14:17.885Z,1557191657.885 [Startup:A.GoToSurface] Running Loop=1
2019-05-07T01:14:17.885Z,1557191657.885 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T01:14:17.886Z,1557191657.886 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T01:14:17.890Z,1557191657.890 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T01:14:17.891Z,1557191657.891 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T01:14:17.891Z,1557191657.891 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T01:14:17.892Z,1557191657.892 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T01:14:17.893Z,1557191657.893 [Startup:StartupSatComms] Running Loop=1
2019-05-07T01:14:17.893Z,1557191657.893 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-07T01:14:17.893Z,1557191657.893 [Startup:StartupSatComms:A] Running Loop=1
2019-05-07T01:14:18.261Z,1557191658.261 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-07T01:14:50.072Z,1557191690.072 [CommandLine](IMPORTANT): got command show stack
2019-05-07T01:14:50.072Z,1557191690.072 [CommandLine](IMPORTANT): Behavior Stack:

2019-05-07T01:14:50.073Z,1557191690.073 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-05-07T01:14:50.073Z,1557191690.073 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:A
2019-05-07T01:15:05.689Z,1557191705.689 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004951
2019-05-07T01:15:18.053Z,1557191718.053 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-07T01:14:17.9Z
2019-05-07T01:15:18.053Z,1557191718.053 [Startup:StartupSatComms:A] Stopped
2019-05-07T01:15:18.053Z,1557191718.053 [Startup:StartupSatComms:B] Running Loop=1
2019-05-07T01:15:18.452Z,1557191718.452 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T01:15:20.085Z,1557191720.085 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-05-07T01:15:23.618Z,1557191723.618 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190506T201918/Courier0160.lzma
2019-05-07T01:15:24.424Z,1557191724.424 [DataOverHttps](INFO): Moved sent file to Logs/20190506T201918/Courier0160.lzma.bak
2019-05-07T01:15:24.425Z,1557191724.425 [DataOverHttps](INFO): SBD MOMSN=10947466
2019-05-07T01:15:39.887Z,1557191739.887 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-07T01:15:39.887Z,1557191739.887 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T01:15:39.901Z,1557191739.901 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T01:15:40.288Z,1557191740.288 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T01:15:40.288Z,1557191740.288 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-07T01:15:41.834Z,1557191741.834 [DataOverHttps](INFO): Sending 261 bytes from file Logs/20190506T201918/Express0161.lzma
2019-05-07T01:15:42.647Z,1557191742.647 [DataOverHttps](INFO): Moved sent file to Logs/20190506T201918/Express0161.lzma.bak
2019-05-07T01:15:42.648Z,1557191742.648 [DataOverHttps](INFO): SBD MOMSN=10947468
2019-05-07T01:15:59.884Z,1557191759.884 [DataOverHttps](INFO): Sending 1376 bytes from file Logs/20190507T011229/Express0001.lzma
2019-05-07T01:16:00.688Z,1557191760.688 [DataOverHttps](INFO): Moved sent file to Logs/20190507T011229/Express0001.lzma.bak
2019-05-07T01:16:00.688Z,1557191760.688 [DataOverHttps](INFO): SBD MOMSN=10947471
2019-05-07T01:16:01.742Z,1557191761.742 [Startup:StartupSatComms:B] Stopped
2019-05-07T01:16:01.746Z,1557191761.746 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-07T01:16:01.746Z,1557191761.746 [Startup:StartupSatComms] Stopped
2019-05-07T01:16:01.747Z,1557191761.747 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-07T01:16:01.747Z,1557191761.747 [Startup](INFO): Completed Startup
2019-05-07T01:16:01.747Z,1557191761.747 [MissionManager](INFO): Startup is completed.
2019-05-07T01:16:01.748Z,1557191761.748 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-07T01:16:01.748Z,1557191761.748 [Startup] Stopped
2019-05-07T01:16:01.748Z,1557191761.748 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-07T01:16:01.748Z,1557191761.748 [Startup:A.GoToSurface] Stopped
2019-05-07T01:16:01.748Z,1557191761.748 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T01:16:02.100Z,1557191762.100 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T01:16:02.100Z,1557191762.100 [Default] Running Loop=1
2019-05-07T01:16:02.100Z,1557191762.100 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T01:16:02.100Z,1557191762.100 [Default:B.GoToSurface] Running Loop=1
2019-05-07T01:16:02.100Z,1557191762.100 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T01:16:02.100Z,1557191762.100 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T01:16:02.101Z,1557191762.101 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T01:16:02.101Z,1557191762.101 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T01:16:02.101Z,1557191762.101 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T01:16:02.102Z,1557191762.102 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T01:16:02.106Z,1557191762.106 [Default:A.Wait] Running Loop=1
2019-05-07T01:16:02.106Z,1557191762.106 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:16:15.454Z,1557191775.454 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T01:16:15.454Z,1557191775.454 [Default:A.Wait] Stopped
2019-05-07T01:16:15.454Z,1557191775.454 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:16:15.852Z,1557191775.852 [Default:CheckIn] Running Loop=1
2019-05-07T01:16:15.852Z,1557191775.852 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:16:15.852Z,1557191775.852 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:16:16.228Z,1557191776.228 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-07T01:16:16.822Z,1557191776.822 [CommandLine](IMPORTANT): got command show variable range
2019-05-07T01:16:16.825Z,1557191776.825 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-07T01:16:16.942Z,1557191776.942 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-07T01:16:16.943Z,1557191776.943 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-07T01:16:16.961Z,1557191776.961 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-07T01:16:16.963Z,1557191776.963 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-07T01:16:16.963Z,1557191776.963 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-07T01:16:16.966Z,1557191776.966 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-07T01:16:16.967Z,1557191776.967 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-07T01:16:16.967Z,1557191776.967 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-07T01:16:16.968Z,1557191776.968 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-07T01:16:29.452Z,1557191789.452 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-07T01:16:32.904Z,1557191792.904 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T01:16:32.904Z,1557191792.904 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T01:16:32.956Z,1557191792.956 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T01:16:32.959Z,1557191792.959 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T01:16:32.963Z,1557191792.963 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T01:16:32.967Z,1557191792.967 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T01:16:32.970Z,1557191792.970 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T01:16:32.973Z,1557191792.973 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T01:16:32.982Z,1557191792.982 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T01:16:32.991Z,1557191792.991 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T01:16:32.994Z,1557191792.994 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

    <Description>
        This mission is requests a DUSBL arming.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="NumberOfRequests"><Description>
        Number of pings to requst.
    </Description><Units:count/><Value>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>   

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    <ReadData>
        <When>
            <Arg Name="EnabledDUSBL"/>
        </When>
            <Universal:acoustic_contact_range/>
            <Universal:acoustic_contact_direction_vehicle_frame/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

        <Sequence Repeat="NumberOfRequests"/>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.transponderCode/><Arg Name="TransponderCode"/></Assign>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.pingRequested/><Arg Name="NumberOfPings"/></Assign>
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:second/><Value>10</Value></Setting>
          </Guidance:Wait>
      </Aggregate>    
</Mission>


2019-05-07T01:16:32.997Z,1557191792.997 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T01:16:33.191Z,1557191793.191 [Default] Stopped
2019-05-07T01:16:33.191Z,1557191793.191 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T01:16:33.191Z,1557191793.191 [Default:B.GoToSurface] Stopped
2019-05-07T01:16:33.191Z,1557191793.191 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T01:16:33.191Z,1557191793.191 [Default:CheckIn] Stopped
2019-05-07T01:16:33.191Z,1557191793.191 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:16:33.192Z,1557191793.192 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:16:33.192Z,1557191793.192 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T01:16:33.192Z,1557191793.192 [DUSBL] Running Loop=1
2019-05-07T01:16:33.192Z,1557191793.192 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T01:16:33.192Z,1557191793.192 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T01:16:33.192Z,1557191793.192 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:C] Running Loop=1
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T01:16:33.193Z,1557191793.193 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:16:33.194Z,1557191793.194 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:16:33.194Z,1557191793.194 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:16:33.195Z,1557191793.195 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T01:16:33.196Z,1557191793.196 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T01:16:33.196Z,1557191793.196 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T01:16:33.196Z,1557191793.196 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T01:16:34.780Z,1557191794.780 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:16:34.780Z,1557191794.780 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:16:34.781Z,1557191794.781 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:16:34.782Z,1557191794.782 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:35.184Z,1557191795.184 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:35.184Z,1557191795.184 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T01:16:35.184Z,1557191795.184 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-07T01:16:35.185Z,1557191795.185 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T01:16:35.598Z,1557191795.598 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:35.992Z,1557191795.992 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:35.992Z,1557191795.992 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:16:35.992Z,1557191795.992 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:16:36.395Z,1557191796.395 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:36.811Z,1557191796.811 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:37.204Z,1557191797.204 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:37.620Z,1557191797.620 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:38.016Z,1557191798.016 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:38.424Z,1557191798.424 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:38.824Z,1557191798.824 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:39.228Z,1557191799.228 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:39.632Z,1557191799.632 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:40.042Z,1557191800.042 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.261561
2019-05-07T01:16:40.042Z,1557191800.042 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:16:40.043Z,1557191800.043 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:16:40.043Z,1557191800.043 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:16:40.044Z,1557191800.044 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:40.440Z,1557191800.440 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:40.440Z,1557191800.440 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T01:16:40.440Z,1557191800.440 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-07T01:16:40.441Z,1557191800.441 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T01:16:40.844Z,1557191800.844 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:41.248Z,1557191801.248 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:41.248Z,1557191801.248 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:16:41.248Z,1557191801.248 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:16:41.648Z,1557191801.648 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:42.056Z,1557191802.056 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:42.460Z,1557191802.460 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:42.860Z,1557191802.860 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:43.272Z,1557191803.272 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:43.307Z,1557191803.307 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T01:16:43.307Z,1557191803.307 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T01:16:43.307Z,1557191803.307 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:16:43.308Z,1557191803.308 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T01:16:43.308Z,1557191803.308 [DUSBL:RequestRepeater] Stopped
2019-05-07T01:16:43.308Z,1557191803.308 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T01:16:43.308Z,1557191803.308 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T01:16:43.308Z,1557191803.308 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T01:16:43.309Z,1557191803.309 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T01:16:43.309Z,1557191803.309 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T01:16:43.309Z,1557191803.309 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T01:16:43.309Z,1557191803.309 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:16:43.309Z,1557191803.309 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:16:43.309Z,1557191803.309 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T01:16:43.309Z,1557191803.309 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:16:43.684Z,1557191803.684 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:44.076Z,1557191804.076 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:44.476Z,1557191804.476 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:44.883Z,1557191804.883 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:45.294Z,1557191805.294 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.251049
2019-05-07T01:16:45.295Z,1557191805.295 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:16:45.295Z,1557191805.295 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:16:45.295Z,1557191805.295 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:16:45.295Z,1557191805.295 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:45.692Z,1557191805.692 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:45.692Z,1557191805.692 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T01:16:45.692Z,1557191805.692 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-07T01:16:45.693Z,1557191805.693 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T01:16:46.095Z,1557191806.095 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:46.496Z,1557191806.496 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:46.496Z,1557191806.496 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:16:46.496Z,1557191806.496 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:16:46.900Z,1557191806.900 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:47.312Z,1557191807.312 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:47.719Z,1557191807.719 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:48.112Z,1557191808.112 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:48.516Z,1557191808.516 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:48.924Z,1557191808.924 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:49.324Z,1557191809.324 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:49.748Z,1557191809.747 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:50.132Z,1557191810.132 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:50.551Z,1557191810.551 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.255259
2019-05-07T01:16:50.552Z,1557191810.552 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:16:50.552Z,1557191810.552 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:16:50.554Z,1557191810.554 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:16:50.554Z,1557191810.554 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:50.939Z,1557191810.939 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:50.940Z,1557191810.940 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T01:16:50.940Z,1557191810.940 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-07T01:16:50.941Z,1557191810.941 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T01:16:51.353Z,1557191811.353 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:51.752Z,1557191811.752 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:51.753Z,1557191811.753 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:16:51.753Z,1557191811.753 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:16:52.160Z,1557191812.160 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:52.560Z,1557191812.560 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:52.960Z,1557191812.960 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:53.372Z,1557191813.372 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:53.776Z,1557191813.776 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:53.906Z,1557191813.906 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T01:16:53.906Z,1557191813.906 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T01:16:53.906Z,1557191813.906 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater] Stopped
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T01:16:53.907Z,1557191813.907 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:16:53.908Z,1557191813.908 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:16:53.908Z,1557191813.908 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T01:16:53.908Z,1557191813.908 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:16:54.176Z,1557191814.176 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:54.580Z,1557191814.580 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:54.980Z,1557191814.980 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:55.388Z,1557191815.388 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:55.806Z,1557191815.806 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.252859
2019-05-07T01:16:55.806Z,1557191815.806 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:16:55.807Z,1557191815.807 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:16:55.807Z,1557191815.807 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:16:55.808Z,1557191815.808 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:56.196Z,1557191816.196 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:56.196Z,1557191816.196 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T01:16:56.197Z,1557191816.197 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-07T01:16:56.197Z,1557191816.197 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T01:16:56.600Z,1557191816.600 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:57.004Z,1557191817.004 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:57.004Z,1557191817.004 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:16:57.004Z,1557191817.004 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:16:57.408Z,1557191817.408 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:57.808Z,1557191817.808 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:58.219Z,1557191818.219 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:58.616Z,1557191818.616 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:59.020Z,1557191819.020 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:59.428Z,1557191819.428 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:16:59.828Z,1557191819.828 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:17:00.241Z,1557191820.241 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:17:00.642Z,1557191820.642 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:17:01.012Z,1557191821.012 [CommandLine](IMPORTANT): got command stop
2019-05-07T01:17:01.012Z,1557191821.012 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-07T01:17:01.013Z,1557191821.013 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-07T01:17:01.063Z,1557191821.063 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.255200
2019-05-07T01:17:01.063Z,1557191821.063 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:17:01.063Z,1557191821.063 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:17:01.064Z,1557191821.064 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:17:01.066Z,1557191821.066 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-07T01:17:01.105Z,1557191821.105 [MissionManager](INFO): MissionManager is completed.
2019-05-07T01:17:01.105Z,1557191821.105 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL] Stopped
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL:A.Pitch] Stopped
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL:B.SetSpeed] Stopped
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL:C] Stopped
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL:RequestRepeater] Stopped
2019-05-07T01:17:01.105Z,1557191821.105 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T01:17:01.106Z,1557191821.106 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T01:17:01.106Z,1557191821.106 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T01:17:01.106Z,1557191821.106 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T01:17:01.106Z,1557191821.106 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:17:01.446Z,1557191821.446 [NAL9602](INFO): SBD MO Status=0, MOMSN=3824, MT Status=0, MTMSN=0
2019-05-07T01:17:01.446Z,1557191821.446 [NAL9602](INFO): No messages in MT queue
2019-05-07T01:17:01.482Z,1557191821.482 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T01:17:01.482Z,1557191821.482 [Default] Running Loop=1
2019-05-07T01:17:01.482Z,1557191821.482 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T01:17:01.483Z,1557191821.483 [Default:B.GoToSurface] Running Loop=1
2019-05-07T01:17:01.483Z,1557191821.483 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T01:17:01.483Z,1557191821.483 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T01:17:01.483Z,1557191821.483 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T01:17:01.484Z,1557191821.484 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T01:17:01.484Z,1557191821.484 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T01:17:01.484Z,1557191821.484 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T01:17:01.484Z,1557191821.484 [Default:A.Wait] Running Loop=1
2019-05-07T01:17:01.485Z,1557191821.485 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:17:02.266Z,1557191822.266 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:17:02.679Z,1557191822.679 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,011535.00,A,3648.17277,N,12147.27861,W,0.214,0.00,070519,,,A*74
2019-05-07T01:17:02.689Z,1557191822.689 [NAL9602](INFO): GPS fix at 20190507T011535: (36.802880, -121.787977)
2019-05-07T01:17:14.833Z,1557191834.833 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T01:17:14.833Z,1557191834.833 [Default:A.Wait] Stopped
2019-05-07T01:17:14.833Z,1557191834.833 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:17:15.247Z,1557191835.247 [Default:CheckIn] Running Loop=1
2019-05-07T01:17:15.247Z,1557191835.247 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:17:15.247Z,1557191835.247 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:17:16.819Z,1557191836.819 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:17:17.210Z,1557191837.210 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,011549.00,A,3648.17275,N,12147.27773,W,0.136,0.00,070519,,,A*72
2019-05-07T01:17:17.212Z,1557191837.212 [NAL9602](INFO): GPS fix at 20190507T011549: (36.802879, -121.787962)
2019-05-07T01:17:17.241Z,1557191837.241 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:17:17.241Z,1557191837.241 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:17:17.658Z,1557191837.658 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T01:17:23.751Z,1557191843.751 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190507T011229/Courier0004.lzma
2019-05-07T01:17:24.548Z,1557191844.548 [DataOverHttps](INFO): Moved sent file to Logs/20190507T011229/Courier0004.lzma.bak
2019-05-07T01:17:24.548Z,1557191844.548 [DataOverHttps](INFO): SBD MOMSN=10947502
2019-05-07T01:17:37.356Z,1557191857.356 [DataOverHttps](INFO): Sending 774 bytes from file Logs/20190507T011229/Express0005.lzma
2019-05-07T01:17:38.160Z,1557191858.160 [DataOverHttps](INFO): Moved sent file to Logs/20190507T011229/Express0005.lzma.bak
2019-05-07T01:17:38.160Z,1557191858.160 [DataOverHttps](INFO): SBD MOMSN=10947505
2019-05-07T01:17:38.889Z,1557191858.889 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:17:38.889Z,1557191858.889 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:17:38.890Z,1557191858.890 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:17:49.357Z,1557191869.357 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T01:20:09.162Z,1557192009.162 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-07T01:20:09.165Z,1557192009.165 [BPC1](INFO): Received data from all battery sticks.
2019-05-07T01:20:19.689Z,1557192019.689 [RDI_Pathfinder](ERROR): Failed to parse:
68,-32768,-32768,V
2019-05-07T01:20:38.678Z,1557192038.678 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T01:20:38.699Z,1557192038.699 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,1822 -00,1448.9,  0
2019-05-07T01:21:06.135Z,1557192066.135 [RDI_Pathfinder](ERROR): Failed to parse:
:B,-32768,-32768,V
2019-05-07T01:22:39.482Z,1557192159.482 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T01:22:39.482Z,1557192159.482 [Default:CheckIn:C.Wait] Stopped
2019-05-07T01:22:39.482Z,1557192159.482 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:22:39.483Z,1557192159.483 [Default:CheckIn:D] Running Loop=1
2019-05-07T01:22:39.896Z,1557192159.896 [Default:CheckIn:D] Stopped
2019-05-07T01:22:39.896Z,1557192159.896 [Default:CheckIn:E] Running Loop=1
2019-05-07T01:22:40.298Z,1557192160.298 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.640236 min 
2019-05-07T01:22:40.298Z,1557192160.298 [Default:CheckIn:E] Stopped
2019-05-07T01:22:40.298Z,1557192160.298 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T01:22:40.298Z,1557192160.298 [Default:CheckIn] Stopped
2019-05-07T01:22:40.298Z,1557192160.298 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:22:40.299Z,1557192160.299 [Default:CheckIn](INFO): Running loop #2
2019-05-07T01:22:40.299Z,1557192160.299 [Default:CheckIn] Running Loop=2
2019-05-07T01:22:40.299Z,1557192160.299 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:22:40.299Z,1557192160.299 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:22:41.898Z,1557192161.898 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:22:42.299Z,1557192162.299 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,012115.00,A,3648.16512,N,12147.28242,W,0.117,169.77,070519,,,A*7E
2019-05-07T01:22:42.301Z,1557192162.301 [NAL9602](INFO): GPS fix at 20190507T012115: (36.802752, -121.788040)
2019-05-07T01:22:42.324Z,1557192162.324 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:22:42.324Z,1557192162.324 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:22:48.234Z,1557192168.234 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190507T011229/Courier0007.lzma
2019-05-07T01:22:49.040Z,1557192169.040 [DataOverHttps](INFO): Moved sent file to Logs/20190507T011229/Courier0007.lzma.bak
2019-05-07T01:22:49.040Z,1557192169.040 [DataOverHttps](INFO): SBD MOMSN=10947591
2019-05-07T01:23:00.948Z,1557192180.948 [DataOverHttps](INFO): Sending 743 bytes from file Logs/20190507T011229/Express0008.lzma
2019-05-07T01:23:01.752Z,1557192181.752 [DataOverHttps](INFO): Moved sent file to Logs/20190507T011229/Express0008.lzma.bak
2019-05-07T01:23:01.752Z,1557192181.752 [DataOverHttps](INFO): SBD MOMSN=10947594
2019-05-07T01:23:02.517Z,1557192182.517 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:23:02.517Z,1557192182.517 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:23:02.517Z,1557192182.517 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:23:56.512Z,1557192236.512 [CommandLine](IMPORTANT): got command restart application
2019-05-07T01:23:57.518Z,1557192237.518 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:57.519Z,1557192237.519 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:57.594Z,1557192237.594 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-07T01:23:57.594Z,1557192237.594 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:57.595Z,1557192237.595 [CommandLine](INFO): Join timeout helper Thread ID is 1371
2019-05-07T01:23:57.596Z,1557192237.596 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-07T01:23:57.596Z,1557192237.596 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:57.596Z,1557192237.596 [NavChartDb](INFO): Join timeout helper Thread ID is 1372
2019-05-07T01:23:57.675Z,1557192237.675 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:57.676Z,1557192237.676 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:57.694Z,1557192237.694 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-07T01:23:57.694Z,1557192237.694 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:57.695Z,1557192237.695 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1373
2019-05-07T01:23:58.026Z,1557192238.026 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:58.027Z,1557192238.027 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T01:23:58.027Z,1557192238.027 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.034Z,1557192238.034 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-07T01:23:58.034Z,1557192238.034 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.035Z,1557192238.035 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1374
2019-05-07T01:23:58.179Z,1557192238.179 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:58.179Z,1557192238.179 [CTD_NeilBrown](INFO): Powering down
2019-05-07T01:23:58.190Z,1557192238.190 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.198Z,1557192238.198 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-07T01:23:58.198Z,1557192238.198 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.199Z,1557192238.199 [Radio_Surface](INFO): Join timeout helper Thread ID is 1375
2019-05-07T01:23:58.418Z,1557192238.418 [Radio_Surface](INFO): Powering down
2019-05-07T01:23:58.419Z,1557192238.419 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:58.420Z,1557192238.420 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.439Z,1557192238.439 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-07T01:23:58.439Z,1557192238.439 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.440Z,1557192238.440 [DataOverHttps](INFO): Join timeout helper Thread ID is 1376
2019-05-07T01:23:58.494Z,1557192238.494 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:58.495Z,1557192238.495 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.503Z,1557192238.503 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-07T01:23:58.503Z,1557192238.503 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.503Z,1557192238.503 [logger](INFO): Join timeout helper Thread ID is 1377
2019-05-07T01:23:58.574Z,1557192238.574 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:58.575Z,1557192238.575 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.583Z,1557192238.583 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-07T01:23:58.583Z,1557192238.583 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.583Z,1557192238.583 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-07T01:23:58.583Z,1557192238.583 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:58.584Z,1557192238.584 [controlThread](INFO): Join timeout helper Thread ID is 1378
2019-05-07T01:23:58.626Z,1557192238.626 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T01:23:58.627Z,1557192238.627 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-07T01:23:58.627Z,1557192238.627 [AHRS_M2](INFO): Powering down
2019-05-07T01:23:58.699Z,1557192238.699 [DUSBL_Hydroid](INFO): Powering down
2019-05-07T01:23:58.771Z,1557192238.771 [Micromodem](INFO): Powering down
2019-05-07T01:23:58.867Z,1557192238.867 [NAL9602](INFO): Powering down
2019-05-07T01:23:58.938Z,1557192238.938 [RDI_Pathfinder](INFO): Powering down
2019-05-07T01:23:58.940Z,1557192238.940 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-07T01:23:58.940Z,1557192238.940 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-07T01:23:58.941Z,1557192238.941 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-07T01:23:58.941Z,1557192238.941 [MissionManager](INFO): Uninitializing Mission Default
2019-05-07T01:23:58.941Z,1557192238.941 [Default] Stopped
2019-05-07T01:23:58.942Z,1557192238.942 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T01:23:58.942Z,1557192238.942 [Default:B.GoToSurface] Stopped
2019-05-07T01:23:58.942Z,1557192238.942 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T01:23:58.942Z,1557192238.942 [Default:CheckIn] Stopped
2019-05-07T01:23:58.942Z,1557192238.942 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:23:58.942Z,1557192238.942 [Default:CheckIn:C.Wait] Stopped
2019-05-07T01:23:58.942Z,1557192238.942 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:23:58.945Z,1557192238.945 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-07T01:23:58.945Z,1557192238.945 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-07T01:23:58.945Z,1557192238.945 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-07T01:23:58.945Z,1557192238.945 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-07T01:23:58.946Z,1557192238.946 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-07T01:23:58.946Z,1557192238.946 [BuoyancyServo](INFO): Powering down
2019-05-07T01:23:58.958Z,1557192238.958 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-07T01:23:58.958Z,1557192238.958 [ElevatorServo](INFO): Powering down
2019-05-07T01:23:58.959Z,1557192238.959 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-07T01:23:58.959Z,1557192238.959 [MassServo](INFO): Powering down
2019-05-07T01:23:58.960Z,1557192238.960 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T01:23:58.960Z,1557192238.960 [RudderServo](INFO): Powering down
2019-05-07T01:23:58.961Z,1557192238.961 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-07T01:23:58.961Z,1557192238.961 [ThrusterServo](INFO): Powering down
2019-05-07T01:23:58.962Z,1557192238.962 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-07T01:23:58.962Z,1557192238.962 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-07T01:23:58.963Z,1557192238.963 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-07T01:23:58.963Z,1557192238.963 [CBIT](DEBUG): Powering off loads.
2019-05-07T01:23:58.974Z,1557192238.974 [CBIT](DEBUG): Disabling WDT.
2019-05-07T01:23:58.986Z,1557192238.986 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-07T01:23:58.987Z,1557192238.987 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:59.039Z,1557192239.039 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:59.048Z,1557192239.048 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:59.092Z,1557192239.092 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:59.094Z,1557192239.094 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:59.148Z,1557192239.148 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T01:23:59.218Z,1557192239.218 [logger ThreadHandler](INFO): Thread cancelled.