2019-07-09T17:36:12.870Z,1562693772.870 [Supervisor](DEBUG): Initializing supervisor.
2019-07-09T17:36:12.873Z,1562693772.873 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-09T17:36:12.874Z,1562693772.874 [SyncHandler](INFO): Protected caller Thread ID is 5306
2019-07-09T17:36:12.874Z,1562693772.874 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-09T17:36:12.875Z,1562693772.875 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-09T17:36:12.876Z,1562693772.876 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5307
2019-07-09T17:36:12.879Z,1562693772.879 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-09T17:36:12.891Z,1562693772.891 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-09T17:36:12.892Z,1562693772.892 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-09T17:36:12.892Z,1562693772.892 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5308
2019-07-09T17:36:12.893Z,1562693772.893 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-09T17:36:12.894Z,1562693772.894 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-09T17:36:12.894Z,1562693772.894 [logger ThreadHandler](INFO): Protected caller Thread ID is 5309
2019-07-09T17:36:12.896Z,1562693772.896 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-09T17:36:12.897Z,1562693772.897 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-09T17:36:12.898Z,1562693772.898 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-09T17:36:13.413Z,1562693773.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-09T17:36:13.414Z,1562693773.414 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-09T17:36:13.514Z,1562693773.514 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-09T17:36:13.514Z,1562693773.514 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-09T17:36:13.835Z,1562693773.835 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-09T17:36:13.835Z,1562693773.835 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-09T17:36:13.978Z,1562693773.978 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-09T17:36:13.978Z,1562693773.978 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-09T17:36:14.173Z,1562693774.173 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-09T17:36:14.173Z,1562693774.173 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-09T17:36:14.627Z,1562693774.627 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-09T17:36:14.628Z,1562693774.628 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-09T17:36:14.837Z,1562693774.837 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-09T17:36:14.838Z,1562693774.838 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-09T17:36:14.984Z,1562693774.984 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-09T17:36:14.985Z,1562693774.985 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-09T17:36:15.182Z,1562693775.182 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-09T17:36:15.183Z,1562693775.183 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-09T17:36:15.281Z,1562693775.281 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-09T17:36:15.282Z,1562693775.282 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-09T17:36:15.585Z,1562693775.585 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-09T17:36:15.585Z,1562693775.585 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-09T17:36:15.668Z,1562693775.668 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-09T17:36:15.773Z,1562693775.773 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-09T17:36:15.773Z,1562693775.773 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-09T17:36:16.370Z,1562693776.370 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-09T17:36:16.370Z,1562693776.370 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-09T17:36:16.764Z,1562693776.764 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-09T17:36:16.766Z,1562693776.766 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-07-09T17:36:16.767Z,1562693776.767 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-07-09T17:36:16.979Z,1562693776.979 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-07-09T17:36:17.082Z,1562693777.082 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-07-09T17:36:17.183Z,1562693777.183 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-07-09T17:36:17.414Z,1562693777.414 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-09T17:36:17.414Z,1562693777.414 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-07-09T17:36:17.501Z,1562693777.501 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-07-09T17:36:17.596Z,1562693777.596 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-07-09T17:36:17.695Z,1562693777.695 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-07-09T17:36:17.780Z,1562693777.780 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-07-09T17:36:17.889Z,1562693777.889 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-07-09T17:36:18.070Z,1562693778.070 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-07-09T17:36:18.203Z,1562693778.203 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-07-09T17:36:18.203Z,1562693778.203 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-07-09T17:36:18.207Z,1562693778.207 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-09T17:36:18.717Z,1562693778.717 [AHRS_M2] Loaded
2019-07-09T17:36:18.717Z,1562693778.717 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-07-09T17:36:18.893Z,1562693778.893 [DataOverHttps] Loaded
2019-07-09T17:36:18.893Z,1562693778.893 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-09T17:36:18.894Z,1562693778.894 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407654E0
2019-07-09T17:36:18.894Z,1562693778.894 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5388
2019-07-09T17:36:18.908Z,1562693778.908 [Depth_Keller] Loaded
2019-07-09T17:36:18.908Z,1562693778.908 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-09T17:36:19.086Z,1562693779.086 [DUSBL_Hydroid] Loaded
2019-07-09T17:36:19.087Z,1562693779.087 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-07-09T17:36:19.218Z,1562693779.218 [Micromodem] Loaded
2019-07-09T17:36:19.219Z,1562693779.219 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-07-09T17:36:19.401Z,1562693779.401 [NAL9602] Loaded
2019-07-09T17:36:19.402Z,1562693779.402 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-09T17:36:19.442Z,1562693779.442 [Onboard] Loaded
2019-07-09T17:36:19.442Z,1562693779.442 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-09T17:36:19.496Z,1562693779.496 [PowerOnly] Loaded
2019-07-09T17:36:19.496Z,1562693779.496 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-07-09T17:36:19.531Z,1562693779.531 [Radio_Surface] Loaded
2019-07-09T17:36:19.531Z,1562693779.531 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-09T17:36:19.532Z,1562693779.532 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407954E0
2019-07-09T17:36:19.533Z,1562693779.533 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5389
2019-07-09T17:36:19.646Z,1562693779.646 [RDI_Pathfinder] Loaded
2019-07-09T17:36:19.646Z,1562693779.646 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-07-09T17:36:21.187Z,1562693781.187 [BPC1] Loaded
2019-07-09T17:36:21.188Z,1562693781.188 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-09T17:36:21.188Z,1562693781.188 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-09T17:36:21.189Z,1562693781.189 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-09T17:36:21.212Z,1562693781.212 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-09T17:36:21.213Z,1562693781.213 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-09T17:36:21.339Z,1562693781.339 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-09T17:36:21.339Z,1562693781.339 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-09T17:36:21.360Z,1562693781.360 [NavChart] Loaded
2019-07-09T17:36:21.360Z,1562693781.360 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-09T17:36:21.364Z,1562693781.364 [UniversalFixResidualReporter] Loaded
2019-07-09T17:36:21.364Z,1562693781.364 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-09T17:36:21.365Z,1562693781.365 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-09T17:36:21.365Z,1562693781.365 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-09T17:36:21.498Z,1562693781.498 [BuoyancyServo] Loaded
2019-07-09T17:36:21.499Z,1562693781.499 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-09T17:36:21.514Z,1562693781.514 [ElevatorServo] Loaded
2019-07-09T17:36:21.514Z,1562693781.514 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-09T17:36:21.529Z,1562693781.529 [MassServo] Loaded
2019-07-09T17:36:21.529Z,1562693781.529 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-09T17:36:21.544Z,1562693781.544 [RudderServo] Loaded
2019-07-09T17:36:21.545Z,1562693781.545 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-09T17:36:21.559Z,1562693781.559 [ThrusterServo] Loaded
2019-07-09T17:36:21.559Z,1562693781.559 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-09T17:36:21.560Z,1562693781.560 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-09T17:36:21.560Z,1562693781.560 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-09T17:36:21.892Z,1562693781.892 [CTD_NeilBrown] Loaded
2019-07-09T17:36:21.892Z,1562693781.892 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-07-09T17:36:21.893Z,1562693781.893 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E04E0
2019-07-09T17:36:21.894Z,1562693781.894 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5390
2019-07-09T17:36:21.939Z,1562693781.939 [WetLabsSeaOWL_UV_A] Loaded
2019-07-09T17:36:21.939Z,1562693781.939 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-07-09T17:36:21.940Z,1562693781.940 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409104E0
2019-07-09T17:36:21.941Z,1562693781.941 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 5391
2019-07-09T17:36:21.941Z,1562693781.941 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-09T17:36:21.942Z,1562693781.942 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-09T17:36:22.298Z,1562693782.298 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-09T17:36:22.299Z,1562693782.299 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-09T17:36:22.356Z,1562693782.356 [DepthRateCalculator] Loaded
2019-07-09T17:36:22.356Z,1562693782.356 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-09T17:36:22.362Z,1562693782.362 [PitchRateCalculator] Loaded
2019-07-09T17:36:22.362Z,1562693782.362 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-09T17:36:22.375Z,1562693782.375 [SpeedCalculator] Loaded
2019-07-09T17:36:22.375Z,1562693782.375 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-09T17:36:22.396Z,1562693782.396 [TempGradientCalculator] Loaded
2019-07-09T17:36:22.396Z,1562693782.396 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-09T17:36:22.402Z,1562693782.402 [YawRateCalculator] Loaded
2019-07-09T17:36:22.402Z,1562693782.402 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-09T17:36:22.444Z,1562693782.444 [ElevatorOffsetCalculator] Loaded
2019-07-09T17:36:22.444Z,1562693782.444 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-09T17:36:22.444Z,1562693782.444 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-09T17:36:22.445Z,1562693782.445 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-09T17:36:22.613Z,1562693782.613 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-09T17:36:22.635Z,1562693782.635 [SBIT] Loaded
2019-07-09T17:36:22.635Z,1562693782.635 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-09T17:36:22.636Z,1562693782.636 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-09T17:36:22.647Z,1562693782.647 [IBIT] Loaded
2019-07-09T17:36:22.647Z,1562693782.647 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-09T17:36:22.650Z,1562693782.650 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-09T17:36:22.792Z,1562693782.792 [CBIT] Loaded
2019-07-09T17:36:22.793Z,1562693782.793 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-09T17:36:22.793Z,1562693782.793 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-09T17:36:22.794Z,1562693782.794 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-09T17:36:22.919Z,1562693782.919 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-09T17:36:22.919Z,1562693782.919 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-09T17:36:23.047Z,1562693783.047 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-09T17:36:23.048Z,1562693783.048 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-09T17:36:23.138Z,1562693783.138 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-09T17:36:23.223Z,1562693783.223 [VerticalControl] Loaded
2019-07-09T17:36:23.223Z,1562693783.223 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-09T17:36:23.224Z,1562693783.224 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-09T17:36:23.281Z,1562693783.281 [HorizontalControl] Loaded
2019-07-09T17:36:23.281Z,1562693783.281 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-09T17:36:23.282Z,1562693783.282 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-09T17:36:23.283Z,1562693783.283 [SpeedControl] Loaded
2019-07-09T17:36:23.284Z,1562693783.284 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-09T17:36:23.284Z,1562693783.284 [LoopControl](DEBUG): Construct LoopControl.
2019-07-09T17:36:23.285Z,1562693783.285 [LoopControl] Loaded
2019-07-09T17:36:23.285Z,1562693783.285 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-09T17:36:23.285Z,1562693783.285 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-09T17:36:23.286Z,1562693783.286 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-09T17:36:23.335Z,1562693783.335 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-09T17:36:23.338Z,1562693783.338 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-09T17:36:23.339Z,1562693783.339 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-09T17:36:23.346Z,1562693783.346 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-09T17:36:23.347Z,1562693783.347 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AEC4E0
2019-07-09T17:36:23.348Z,1562693783.348 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5392
2019-07-09T17:36:23.352Z,1562693783.352 [Supervisor](INFO): Main Thread ID is 4931
2019-07-09T17:36:23.352Z,1562693783.352 [Supervisor](DEBUG): Running supervisor.
2019-07-09T17:36:23.353Z,1562693783.353 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5393
2019-07-09T17:36:23.355Z,1562693783.355 [controlThread ThreadHandler](INFO): Handler Thread ID is 5394
2019-07-09T17:36:23.356Z,1562693783.356 [controlThread](DEBUG): Initializing ControlThread
2019-07-09T17:36:23.363Z,1562693783.363 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-09T17:36:23.364Z,1562693783.364 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-09T17:36:23.365Z,1562693783.365 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-09T17:36:23.366Z,1562693783.366 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-09T17:36:23.366Z,1562693783.366 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-09T17:36:23.366Z,1562693783.366 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-09T17:36:23.367Z,1562693783.367 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-09T17:36:23.367Z,1562693783.367 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-09T17:36:23.367Z,1562693783.367 [SBIT](INFO): Initialize SBIT Component.
2019-07-09T17:36:23.368Z,1562693783.368 [SBIT](IMPORTANT): git: 2019-07-01-1-gec4d815
2019-07-09T17:36:23.368Z,1562693783.368 [SBIT](INFO): git hash: ec4d81507ac98db5eafe8caa852a083fe7be759d
2019-07-09T17:36:23.369Z,1562693783.369 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-09T17:36:23.370Z,1562693783.370 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-07-09T17:36:23.371Z,1562693783.371 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-07-09T17:36:23.371Z,1562693783.371 [IBIT](INFO): Initialize IBIT Component.
2019-07-09T17:36:23.372Z,1562693783.372 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-09T17:36:23.373Z,1562693783.373 [logger ThreadHandler](INFO): Handler Thread ID is 5395
2019-07-09T17:36:23.385Z,1562693783.385 [CBIT](DEBUG): Initialized mux pins.
2019-07-09T17:36:23.385Z,1562693783.385 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-09T17:36:23.393Z,1562693783.393 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5396
2019-07-09T17:36:23.394Z,1562693783.394 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-09T17:36:23.405Z,1562693783.405 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5397
2019-07-09T17:36:23.409Z,1562693783.409 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-09T17:36:23.409Z,1562693783.409 [CBIT](DEBUG): Initializing heartbeat.
2019-07-09T17:36:23.425Z,1562693783.425 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5398
2019-07-09T17:36:23.426Z,1562693783.426 [CTD_NeilBrown](INFO): Powering down
2019-07-09T17:36:23.461Z,1562693783.461 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 5399
2019-07-09T17:36:23.462Z,1562693783.462 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-09T17:36:23.481Z,1562693783.481 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-09T17:36:23.481Z,1562693783.481 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-09T17:36:23.482Z,1562693783.482 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5400
2019-07-09T17:36:23.486Z,1562693783.486 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-09T17:36:23.486Z,1562693783.486 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-09T17:36:23.487Z,1562693783.487 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-09T17:36:23.487Z,1562693783.487 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-09T17:36:23.487Z,1562693783.487 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-09T17:36:23.487Z,1562693783.487 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-09T17:36:23.487Z,1562693783.487 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-09T17:36:23.488Z,1562693783.488 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-09T17:36:23.488Z,1562693783.488 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-09T17:36:23.488Z,1562693783.488 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-09T17:36:23.488Z,1562693783.488 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-09T17:36:23.488Z,1562693783.488 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-09T17:36:23.489Z,1562693783.489 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-09T17:36:23.489Z,1562693783.489 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-09T17:36:23.489Z,1562693783.489 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-09T17:36:23.489Z,1562693783.489 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-09T17:36:23.517Z,1562693783.517 [CBIT](DEBUG): Backplane powered.
2019-07-09T17:36:23.517Z,1562693783.517 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-09T17:36:23.519Z,1562693783.519 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-09T17:36:23.520Z,1562693783.520 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-09T17:36:23.520Z,1562693783.520 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-09T17:36:23.521Z,1562693783.521 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-09T17:36:23.536Z,1562693783.536 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-09T17:36:23.564Z,1562693783.564 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2019-07-09T17:36:23.564Z,1562693783.564 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-09T17:36:23.650Z,1562693783.650 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-09T17:36:23.651Z,1562693783.651 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-09T17:36:23.661Z,1562693783.661 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-09T17:36:23.687Z,1562693783.687 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-09T17:36:23.690Z,1562693783.690 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-09T17:36:23.709Z,1562693783.709 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-09T17:36:23.712Z,1562693783.712 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2019-07-09T17:36:23.730Z,1562693783.730 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-09T17:36:23.751Z,1562693783.751 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-07-09T17:36:23.809Z,1562693783.809 [Radio_Surface](INFO): Powering up
2019-07-09T17:36:23.891Z,1562693783.891 [DUSBL_Hydroid](INFO): Powering up
2019-07-09T17:36:23.891Z,1562693783.891 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-07-09T17:36:23.983Z,1562693783.983 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-09T17:36:23.989Z,1562693783.989 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-09T17:36:23.990Z,1562693783.990 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-09T17:36:23.997Z,1562693783.997 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-09T17:36:23.998Z,1562693783.998 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-09T17:36:24.005Z,1562693784.005 [MassServo](DEBUG): Initializing MassServo.
2019-07-09T17:36:24.006Z,1562693784.006 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-09T17:36:24.013Z,1562693784.013 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-09T17:36:24.014Z,1562693784.014 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-09T17:36:24.021Z,1562693784.021 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-09T17:36:24.156Z,1562693784.156 [Micromodem](INFO): Powering up
2019-07-09T17:36:24.157Z,1562693784.157 [Micromodem](DEBUG): Initializing Micromodem.
2019-07-09T17:36:24.885Z,1562693784.885 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-09T17:36:24.885Z,1562693784.885 [RudderServo](FAULT): Rudder failed to initialize
2019-07-09T17:36:24.885Z,1562693784.885 [RudderServo] Communications Fault, FailCount= 1
2019-07-09T17:36:24.885Z,1562693784.885 [RudderServo](ERROR): Communications Fault
2019-07-09T17:36:24.996Z,1562693784.996 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-09T17:36:25.158Z,1562693785.158 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-09T17:36:25.158Z,1562693785.158 [RudderServo](INFO): Powering down
2019-07-09T17:36:25.841Z,1562693785.841 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-09T17:36:25.962Z,1562693785.962 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-09T17:36:25.966Z,1562693785.966 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-09T17:36:25.966Z,1562693785.966 [RudderServo] No Fault, FailCount= 1
2019-07-09T17:36:29.084Z,1562693789.084 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-07-09T17:36:31.183Z,1562693791.183 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-07-09T17:36:31.184Z,1562693791.184 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-07-09T17:36:31.587Z,1562693791.587 [Micromodem](INFO): Nmea in: $CATMG,2019-07-09T17:36:30Z,RTC,RTC*7A

2019-07-09T17:36:31.587Z,1562693791.587 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-07-09T17:36:30Z,RTC,RTC*7A

2019-07-09T17:36:31.979Z,1562693791.979 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-07-09T17:36:31.979Z,1562693791.979 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-07-09T17:36:32.388Z,1562693792.388 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-07-09T17:36:32.388Z,1562693792.388 [Micromodem](INFO): Nmea out: $CCCFG,nav.nst,1*4D

2019-07-09T17:36:32.775Z,1562693792.775 [Micromodem](INFO): Nmea in: $CACFG,nav.nst,1*4F

2019-07-09T17:36:32.775Z,1562693792.775 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-07-09T17:36:33.187Z,1562693793.187 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-07-09T17:36:33.187Z,1562693793.187 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-07-09T17:36:33.579Z,1562693793.579 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-07-09T17:36:33.579Z,1562693793.579 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-07-09T17:36:33.979Z,1562693793.979 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-07-09T17:36:33.979Z,1562693793.979 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-07-09T17:36:34.399Z,1562693794.399 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-07-09T17:36:34.399Z,1562693794.399 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-07-09T17:36:34.787Z,1562693794.787 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-07-09T17:36:34.788Z,1562693794.788 [Micromodem](INFO): Nmea out: $CCCLK,2019,07,09,17,36,35*45

2019-07-09T17:36:35.187Z,1562693795.187 [Micromodem](INFO): Nmea in: $CACLK,2019,7,9,17,36,35*47

2019-07-09T17:36:35.999Z,1562693795.999 [Micromodem](INFO): Nmea in: $CATMS,0,2019-07-09T17:36:36Z*74

2019-07-09T17:36:36.010Z,1562693796.010 [Micromodem](INFO): Nmea in: $CATMG,2019-07-09T17:36:36Z,USER_CMD,RTC*3D

2019-07-09T17:36:37.243Z,1562693797.243 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-07-09T17:36:42.070Z,1562693802.070 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-07-09T17:36:49.731Z,1562693809.731 [NAL9602](INFO): Powering up NAL9602
2019-07-09T17:36:51.799Z,1562693811.799 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-09T17:36:51.807Z,1562693811.807 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-09T17:37:00.743Z,1562693820.743 [NAL9602](INFO): NAL9602 initialized
2019-07-09T17:37:01.561Z,1562693821.561 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:37:02.869Z,1562693822.869 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.009417
CHAN A1 (24V): -0.027145
CHAN A2 (12V): -0.008995
CHAN A3 (5V): -0.002116
CHAN B0 (3.3V): 0.000011
CHAN B1 (3.15aV): -0.000108
CHAN B2 (3.15bV): -0.000023
CHAN B3 (GND): 0.002039
OPEN: 0.005423
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-09T17:37:11.063Z,1562693831.063 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-07-09T17:37:11.063Z,1562693831.063 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,     ,        +0.00,        +0.00,   0.00, 34.00
2019-07-09T17:37:45.061Z,1562693865.061 [SBIT](IMPORTANT): SBIT PASSED
2019-07-09T17:37:45.162Z,1562693865.162 [CommandLine](IMPORTANT): got command configSet list
2019-07-09T17:37:45.162Z,1562693865.162 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-09T17:37:45.163Z,1562693865.163 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-07-09T17:37:45.506Z,1562693865.506 [MissionManager](IMPORTANT): Started mission Startup
2019-07-09T17:37:45.506Z,1562693865.506 [Startup] Running Loop=1
2019-07-09T17:37:45.506Z,1562693865.506 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-09T17:37:45.506Z,1562693865.506 [Startup:A.GoToSurface] Running Loop=1
2019-07-09T17:37:45.506Z,1562693865.506 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-09T17:37:45.507Z,1562693865.507 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-09T17:37:45.507Z,1562693865.507 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-09T17:37:45.508Z,1562693865.508 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-09T17:37:45.508Z,1562693865.508 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-09T17:37:45.513Z,1562693865.513 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-09T17:37:45.514Z,1562693865.514 [Startup:StartupSatComms] Running Loop=1
2019-07-09T17:37:45.515Z,1562693865.515 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-09T17:37:45.515Z,1562693865.515 [Startup:StartupSatComms:A] Running Loop=1
2019-07-09T17:37:45.882Z,1562693865.882 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-09T17:38:36.461Z,1562693916.461 [CommandLine](IMPORTANT): got command show stack
2019-07-09T17:38:36.462Z,1562693916.462 [CommandLine](IMPORTANT): Behavior Stack:

2019-07-09T17:38:36.462Z,1562693916.462 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-07-09T17:38:36.462Z,1562693916.462 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:A
2019-07-09T17:38:45.660Z,1562693925.660 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-09T17:37:45.5Z
2019-07-09T17:38:45.660Z,1562693925.660 [Startup:StartupSatComms:A] Stopped
2019-07-09T17:38:45.660Z,1562693925.660 [Startup:StartupSatComms:B] Running Loop=1
2019-07-09T17:38:46.047Z,1562693926.047 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-09T17:38:49.307Z,1562693929.307 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005055
2019-07-09T17:38:56.729Z,1562693936.729 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190709T170238/Express0014.lzma
2019-07-09T17:38:57.534Z,1562693937.534 [DataOverHttps](INFO): Moved sent file to Logs/20190709T170238/Express0014.lzma.bak
2019-07-09T17:38:57.535Z,1562693937.535 [DataOverHttps](INFO): SBD MOMSN=11436120
2019-07-09T17:39:11.767Z,1562693951.767 [DataOverHttps](INFO): Sending 739 bytes from file Logs/20190709T173612/Express0001.lzma
2019-07-09T17:39:12.566Z,1562693952.566 [DataOverHttps](INFO): Moved sent file to Logs/20190709T173612/Express0001.lzma.bak
2019-07-09T17:39:12.566Z,1562693952.566 [DataOverHttps](INFO): SBD MOMSN=11436127
2019-07-09T17:39:14.750Z,1562693954.750 [Startup:StartupSatComms:B] Stopped
2019-07-09T17:39:14.750Z,1562693954.750 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-09T17:39:14.750Z,1562693954.750 [Startup:StartupSatComms] Stopped
2019-07-09T17:39:14.750Z,1562693954.750 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-09T17:39:14.751Z,1562693954.751 [Startup](INFO): Completed Startup
2019-07-09T17:39:14.751Z,1562693954.751 [MissionManager](INFO): Startup is completed.
2019-07-09T17:39:14.751Z,1562693954.751 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-09T17:39:14.751Z,1562693954.751 [Startup] Stopped
2019-07-09T17:39:14.752Z,1562693954.752 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-09T17:39:14.752Z,1562693954.752 [Startup:A.GoToSurface] Stopped
2019-07-09T17:39:14.752Z,1562693954.752 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-09T17:39:15.146Z,1562693955.146 [MissionManager](IMPORTANT): Started mission Default
2019-07-09T17:39:15.146Z,1562693955.146 [Default] Running Loop=1
2019-07-09T17:39:15.146Z,1562693955.146 [Default](DEBUG): Aggregate::initialize Default
2019-07-09T17:39:15.146Z,1562693955.146 [Default:B.GoToSurface] Running Loop=1
2019-07-09T17:39:15.146Z,1562693955.146 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-09T17:39:15.147Z,1562693955.147 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-09T17:39:15.147Z,1562693955.147 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-09T17:39:15.147Z,1562693955.147 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-09T17:39:15.148Z,1562693955.148 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-09T17:39:15.148Z,1562693955.148 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-09T17:39:15.148Z,1562693955.148 [Default:A.Wait] Running Loop=1
2019-07-09T17:39:15.148Z,1562693955.148 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:39:23.609Z,1562693963.609 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-09T17:39:23.609Z,1562693963.609 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-09T17:39:23.623Z,1562693963.623 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-09T17:39:24.021Z,1562693964.021 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-09T17:39:24.021Z,1562693964.021 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-09T17:39:28.466Z,1562693968.466 [Default:A.Wait](INFO): Done Waiting.
2019-07-09T17:39:28.466Z,1562693968.466 [Default:A.Wait] Stopped
2019-07-09T17:39:28.466Z,1562693968.466 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:39:28.871Z,1562693968.871 [Default:CheckIn] Running Loop=1
2019-07-09T17:39:28.871Z,1562693968.871 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-09T17:39:28.871Z,1562693968.871 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-09T17:39:29.297Z,1562693969.297 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-09T17:40:49.279Z,1562694049.279 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:40:49.279Z,1562694049.279 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:40:49.342Z,1562694049.342 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-07-09T17:40:49.346Z,1562694049.346 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-07-09T17:40:49.357Z,1562694049.357 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 2.000000 s
2019-07-09T17:40:49.361Z,1562694049.361 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-07-09T17:40:49.364Z,1562694049.364 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-07-09T17:40:49.374Z,1562694049.374 [DUSBL:A.Pitch](DEBUG): Construct.
2019-07-09T17:40:49.396Z,1562694049.396 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-07-09T17:40:49.558Z,1562694049.558 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-07-09T17:40:49.586Z,1562694049.586 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><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>

    
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>
        
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-07-09T17:40:49.589Z,1562694049.589 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:40:49.672Z,1562694049.672 [Default] Stopped
2019-07-09T17:40:49.673Z,1562694049.673 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-09T17:40:49.673Z,1562694049.673 [Default:B.GoToSurface] Stopped
2019-07-09T17:40:49.673Z,1562694049.673 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-09T17:40:49.673Z,1562694049.673 [Default:CheckIn] Stopped
2019-07-09T17:40:49.673Z,1562694049.673 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-09T17:40:49.673Z,1562694049.673 [Default:CheckIn:Read_GPS] Stopped
2019-07-09T17:40:49.673Z,1562694049.673 [MissionManager](IMPORTANT): Started mission DUSBL
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL] Running Loop=1
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL:C.] Running Loop=1
2019-07-09T17:40:49.674Z,1562694049.674 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-07-09T17:40:49.675Z,1562694049.675 [DUSBL:RequestRepeater] Running Loop=1
2019-07-09T17:40:49.675Z,1562694049.675 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-07-09T17:40:49.675Z,1562694049.675 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-07-09T17:40:49.675Z,1562694049.675 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:40:49.675Z,1562694049.675 [DUSBL:C.] Running Loop=1
2019-07-09T17:40:49.676Z,1562694049.676 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:40:49.676Z,1562694049.676 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:40:51.710Z,1562694051.710 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:40:52.468Z,1562694052.468 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-09T17:40:52.876Z,1562694052.876 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-09T17:40:53.730Z,1562694053.730 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:40:55.707Z,1562694055.707 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-09T17:40:55.760Z,1562694055.760 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:40:56.508Z,1562694056.508 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-09T17:40:56.886Z,1562694056.886 [CommandLine](IMPORTANT): got command stop
2019-07-09T17:40:56.887Z,1562694056.887 [CommandLine](IMPORTANT): Scheduling is paused
2019-07-09T17:40:56.887Z,1562694056.887 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-09T17:40:56.916Z,1562694056.916 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-09T17:40:56.966Z,1562694056.966 [MissionManager](INFO): MissionManager is completed.
2019-07-09T17:40:56.966Z,1562694056.966 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL] Stopped
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:A.Pitch] Stopped
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:B.SetSpeed] Stopped
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:C.] Stopped
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:RequestRepeater] Stopped
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-07-09T17:40:56.967Z,1562694056.967 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:40:57.359Z,1562694057.359 [MissionManager](IMPORTANT): Started mission Default
2019-07-09T17:40:57.359Z,1562694057.359 [Default] Running Loop=1
2019-07-09T17:40:57.360Z,1562694057.360 [Default](DEBUG): Aggregate::initialize Default
2019-07-09T17:40:57.360Z,1562694057.360 [Default:B.GoToSurface] Running Loop=1
2019-07-09T17:40:57.360Z,1562694057.360 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-09T17:40:57.360Z,1562694057.360 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-09T17:40:57.360Z,1562694057.360 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-09T17:40:57.361Z,1562694057.361 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-09T17:40:57.361Z,1562694057.361 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-09T17:40:57.361Z,1562694057.361 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-09T17:40:57.362Z,1562694057.362 [Default:A.Wait] Running Loop=1
2019-07-09T17:40:57.362Z,1562694057.362 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:41:10.670Z,1562694070.670 [Default:A.Wait](INFO): Done Waiting.
2019-07-09T17:41:10.670Z,1562694070.670 [Default:A.Wait] Stopped
2019-07-09T17:41:10.670Z,1562694070.670 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:41:11.091Z,1562694071.091 [Default:CheckIn] Running Loop=1
2019-07-09T17:41:11.091Z,1562694071.091 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-09T17:41:11.091Z,1562694071.091 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-09T17:41:18.903Z,1562694078.903 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.verbosity 3.000000 count
2019-07-09T17:41:25.110Z,1562694085.110 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:41:25.111Z,1562694085.111 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:41:25.134Z,1562694085.134 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-07-09T17:41:25.136Z,1562694085.136 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-07-09T17:41:25.139Z,1562694085.139 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 2.000000 s
2019-07-09T17:41:25.141Z,1562694085.141 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-07-09T17:41:25.143Z,1562694085.143 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-07-09T17:41:25.144Z,1562694085.144 [DUSBL:A.Pitch](DEBUG): Construct.
2019-07-09T17:41:25.148Z,1562694085.148 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-07-09T17:41:25.160Z,1562694085.160 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-07-09T17:41:25.164Z,1562694085.164 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><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>

    
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>
        
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-07-09T17:41:25.166Z,1562694085.166 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:41:25.248Z,1562694085.248 [Default] Stopped
2019-07-09T17:41:25.253Z,1562694085.253 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-09T17:41:25.253Z,1562694085.253 [Default:B.GoToSurface] Stopped
2019-07-09T17:41:25.253Z,1562694085.253 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-09T17:41:25.253Z,1562694085.253 [Default:CheckIn] Stopped
2019-07-09T17:41:25.253Z,1562694085.253 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-09T17:41:25.253Z,1562694085.253 [Default:CheckIn:Read_GPS] Stopped
2019-07-09T17:41:25.253Z,1562694085.253 [MissionManager](IMPORTANT): Started mission DUSBL
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL] Running Loop=1
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL:C.] Running Loop=1
2019-07-09T17:41:25.254Z,1562694085.254 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-07-09T17:41:25.255Z,1562694085.255 [DUSBL:RequestRepeater] Running Loop=1
2019-07-09T17:41:25.255Z,1562694085.255 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-07-09T17:41:25.255Z,1562694085.255 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-07-09T17:41:25.255Z,1562694085.255 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:41:25.255Z,1562694085.255 [DUSBL:C.] Running Loop=1
2019-07-09T17:41:25.256Z,1562694085.256 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:41:25.256Z,1562694085.256 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:41:27.646Z,1562694087.646 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:41:28.431Z,1562694088.431 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-09T17:41:28.828Z,1562694088.828 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-09T17:41:29.666Z,1562694089.666 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:41:31.598Z,1562694091.598 [CommandLine](IMPORTANT): got command stop
2019-07-09T17:41:31.599Z,1562694091.599 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-09T17:41:31.673Z,1562694091.673 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-09T17:41:31.697Z,1562694091.697 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:41:31.697Z,1562694091.697 [MissionManager](INFO): MissionManager is completed.
2019-07-09T17:41:31.698Z,1562694091.698 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL] Stopped
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:A.Pitch] Stopped
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:B.SetSpeed] Stopped
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:C.] Stopped
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:RequestRepeater] Stopped
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-07-09T17:41:31.698Z,1562694091.698 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:41:32.111Z,1562694092.111 [MissionManager](IMPORTANT): Started mission Default
2019-07-09T17:41:32.111Z,1562694092.111 [Default] Running Loop=1
2019-07-09T17:41:32.111Z,1562694092.111 [Default](DEBUG): Aggregate::initialize Default
2019-07-09T17:41:32.111Z,1562694092.111 [Default:B.GoToSurface] Running Loop=1
2019-07-09T17:41:32.112Z,1562694092.112 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-09T17:41:32.112Z,1562694092.112 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-09T17:41:32.112Z,1562694092.112 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-09T17:41:32.112Z,1562694092.112 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-09T17:41:32.113Z,1562694092.113 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-09T17:41:32.113Z,1562694092.113 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-09T17:41:32.114Z,1562694092.114 [Default:A.Wait] Running Loop=1
2019-07-09T17:41:32.114Z,1562694092.114 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:41:45.447Z,1562694105.447 [Default:A.Wait](INFO): Done Waiting.
2019-07-09T17:41:45.447Z,1562694105.447 [Default:A.Wait] Stopped
2019-07-09T17:41:45.447Z,1562694105.447 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:41:45.818Z,1562694105.818 [Default:CheckIn] Running Loop=1
2019-07-09T17:41:45.818Z,1562694105.818 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-09T17:41:45.818Z,1562694105.818 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-09T17:41:46.210Z,1562694106.210 [CommandLine](IMPORTANT): got command failComponent hardware DUSBL_Hydroid
2019-07-09T17:41:46.210Z,1562694106.210 [DUSBL_Hydroid] Hardware Fault, FailCount= 1
2019-07-09T17:41:46.210Z,1562694106.210 [DUSBL_Hydroid](ERROR): Hardware Fault
2019-07-09T17:41:46.210Z,1562694106.210 [CommandLine](IMPORTANT): DUSBL_Hydroid failureMode is Hardware Fault
2019-07-09T17:41:46.216Z,1562694106.216 [DUSBL_Hydroid](INFO): Powering down
2019-07-09T17:41:46.347Z,1562694106.347 [CBIT](ERROR): Hardware Fault in component: DUSBL_Hydroid
2019-07-09T17:41:47.229Z,1562694107.229 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-07-09T17:41:47.229Z,1562694107.229 [DUSBL_Hydroid] No Fault, FailCount= 1
2019-07-09T17:41:49.434Z,1562694109.434 [DUSBL_Hydroid](INFO): Powering up
2019-07-09T17:41:49.434Z,1562694109.434 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-07-09T17:42:01.462Z,1562694121.462 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:42:01.463Z,1562694121.463 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:42:01.491Z,1562694121.491 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-07-09T17:42:01.493Z,1562694121.493 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-07-09T17:42:01.495Z,1562694121.495 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 2.000000 s
2019-07-09T17:42:01.498Z,1562694121.498 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-07-09T17:42:01.499Z,1562694121.499 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-07-09T17:42:01.500Z,1562694121.500 [DUSBL:A.Pitch](DEBUG): Construct.
2019-07-09T17:42:01.505Z,1562694121.505 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-07-09T17:42:01.517Z,1562694121.517 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-07-09T17:42:01.521Z,1562694121.521 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><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>

    
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>
        
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-07-09T17:42:01.523Z,1562694121.523 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:42:01.618Z,1562694121.618 [Default] Stopped
2019-07-09T17:42:01.618Z,1562694121.618 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-09T17:42:01.618Z,1562694121.618 [Default:B.GoToSurface] Stopped
2019-07-09T17:42:01.618Z,1562694121.618 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-09T17:42:01.618Z,1562694121.618 [Default:CheckIn] Stopped
2019-07-09T17:42:01.618Z,1562694121.618 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-09T17:42:01.618Z,1562694121.618 [Default:CheckIn:Read_GPS] Stopped
2019-07-09T17:42:01.618Z,1562694121.618 [MissionManager](IMPORTANT): Started mission DUSBL
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL] Running Loop=1
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL:C.] Running Loop=1
2019-07-09T17:42:01.619Z,1562694121.619 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-07-09T17:42:01.620Z,1562694121.620 [DUSBL:RequestRepeater] Running Loop=1
2019-07-09T17:42:01.620Z,1562694121.620 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-07-09T17:42:01.620Z,1562694121.620 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-07-09T17:42:01.620Z,1562694121.620 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:42:01.620Z,1562694121.620 [DUSBL:C.] Running Loop=1
2019-07-09T17:42:01.625Z,1562694121.625 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:42:01.625Z,1562694121.625 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:42:03.975Z,1562694123.975 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-09T17:42:04.002Z,1562694124.002 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:42:04.801Z,1562694124.801 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:06.016Z,1562694126.016 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:42:07.614Z,1562694127.614 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-07-09T17:42:07.637Z,1562694127.637 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:08.088Z,1562694128.088 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:42:08.422Z,1562694128.422 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-07-09T17:42:08.422Z,1562694128.422 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-07-09T17:42:08.422Z,1562694128.422 [DUSBL_Hydroid](INFO): Arming DUSBL detection threshold 32
2019-07-09T17:42:08.423Z,1562694128.423 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-07-09T17:42:08.822Z,1562694128.822 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
O
2019-07-09T17:42:08.822Z,1562694128.822 [DUSBL_Hydroid](INFO): Command Ack
2019-07-09T17:42:08.822Z,1562694128.822 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-07-09T17:42:08.824Z,1562694128.824 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-09T17:42:09.234Z,1562694129.234 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-09T17:42:10.457Z,1562694130.457 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:10.486Z,1562694130.486 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:42:12.067Z,1562694132.067 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,63,E4
2019-07-09T17:42:12.067Z,1562694132.067 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
2019-07-09T17:42:12.067Z,1562694132.067 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-09T17:42:12.498Z,1562694132.498 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:42:12.862Z,1562694132.862 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-07-09T17:42:12.862Z,1562694132.862 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-07-09T17:42:12.862Z,1562694132.862 [DUSBL_Hydroid](INFO): Arming DUSBL detection threshold 32
2019-07-09T17:42:12.863Z,1562694132.863 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-07-09T17:42:13.266Z,1562694133.266 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
80,80,63,E4
2019-07-09T17:42:13.266Z,1562694133.266 [DUSBL_Hydroid](INFO): Command Ack
2019-07-09T17:42:13.267Z,1562694133.267 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-07-09T17:42:13.268Z,1562694133.268 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-09T17:42:13.676Z,1562694133.676 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-09T17:42:13.701Z,1562694133.701 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:14.714Z,1562694134.714 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:42:15.041Z,1562694135.041 [CommandLine](IMPORTANT): got command stop
2019-07-09T17:42:15.042Z,1562694135.042 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-09T17:42:15.339Z,1562694135.339 [MissionManager](INFO): MissionManager is completed.
2019-07-09T17:42:15.339Z,1562694135.339 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-07-09T17:42:15.339Z,1562694135.339 [DUSBL] Stopped
2019-07-09T17:42:15.340Z,1562694135.340 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-07-09T17:42:15.340Z,1562694135.340 [DUSBL:A.Pitch] Stopped
2019-07-09T17:42:15.340Z,1562694135.340 [DUSBL:B.SetSpeed] Stopped
2019-07-09T17:42:15.340Z,1562694135.340 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-07-09T17:42:15.345Z,1562694135.345 [DUSBL:C.] Stopped
2019-07-09T17:42:15.345Z,1562694135.345 [DUSBL:RequestRepeater] Stopped
2019-07-09T17:42:15.345Z,1562694135.345 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-07-09T17:42:15.345Z,1562694135.345 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-07-09T17:42:15.345Z,1562694135.345 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:42:15.762Z,1562694135.762 [MissionManager](IMPORTANT): Started mission Default
2019-07-09T17:42:15.762Z,1562694135.762 [Default] Running Loop=1
2019-07-09T17:42:15.762Z,1562694135.762 [Default](DEBUG): Aggregate::initialize Default
2019-07-09T17:42:15.762Z,1562694135.762 [Default:B.GoToSurface] Running Loop=1
2019-07-09T17:42:15.762Z,1562694135.762 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-09T17:42:15.763Z,1562694135.763 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-09T17:42:15.763Z,1562694135.763 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-09T17:42:15.763Z,1562694135.763 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-09T17:42:15.764Z,1562694135.764 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-09T17:42:15.764Z,1562694135.764 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-09T17:42:15.764Z,1562694135.764 [Default:A.Wait] Running Loop=1
2019-07-09T17:42:15.764Z,1562694135.764 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:42:16.521Z,1562694136.521 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:19.341Z,1562694139.341 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:22.589Z,1562694142.589 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:24.605Z,1562694144.605 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-07-09T17:42:24.605Z,1562694144.605 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-09T17:42:24.623Z,1562694144.623 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-09T17:42:25.026Z,1562694145.026 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-09T17:42:25.026Z,1562694145.026 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-07-09T17:42:25.421Z,1562694145.421 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:28.657Z,1562694148.657 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:29.189Z,1562694149.189 [Default:A.Wait](INFO): Done Waiting.
2019-07-09T17:42:29.189Z,1562694149.189 [Default:A.Wait] Stopped
2019-07-09T17:42:29.189Z,1562694149.189 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:42:29.511Z,1562694149.511 [Default:CheckIn] Running Loop=1
2019-07-09T17:42:29.512Z,1562694149.512 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-09T17:42:29.512Z,1562694149.512 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-09T17:42:31.481Z,1562694151.481 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:34.325Z,1562694154.325 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:36.333Z,1562694156.333 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:39.565Z,1562694159.565 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:42.393Z,1562694162.393 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:45.629Z,1562694165.629 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:48.449Z,1562694168.449 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:51.277Z,1562694171.277 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:53.317Z,1562694173.317 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:55.457Z,1562694175.457 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:42:57.811Z,1562694177.811 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.detectionThreshold 75.000000 count persist
2019-07-09T17:42:58.697Z,1562694178.697 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:01.517Z,1562694181.517 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:04.349Z,1562694184.349 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:07.577Z,1562694187.577 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:08.450Z,1562694188.450 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-07-09T17:43:10.413Z,1562694190.413 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:12.187Z,1562694192.187 [CommandLine](IMPORTANT): got command failComponent hardware DUSBL_Hydroid
2019-07-09T17:43:12.187Z,1562694192.187 [DUSBL_Hydroid] Hardware Fault, FailCount= 1
2019-07-09T17:43:12.187Z,1562694192.187 [DUSBL_Hydroid](ERROR): Hardware Fault
2019-07-09T17:43:12.187Z,1562694192.187 [CommandLine](IMPORTANT): DUSBL_Hydroid failureMode is Hardware Fault
2019-07-09T17:43:12.414Z,1562694192.414 [DUSBL_Hydroid](INFO): Powering down
2019-07-09T17:43:12.530Z,1562694192.530 [CBIT](ERROR): Hardware Fault in component: DUSBL_Hydroid
2019-07-09T17:43:13.233Z,1562694193.233 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:13.273Z,1562694193.273 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-07-09T17:43:13.273Z,1562694193.273 [DUSBL_Hydroid] No Fault, FailCount= 1
2019-07-09T17:43:15.642Z,1562694195.642 [DUSBL_Hydroid](INFO): Powering up
2019-07-09T17:43:15.642Z,1562694195.642 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-07-09T17:43:15.673Z,1562694195.673 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:18.485Z,1562694198.485 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:21.317Z,1562694201.317 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:21.962Z,1562694201.962 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:43:21.963Z,1562694201.963 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:43:21.985Z,1562694201.985 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-07-09T17:43:21.988Z,1562694201.988 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-07-09T17:43:21.990Z,1562694201.990 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 2.000000 s
2019-07-09T17:43:21.992Z,1562694201.992 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-07-09T17:43:21.994Z,1562694201.994 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-07-09T17:43:21.995Z,1562694201.995 [DUSBL:A.Pitch](DEBUG): Construct.
2019-07-09T17:43:21.999Z,1562694201.999 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-07-09T17:43:22.016Z,1562694202.016 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-07-09T17:43:22.020Z,1562694202.020 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><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>

    
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>
        
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-07-09T17:43:22.024Z,1562694202.024 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL_Tracking.xml
2019-07-09T17:43:22.197Z,1562694202.197 [Default] Stopped
2019-07-09T17:43:22.197Z,1562694202.197 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-09T17:43:22.197Z,1562694202.197 [Default:B.GoToSurface] Stopped
2019-07-09T17:43:22.197Z,1562694202.197 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-09T17:43:22.197Z,1562694202.197 [Default:CheckIn] Stopped
2019-07-09T17:43:22.197Z,1562694202.197 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-09T17:43:22.197Z,1562694202.197 [Default:CheckIn:Read_GPS] Stopped
2019-07-09T17:43:22.197Z,1562694202.197 [MissionManager](IMPORTANT): Started mission DUSBL
2019-07-09T17:43:22.198Z,1562694202.198 [DUSBL] Running Loop=1
2019-07-09T17:43:22.198Z,1562694202.198 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-07-09T17:43:22.198Z,1562694202.198 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:43:22.198Z,1562694202.198 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-07-09T17:43:22.199Z,1562694202.199 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:43:22.199Z,1562694202.199 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-07-09T17:43:22.199Z,1562694202.199 [DUSBL:C.] Running Loop=1
2019-07-09T17:43:22.199Z,1562694202.199 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-07-09T17:43:22.199Z,1562694202.199 [DUSBL:RequestRepeater] Running Loop=1
2019-07-09T17:43:22.199Z,1562694202.199 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-07-09T17:43:22.199Z,1562694202.199 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-07-09T17:43:22.200Z,1562694202.200 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:43:22.200Z,1562694202.200 [DUSBL:C.] Running Loop=1
2019-07-09T17:43:22.200Z,1562694202.200 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-09T17:43:22.200Z,1562694202.200 [DUSBL:A.Pitch] Running Loop=1
2019-07-09T17:43:23.337Z,1562694203.337 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:24.587Z,1562694204.587 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:26.565Z,1562694206.565 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:26.596Z,1562694206.596 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:28.598Z,1562694208.598 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:29.393Z,1562694209.393 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:30.631Z,1562694210.631 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:32.641Z,1562694212.641 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:32.666Z,1562694212.666 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:33.834Z,1562694213.834 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-07-09T17:43:34.253Z,1562694214.253 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:81.389503
2019-07-09T17:43:34.757Z,1562694214.757 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:35.038Z,1562694215.038 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-07-09T17:43:35.038Z,1562694215.038 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-07-09T17:43:35.038Z,1562694215.038 [DUSBL_Hydroid](INFO): Arming DUSBL detection threshold 75
2019-07-09T17:43:35.039Z,1562694215.039 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-07-09T17:43:35.438Z,1562694215.438 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
O
2019-07-09T17:43:35.438Z,1562694215.438 [DUSBL_Hydroid](INFO): Command Ack
2019-07-09T17:43:35.438Z,1562694215.438 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-07-09T17:43:35.440Z,1562694215.440 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-09T17:43:35.458Z,1562694215.458 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:35.844Z,1562694215.844 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-09T17:43:37.106Z,1562694217.106 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:38.675Z,1562694218.675 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,63,E4
2019-07-09T17:43:38.675Z,1562694218.675 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
2019-07-09T17:43:38.675Z,1562694218.675 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-09T17:43:38.689Z,1562694218.689 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:39.120Z,1562694219.120 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:39.482Z,1562694219.482 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-07-09T17:43:39.482Z,1562694219.482 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-07-09T17:43:39.482Z,1562694219.482 [DUSBL_Hydroid](INFO): Arming DUSBL detection threshold 75
2019-07-09T17:43:39.483Z,1562694219.483 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-07-09T17:43:39.886Z,1562694219.886 [DUSBL_Hydroid](INFO): USBL response received:F4
!U1,P
80,63,E4
2019-07-09T17:43:39.886Z,1562694219.886 [DUSBL_Hydroid](INFO): Command Ack
2019-07-09T17:43:39.887Z,1562694219.887 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-07-09T17:43:39.888Z,1562694219.888 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-09T17:43:40.300Z,1562694220.300 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-09T17:43:40.769Z,1562694220.769 [CommandLine](IMPORTANT): got command stop
2019-07-09T17:43:40.770Z,1562694220.770 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-09T17:43:41.154Z,1562694221.154 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-09T17:43:41.155Z,1562694221.155 [MissionManager](INFO): MissionManager is completed.
2019-07-09T17:43:41.155Z,1562694221.155 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-07-09T17:43:41.155Z,1562694221.155 [DUSBL] Stopped
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:A.Pitch] Stopped
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:B.SetSpeed] Stopped
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:C.] Stopped
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:RequestRepeater] Stopped
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-07-09T17:43:41.156Z,1562694221.156 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:43:41.513Z,1562694221.513 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:41.562Z,1562694221.562 [MissionManager](IMPORTANT): Started mission Default
2019-07-09T17:43:41.562Z,1562694221.562 [Default] Running Loop=1
2019-07-09T17:43:41.562Z,1562694221.562 [Default](DEBUG): Aggregate::initialize Default
2019-07-09T17:43:41.562Z,1562694221.562 [Default:B.GoToSurface] Running Loop=1
2019-07-09T17:43:41.562Z,1562694221.562 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-09T17:43:41.562Z,1562694221.562 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-09T17:43:41.563Z,1562694221.563 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-09T17:43:41.563Z,1562694221.563 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-09T17:43:41.563Z,1562694221.563 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-09T17:43:41.564Z,1562694221.564 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-09T17:43:41.564Z,1562694221.564 [Default:A.Wait] Running Loop=1
2019-07-09T17:43:41.564Z,1562694221.564 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-09T17:43:44.341Z,1562694224.341 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:47.200Z,1562694227.200 [BPC1](ERROR): Battery stick #5 (s/n: 013D) reported OVER_TEMP_ALARM. Status code: 0x1717.
2019-07-09T17:43:47.201Z,1562694227.201 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 6.
2019-07-09T17:43:47.204Z,1562694227.204 [BPC1](INFO): Received data from all battery sticks.
2019-07-09T17:43:47.573Z,1562694227.573 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:50.409Z,1562694230.409 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:53.636Z,1562694233.636 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:54.858Z,1562694234.858 [Default:A.Wait](INFO): Done Waiting.
2019-07-09T17:43:54.858Z,1562694234.858 [Default:A.Wait] Stopped
2019-07-09T17:43:54.858Z,1562694234.858 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-09T17:43:55.259Z,1562694235.259 [Default:CheckIn] Running Loop=1
2019-07-09T17:43:55.259Z,1562694235.259 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-09T17:43:55.260Z,1562694235.260 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-09T17:43:56.469Z,1562694236.469 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:43:59.289Z,1562694239.289 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:01.313Z,1562694241.313 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:03.333Z,1562694243.333 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:06.561Z,1562694246.561 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:09.393Z,1562694249.393 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:12.625Z,1562694252.625 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:15.449Z,1562694255.449 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:18.685Z,1562694258.685 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:21.509Z,1562694261.509 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:24.337Z,1562694264.337 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:27.569Z,1562694267.569 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:30.397Z,1562694270.397 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:33.629Z,1562694273.629 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:34.674Z,1562694274.674 [CommandLine](IMPORTANT): got command quit
2019-07-09T17:44:35.681Z,1562694275.681 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:35.682Z,1562694275.681 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:35.805Z,1562694275.805 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-09T17:44:35.805Z,1562694275.805 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:35.805Z,1562694275.805 [CommandLine](INFO): Join timeout helper Thread ID is 5431
2019-07-09T17:44:35.806Z,1562694275.806 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-09T17:44:35.806Z,1562694275.806 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:35.807Z,1562694275.807 [NavChartDb](INFO): Join timeout helper Thread ID is 5432
2019-07-09T17:44:36.185Z,1562694276.185 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:36.185Z,1562694276.185 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.189Z,1562694276.189 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-07-09T17:44:36.189Z,1562694276.189 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.189Z,1562694276.189 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 5433
2019-07-09T17:44:36.426Z,1562694276.426 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:36.426Z,1562694276.426 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-09T17:44:36.427Z,1562694276.427 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.429Z,1562694276.429 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-07-09T17:44:36.429Z,1562694276.429 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.429Z,1562694276.429 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5434
2019-07-09T17:44:36.457Z,1562694276.457 [NAL9602](DEBUG): Fix Requested
2019-07-09T17:44:36.517Z,1562694276.517 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:36.517Z,1562694276.517 [CTD_NeilBrown](INFO): Powering down
2019-07-09T17:44:36.533Z,1562694276.533 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.542Z,1562694276.542 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-09T17:44:36.542Z,1562694276.542 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.543Z,1562694276.543 [Radio_Surface](INFO): Join timeout helper Thread ID is 5435
2019-07-09T17:44:36.829Z,1562694276.829 [Radio_Surface](INFO): Powering down
2019-07-09T17:44:36.830Z,1562694276.830 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:36.830Z,1562694276.830 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.858Z,1562694276.858 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-09T17:44:36.858Z,1562694276.858 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:36.858Z,1562694276.858 [DataOverHttps](INFO): Join timeout helper Thread ID is 5436
2019-07-09T17:44:37.089Z,1562694277.089 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:37.089Z,1562694277.089 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.105Z,1562694277.105 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-09T17:44:37.106Z,1562694277.106 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.106Z,1562694277.106 [logger](INFO): Join timeout helper Thread ID is 5437
2019-07-09T17:44:37.165Z,1562694277.165 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:37.165Z,1562694277.165 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.185Z,1562694277.185 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-09T17:44:37.185Z,1562694277.185 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.186Z,1562694277.186 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-09T17:44:37.186Z,1562694277.186 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.186Z,1562694277.186 [controlThread](INFO): Join timeout helper Thread ID is 5438
2019-07-09T17:44:37.241Z,1562694277.241 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-09T17:44:37.241Z,1562694277.241 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-09T17:44:37.241Z,1562694277.241 [AHRS_M2](INFO): Powering down
2019-07-09T17:44:37.313Z,1562694277.313 [DUSBL_Hydroid](INFO): Powering down
2019-07-09T17:44:37.385Z,1562694277.385 [Micromodem](INFO): Powering down
2019-07-09T17:44:37.481Z,1562694277.481 [NAL9602](INFO): Powering down
2019-07-09T17:44:37.553Z,1562694277.553 [RDI_Pathfinder](INFO): Powering down
2019-07-09T17:44:37.554Z,1562694277.554 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-09T17:44:37.555Z,1562694277.555 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-09T17:44:37.555Z,1562694277.555 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-09T17:44:37.556Z,1562694277.556 [MissionManager](INFO): Uninitializing Mission Default
2019-07-09T17:44:37.556Z,1562694277.556 [Default] Stopped
2019-07-09T17:44:37.556Z,1562694277.556 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-09T17:44:37.556Z,1562694277.556 [Default:B.GoToSurface] Stopped
2019-07-09T17:44:37.556Z,1562694277.556 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-09T17:44:37.556Z,1562694277.556 [Default:CheckIn] Stopped
2019-07-09T17:44:37.557Z,1562694277.557 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-09T17:44:37.557Z,1562694277.557 [Default:CheckIn:Read_GPS] Stopped
2019-07-09T17:44:37.559Z,1562694277.559 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-09T17:44:37.559Z,1562694277.559 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-09T17:44:37.559Z,1562694277.559 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-09T17:44:37.560Z,1562694277.560 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-09T17:44:37.560Z,1562694277.560 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-09T17:44:37.560Z,1562694277.560 [BuoyancyServo](INFO): Powering down
2019-07-09T17:44:37.573Z,1562694277.573 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-09T17:44:37.573Z,1562694277.573 [ElevatorServo](INFO): Powering down
2019-07-09T17:44:37.574Z,1562694277.574 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-09T17:44:37.574Z,1562694277.574 [MassServo](INFO): Powering down
2019-07-09T17:44:37.575Z,1562694277.575 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-09T17:44:37.575Z,1562694277.575 [RudderServo](INFO): Powering down
2019-07-09T17:44:37.575Z,1562694277.575 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-09T17:44:37.576Z,1562694277.576 [ThrusterServo](INFO): Powering down
2019-07-09T17:44:37.576Z,1562694277.576 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-09T17:44:37.577Z,1562694277.577 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-09T17:44:37.577Z,1562694277.577 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-09T17:44:37.577Z,1562694277.577 [CBIT](DEBUG): Powering off loads.
2019-07-09T17:44:37.589Z,1562694277.589 [CBIT](DEBUG): Disabling WDT.
2019-07-09T17:44:37.601Z,1562694277.601 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-09T17:44:37.601Z,1562694277.601 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.643Z,1562694277.643 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.652Z,1562694277.652 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.692Z,1562694277.692 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.694Z,1562694277.694 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.751Z,1562694277.751 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-09T17:44:37.807Z,1562694277.807 [logger ThreadHandler](INFO): Thread cancelled.