2019-05-02T23:59:18.500Z,1556841558.500 [Supervisor](DEBUG): Initializing supervisor.
2019-05-02T23:59:18.503Z,1556841558.503 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-02T23:59:18.504Z,1556841558.504 [SyncHandler](INFO): Protected caller Thread ID is 9299
2019-05-02T23:59:18.505Z,1556841558.505 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-02T23:59:18.506Z,1556841558.506 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-02T23:59:18.506Z,1556841558.506 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 9300
2019-05-02T23:59:18.509Z,1556841558.509 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-02T23:59:18.521Z,1556841558.521 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-02T23:59:18.522Z,1556841558.522 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-02T23:59:18.523Z,1556841558.523 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 9301
2019-05-02T23:59:18.523Z,1556841558.523 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-02T23:59:18.524Z,1556841558.524 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-02T23:59:18.525Z,1556841558.525 [logger ThreadHandler](INFO): Protected caller Thread ID is 9302
2019-05-02T23:59:18.527Z,1556841558.527 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-02T23:59:18.527Z,1556841558.527 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-02T23:59:18.529Z,1556841558.529 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-02T23:59:18.946Z,1556841558.946 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-02T23:59:18.947Z,1556841558.947 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-02T23:59:19.043Z,1556841559.043 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-02T23:59:19.044Z,1556841559.044 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-02T23:59:19.365Z,1556841559.365 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-02T23:59:19.366Z,1556841559.366 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-02T23:59:19.506Z,1556841559.506 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-02T23:59:19.507Z,1556841559.507 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-02T23:59:19.696Z,1556841559.696 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-02T23:59:19.696Z,1556841559.696 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-02T23:59:20.147Z,1556841560.147 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-02T23:59:20.147Z,1556841560.147 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-02T23:59:20.443Z,1556841560.443 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-02T23:59:20.444Z,1556841560.444 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-02T23:59:20.662Z,1556841560.662 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-02T23:59:20.663Z,1556841560.663 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-02T23:59:20.861Z,1556841560.861 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-02T23:59:20.861Z,1556841560.861 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-02T23:59:20.955Z,1556841560.955 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-02T23:59:20.956Z,1556841560.956 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-02T23:59:21.287Z,1556841561.287 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-02T23:59:21.288Z,1556841561.288 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-02T23:59:21.367Z,1556841561.367 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-02T23:59:21.468Z,1556841561.468 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-02T23:59:21.469Z,1556841561.469 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-02T23:59:22.040Z,1556841562.040 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-02T23:59:22.040Z,1556841562.040 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-02T23:59:22.430Z,1556841562.430 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-02T23:59:22.432Z,1556841562.432 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-02T23:59:22.433Z,1556841562.433 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-02T23:59:22.640Z,1556841562.640 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-02T23:59:22.738Z,1556841562.738 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-02T23:59:22.835Z,1556841562.835 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-02T23:59:23.059Z,1556841563.059 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-02T23:59:23.060Z,1556841563.060 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-02T23:59:23.143Z,1556841563.143 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-02T23:59:23.235Z,1556841563.235 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-02T23:59:23.331Z,1556841563.331 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-02T23:59:23.412Z,1556841563.412 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-02T23:59:23.518Z,1556841563.518 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-02T23:59:23.686Z,1556841563.686 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-02T23:59:23.817Z,1556841563.817 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-02T23:59:23.817Z,1556841563.817 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-02T23:59:23.830Z,1556841563.830 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-02T23:59:24.213Z,1556841564.213 [AHRS_M2] Loaded
2019-05-02T23:59:24.214Z,1556841564.214 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-02T23:59:24.286Z,1556841564.286 [DataOverHttps] Loaded
2019-05-02T23:59:24.286Z,1556841564.286 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-02T23:59:24.287Z,1556841564.287 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-02T23:59:24.288Z,1556841564.288 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 9381
2019-05-02T23:59:24.301Z,1556841564.301 [Depth_Keller] Loaded
2019-05-02T23:59:24.302Z,1556841564.302 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-02T23:59:24.306Z,1556841564.306 [DropWeight] Loaded
2019-05-02T23:59:24.307Z,1556841564.307 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-02T23:59:24.362Z,1556841564.362 [DUSBL_Hydroid] Loaded
2019-05-02T23:59:24.363Z,1556841564.363 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-02T23:59:24.403Z,1556841564.403 [Micromodem] Loaded
2019-05-02T23:59:24.403Z,1556841564.403 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-02T23:59:24.501Z,1556841564.501 [NAL9602] Loaded
2019-05-02T23:59:24.501Z,1556841564.501 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-02T23:59:24.516Z,1556841564.516 [Onboard] Loaded
2019-05-02T23:59:24.517Z,1556841564.517 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-02T23:59:24.522Z,1556841564.522 [PowerOnly] Loaded
2019-05-02T23:59:24.523Z,1556841564.523 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-02T23:59:24.529Z,1556841564.529 [Radio_Surface] Loaded
2019-05-02T23:59:24.529Z,1556841564.529 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-02T23:59:24.530Z,1556841564.530 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-02T23:59:24.531Z,1556841564.531 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 9382
2019-05-02T23:59:24.575Z,1556841564.575 [RDI_Pathfinder] Loaded
2019-05-02T23:59:24.575Z,1556841564.575 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-02T23:59:26.053Z,1556841566.053 [BPC1] Loaded
2019-05-02T23:59:26.053Z,1556841566.053 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-02T23:59:26.054Z,1556841566.054 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-02T23:59:26.054Z,1556841566.054 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-02T23:59:26.103Z,1556841566.103 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-02T23:59:26.103Z,1556841566.103 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-02T23:59:26.569Z,1556841566.569 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-02T23:59:26.569Z,1556841566.569 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-02T23:59:26.590Z,1556841566.590 [NavChart] Loaded
2019-05-02T23:59:26.590Z,1556841566.590 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-02T23:59:26.594Z,1556841566.594 [UniversalFixResidualReporter] Loaded
2019-05-02T23:59:26.594Z,1556841566.594 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-02T23:59:26.595Z,1556841566.595 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-02T23:59:26.595Z,1556841566.595 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-02T23:59:26.728Z,1556841566.728 [BuoyancyServo] Loaded
2019-05-02T23:59:26.728Z,1556841566.728 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-02T23:59:26.787Z,1556841566.787 [ElevatorServo] Loaded
2019-05-02T23:59:26.787Z,1556841566.787 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-02T23:59:26.826Z,1556841566.826 [MassServo] Loaded
2019-05-02T23:59:26.826Z,1556841566.826 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-02T23:59:26.873Z,1556841566.873 [RudderServo] Loaded
2019-05-02T23:59:26.874Z,1556841566.874 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-02T23:59:26.919Z,1556841566.919 [ThrusterServo] Loaded
2019-05-02T23:59:26.919Z,1556841566.919 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-02T23:59:26.919Z,1556841566.919 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-02T23:59:26.920Z,1556841566.920 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-02T23:59:27.166Z,1556841567.166 [CTD_NeilBrown] Loaded
2019-05-02T23:59:27.167Z,1556841567.167 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-02T23:59:27.168Z,1556841567.168 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-02T23:59:27.168Z,1556841567.168 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 9383
2019-05-02T23:59:27.212Z,1556841567.212 [WetLabsSeaOWL_UV_A] Loaded
2019-05-02T23:59:27.212Z,1556841567.212 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-02T23:59:27.213Z,1556841567.213 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-02T23:59:27.214Z,1556841567.214 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 9384
2019-05-02T23:59:27.214Z,1556841567.214 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-02T23:59:27.215Z,1556841567.215 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-02T23:59:27.506Z,1556841567.506 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-02T23:59:27.507Z,1556841567.507 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-02T23:59:27.547Z,1556841567.547 [DepthRateCalculator] Loaded
2019-05-02T23:59:27.547Z,1556841567.547 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-02T23:59:27.553Z,1556841567.553 [PitchRateCalculator] Loaded
2019-05-02T23:59:27.553Z,1556841567.553 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-02T23:59:27.565Z,1556841567.565 [SpeedCalculator] Loaded
2019-05-02T23:59:27.566Z,1556841567.566 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-02T23:59:27.587Z,1556841567.587 [TempGradientCalculator] Loaded
2019-05-02T23:59:27.587Z,1556841567.587 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-02T23:59:27.593Z,1556841567.593 [YawRateCalculator] Loaded
2019-05-02T23:59:27.593Z,1556841567.593 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-02T23:59:27.633Z,1556841567.633 [ElevatorOffsetCalculator] Loaded
2019-05-02T23:59:27.634Z,1556841567.634 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-02T23:59:27.634Z,1556841567.634 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-02T23:59:27.634Z,1556841567.634 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-02T23:59:27.770Z,1556841567.770 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-02T23:59:27.792Z,1556841567.792 [SBIT] Loaded
2019-05-02T23:59:27.792Z,1556841567.792 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-02T23:59:27.793Z,1556841567.793 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-02T23:59:27.804Z,1556841567.804 [IBIT] Loaded
2019-05-02T23:59:27.805Z,1556841567.805 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-02T23:59:27.808Z,1556841567.808 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-02T23:59:27.944Z,1556841567.944 [CBIT] Loaded
2019-05-02T23:59:27.944Z,1556841567.944 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-02T23:59:27.945Z,1556841567.945 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-02T23:59:27.945Z,1556841567.945 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-02T23:59:28.015Z,1556841568.015 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-02T23:59:28.016Z,1556841568.016 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-02T23:59:28.114Z,1556841568.114 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-02T23:59:28.115Z,1556841568.115 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-02T23:59:28.181Z,1556841568.181 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-02T23:59:28.264Z,1556841568.264 [VerticalControl] Loaded
2019-05-02T23:59:28.265Z,1556841568.265 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-02T23:59:28.265Z,1556841568.265 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-02T23:59:28.323Z,1556841568.323 [HorizontalControl] Loaded
2019-05-02T23:59:28.323Z,1556841568.323 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-02T23:59:28.324Z,1556841568.324 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-02T23:59:28.326Z,1556841568.326 [SpeedControl] Loaded
2019-05-02T23:59:28.326Z,1556841568.326 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-02T23:59:28.327Z,1556841568.327 [LoopControl](DEBUG): Construct LoopControl.
2019-05-02T23:59:28.327Z,1556841568.327 [LoopControl] Loaded
2019-05-02T23:59:28.327Z,1556841568.327 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-02T23:59:28.328Z,1556841568.328 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-02T23:59:28.328Z,1556841568.328 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-02T23:59:28.355Z,1556841568.355 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-02T23:59:28.359Z,1556841568.359 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-02T23:59:28.360Z,1556841568.360 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-02T23:59:28.366Z,1556841568.366 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-02T23:59:28.367Z,1556841568.367 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-02T23:59:28.368Z,1556841568.368 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 9385
2019-05-02T23:59:28.372Z,1556841568.372 [Supervisor](INFO): Main Thread ID is 9155
2019-05-02T23:59:28.372Z,1556841568.372 [Supervisor](DEBUG): Running supervisor.
2019-05-02T23:59:28.373Z,1556841568.373 [CommandLine ThreadHandler](INFO): Handler Thread ID is 9386
2019-05-02T23:59:28.375Z,1556841568.375 [controlThread ThreadHandler](INFO): Handler Thread ID is 9387
2019-05-02T23:59:28.376Z,1556841568.376 [controlThread](DEBUG): Initializing ControlThread
2019-05-02T23:59:28.385Z,1556841568.385 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-02T23:59:28.385Z,1556841568.385 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-02T23:59:28.386Z,1556841568.386 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-02T23:59:28.387Z,1556841568.387 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-02T23:59:28.387Z,1556841568.387 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-02T23:59:28.387Z,1556841568.387 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-02T23:59:28.388Z,1556841568.388 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-02T23:59:28.388Z,1556841568.388 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-02T23:59:28.389Z,1556841568.389 [SBIT](INFO): Initialize SBIT Component.
2019-05-02T23:59:28.389Z,1556841568.389 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-02T23:59:28.389Z,1556841568.389 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-02T23:59:28.390Z,1556841568.390 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-02T23:59:28.391Z,1556841568.391 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-05-02T23:59:28.392Z,1556841568.392 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-02T23:59:28.393Z,1556841568.393 [IBIT](INFO): Initialize IBIT Component.
2019-05-02T23:59:28.394Z,1556841568.394 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-02T23:59:28.394Z,1556841568.394 [logger ThreadHandler](INFO): Handler Thread ID is 9388
2019-05-02T23:59:28.405Z,1556841568.405 [CBIT](DEBUG): Initialized mux pins.
2019-05-02T23:59:28.405Z,1556841568.405 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-02T23:59:28.413Z,1556841568.413 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 9389
2019-05-02T23:59:28.414Z,1556841568.414 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-02T23:59:28.425Z,1556841568.425 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 9390
2019-05-02T23:59:28.429Z,1556841568.429 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-02T23:59:28.429Z,1556841568.429 [CBIT](DEBUG): Initializing heartbeat.
2019-05-02T23:59:28.445Z,1556841568.445 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 9391
2019-05-02T23:59:28.446Z,1556841568.446 [CTD_NeilBrown](INFO): Powering down
2019-05-02T23:59:28.481Z,1556841568.481 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 9392
2019-05-02T23:59:28.482Z,1556841568.482 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-02T23:59:28.501Z,1556841568.501 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-02T23:59:28.501Z,1556841568.501 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-02T23:59:28.502Z,1556841568.502 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 9393
2019-05-02T23:59:28.505Z,1556841568.505 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-02T23:59:28.505Z,1556841568.505 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-02T23:59:28.505Z,1556841568.505 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-02T23:59:28.505Z,1556841568.505 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-02T23:59:28.506Z,1556841568.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-02T23:59:28.506Z,1556841568.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-02T23:59:28.506Z,1556841568.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-02T23:59:28.506Z,1556841568.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-02T23:59:28.506Z,1556841568.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-02T23:59:28.507Z,1556841568.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-02T23:59:28.507Z,1556841568.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-02T23:59:28.507Z,1556841568.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-02T23:59:28.507Z,1556841568.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-02T23:59:28.507Z,1556841568.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-02T23:59:28.507Z,1556841568.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-02T23:59:28.508Z,1556841568.508 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-02T23:59:28.537Z,1556841568.537 [CBIT](DEBUG): Backplane powered.
2019-05-02T23:59:28.537Z,1556841568.537 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-02T23:59:28.539Z,1556841568.539 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-02T23:59:28.539Z,1556841568.539 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-02T23:59:28.540Z,1556841568.540 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-02T23:59:28.541Z,1556841568.541 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-02T23:59:28.550Z,1556841568.550 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-02T23:59:28.581Z,1556841568.581 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-05-02T23:59:28.582Z,1556841568.582 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-02T23:59:28.652Z,1556841568.652 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-02T23:59:28.653Z,1556841568.653 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-02T23:59:28.655Z,1556841568.655 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-02T23:59:28.693Z,1556841568.693 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-02T23:59:28.696Z,1556841568.696 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-02T23:59:28.717Z,1556841568.717 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-02T23:59:28.720Z,1556841568.720 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-05-02T23:59:28.738Z,1556841568.738 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-02T23:59:28.762Z,1556841568.762 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-02T23:59:28.813Z,1556841568.813 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-02T23:59:28.814Z,1556841568.814 [DUSBL_Hydroid](INFO): Powering up
2019-05-02T23:59:28.814Z,1556841568.814 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-02T23:59:28.829Z,1556841568.829 [Radio_Surface](INFO): Powering up
2019-05-02T23:59:28.881Z,1556841568.881 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-02T23:59:28.918Z,1556841568.918 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-02T23:59:28.929Z,1556841568.929 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-02T23:59:28.930Z,1556841568.930 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-02T23:59:28.941Z,1556841568.941 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-02T23:59:28.942Z,1556841568.942 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-02T23:59:28.949Z,1556841568.949 [MassServo](DEBUG): Initializing MassServo.
2019-05-02T23:59:28.950Z,1556841568.950 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-02T23:59:28.957Z,1556841568.957 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-02T23:59:28.958Z,1556841568.958 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-02T23:59:28.965Z,1556841568.965 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-02T23:59:29.163Z,1556841569.163 [Micromodem](INFO): Powering up
2019-05-02T23:59:29.163Z,1556841569.163 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-02T23:59:29.197Z,1556841569.197 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-02T23:59:29.901Z,1556841569.901 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-02T23:59:29.901Z,1556841569.901 [RudderServo](FAULT): Rudder failed to initialize
2019-05-02T23:59:29.901Z,1556841569.901 [RudderServo] Communications Fault, FailCount= 1
2019-05-02T23:59:29.901Z,1556841569.901 [RudderServo](ERROR): Communications Fault
2019-05-02T23:59:30.013Z,1556841570.013 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-02T23:59:30.170Z,1556841570.170 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-02T23:59:30.170Z,1556841570.170 [RudderServo](INFO): Powering down
2019-05-02T23:59:30.857Z,1556841570.857 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-02T23:59:30.978Z,1556841570.978 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-02T23:59:30.982Z,1556841570.982 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-02T23:59:30.982Z,1556841570.982 [RudderServo] No Fault, FailCount= 1
2019-05-02T23:59:42.189Z,1556841582.189 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-02T23:59:47.021Z,1556841587.021 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-02T23:59:54.687Z,1556841594.687 [NAL9602](INFO): Powering up NAL9602
2019-05-03T00:00:05.599Z,1556841605.599 [Micromodem](ERROR): Response from modem unexpected: $CADQF,189,1*50

2019-05-03T00:00:05.600Z,1556841605.600 [NAL9602](INFO): NAL9602 initialized
2019-05-03T00:00:05.996Z,1556841605.996 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-03T00:00:06.404Z,1556841606.404 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190503000004.682421,05,173,16,0100,0150,246,00,00,01,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,189,-0.05,-999,9760,4000*7B

2019-05-03T00:00:06.417Z,1556841606.417 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:00:12.930Z,1556841612.930 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-03T00:00:12.942Z,1556841612.942 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-03T00:00:23.954Z,1556841623.954 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.018826
CHAN A1 (24V): -0.027314
CHAN A2 (12V): -0.006708
CHAN A3 (5V): -0.002118
CHAN B0 (3.3V): 0.000243
CHAN B1 (3.15aV): -0.000072
CHAN B2 (3.15bV): 0.000443
CHAN B3 (GND): 0.001906
OPEN: 0.006339
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-03T00:00:47.057Z,1556841647.057 [NAL9602](INFO): SBD MO Status=2, MOMSN=3795, MT Status=2, MTMSN=0
2019-05-03T00:00:47.057Z,1556841647.057 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-03T00:01:06.603Z,1556841666.603 [SBIT](IMPORTANT): SBIT PASSED
2019-05-03T00:01:06.669Z,1556841666.669 [CommandLine](IMPORTANT): got command configSet list
2019-05-03T00:01:06.669Z,1556841666.669 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-03T00:01:06.670Z,1556841666.670 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-03T00:01:06.670Z,1556841666.670 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-03T00:01:06.671Z,1556841666.671 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-03T00:01:06.672Z,1556841666.672 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-03T00:01:06.672Z,1556841666.672 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-03T00:01:07.027Z,1556841667.027 [MissionManager](IMPORTANT): Started mission Startup
2019-05-03T00:01:07.053Z,1556841667.053 [Startup] Running Loop=1
2019-05-03T00:01:07.053Z,1556841667.053 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-03T00:01:07.053Z,1556841667.053 [Startup:A.GoToSurface] Running Loop=1
2019-05-03T00:01:07.053Z,1556841667.053 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-03T00:01:07.054Z,1556841667.054 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-03T00:01:07.054Z,1556841667.054 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-03T00:01:07.055Z,1556841667.055 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-03T00:01:07.055Z,1556841667.055 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-03T00:01:07.055Z,1556841667.055 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-03T00:01:07.065Z,1556841667.065 [Startup:StartupSatComms] Running Loop=1
2019-05-03T00:01:07.065Z,1556841667.065 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-03T00:01:07.065Z,1556841667.065 [Startup:StartupSatComms:A] Running Loop=1
2019-05-03T00:01:07.423Z,1556841667.423 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-03T00:01:41.363Z,1556841701.363 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-03T00:01:41.364Z,1556841701.364 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.00,        +0.00,     ,   0.00,119.00
2019-05-03T00:01:54.615Z,1556841714.615 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004866
2019-05-03T00:02:07.217Z,1556841727.217 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-03T00:01:07.1Z
2019-05-03T00:02:07.217Z,1556841727.217 [Startup:StartupSatComms:A] Stopped
2019-05-03T00:02:07.218Z,1556841727.218 [Startup:StartupSatComms:B] Running Loop=1
2019-05-03T00:02:07.606Z,1556841727.606 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-03T00:02:13.017Z,1556841733.017 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190502T234600/Courier0010.lzma
2019-05-03T00:02:13.822Z,1556841733.822 [DataOverHttps](INFO): Moved sent file to Logs/20190502T234600/Courier0010.lzma.bak
2019-05-03T00:02:13.823Z,1556841733.823 [DataOverHttps](INFO): SBD MOMSN=10914199
2019-05-03T00:02:25.278Z,1556841745.278 [DataOverHttps](INFO): Sending 303 bytes from file Logs/20190502T234600/Express0011.lzma
2019-05-03T00:02:26.082Z,1556841746.082 [DataOverHttps](INFO): Moved sent file to Logs/20190502T234600/Express0011.lzma.bak
2019-05-03T00:02:26.082Z,1556841746.082 [DataOverHttps](INFO): SBD MOMSN=10914201
2019-05-03T00:02:28.609Z,1556841748.609 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-03T00:02:28.609Z,1556841748.609 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-03T00:02:28.624Z,1556841748.624 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-03T00:02:29.028Z,1556841749.028 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-03T00:02:29.028Z,1556841749.028 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-03T00:02:37.508Z,1556841757.508 [DataOverHttps](INFO): Sending 1278 bytes from file Logs/20190502T235918/Express0001.lzma
2019-05-03T00:02:38.310Z,1556841758.310 [DataOverHttps](INFO): Moved sent file to Logs/20190502T235918/Express0001.lzma.bak
2019-05-03T00:02:38.311Z,1556841758.311 [DataOverHttps](INFO): SBD MOMSN=10914204
2019-05-03T00:02:39.145Z,1556841759.145 [Startup:StartupSatComms:B] Stopped
2019-05-03T00:02:39.145Z,1556841759.145 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-03T00:02:39.145Z,1556841759.145 [Startup:StartupSatComms] Stopped
2019-05-03T00:02:39.145Z,1556841759.145 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-03T00:02:39.146Z,1556841759.146 [Startup](INFO): Completed Startup
2019-05-03T00:02:39.146Z,1556841759.146 [MissionManager](INFO): Startup is completed.
2019-05-03T00:02:39.146Z,1556841759.146 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-03T00:02:39.146Z,1556841759.146 [Startup] Stopped
2019-05-03T00:02:39.147Z,1556841759.147 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-03T00:02:39.147Z,1556841759.147 [Startup:A.GoToSurface] Stopped
2019-05-03T00:02:39.147Z,1556841759.147 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-03T00:02:39.518Z,1556841759.518 [MissionManager](IMPORTANT): Started mission Default
2019-05-03T00:02:39.518Z,1556841759.518 [Default] Running Loop=1
2019-05-03T00:02:39.518Z,1556841759.518 [Default](DEBUG): Aggregate::initialize Default
2019-05-03T00:02:39.518Z,1556841759.518 [Default:B.GoToSurface] Running Loop=1
2019-05-03T00:02:39.518Z,1556841759.518 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-03T00:02:39.518Z,1556841759.518 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-03T00:02:39.519Z,1556841759.519 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-03T00:02:39.519Z,1556841759.519 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-03T00:02:39.519Z,1556841759.519 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-03T00:02:39.520Z,1556841759.520 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-03T00:02:39.520Z,1556841759.520 [Default:A.Wait] Running Loop=1
2019-05-03T00:02:39.520Z,1556841759.520 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:02:43.938Z,1556841763.938 [NAL9602](INFO): SBD MO Status=2, MOMSN=3795, MT Status=2, MTMSN=0
2019-05-03T00:02:43.939Z,1556841763.939 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-03T00:02:52.844Z,1556841772.844 [Default:A.Wait](INFO): Done Waiting.
2019-05-03T00:02:52.844Z,1556841772.844 [Default:A.Wait] Stopped
2019-05-03T00:02:52.844Z,1556841772.844 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:02:53.259Z,1556841773.259 [Default:CheckIn] Running Loop=1
2019-05-03T00:02:53.259Z,1556841773.259 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-03T00:02:53.259Z,1556841773.259 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-03T00:02:53.658Z,1556841773.658 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-03T00:03:05.376Z,1556841785.376 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-03T00:03:05.376Z,1556841785.376 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050217113939,35.0, -0.1,   0.0,10
2019-05-03T00:04:01.105Z,1556841841.105 [NAL9602](INFO): SBD MO Status=2, MOMSN=3795, MT Status=2, MTMSN=0
2019-05-03T00:04:01.105Z,1556841841.105 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-03T00:04:21.300Z,1556841861.300 [NAL9602](INFO): SBD MO Status=0, MOMSN=3795, MT Status=0, MTMSN=0
2019-05-03T00:04:21.300Z,1556841861.300 [NAL9602](INFO): No messages in MT queue
2019-05-03T00:04:22.125Z,1556841862.125 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:24.953Z,1556841864.953 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:27.777Z,1556841867.777 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:31.029Z,1556841871.029 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:33.841Z,1556841873.841 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:36.665Z,1556841876.665 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:39.901Z,1556841879.901 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:42.729Z,1556841882.729 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:45.961Z,1556841885.961 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:48.789Z,1556841888.789 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:52.021Z,1556841892.021 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:54.845Z,1556841894.845 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:04:58.081Z,1556841898.081 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:00.905Z,1556841900.905 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:03.745Z,1556841903.745 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:06.969Z,1556841906.969 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:09.793Z,1556841909.793 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:13.025Z,1556841913.025 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:15.857Z,1556841915.857 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:18.681Z,1556841918.681 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:21.913Z,1556841921.913 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:24.745Z,1556841924.745 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:27.989Z,1556841927.989 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:29.659Z,1556841929.659 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-05-03T00:05:29.659Z,1556841929.659 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-03T00:05:29.702Z,1556841929.702 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-03T00:05:30.153Z,1556841930.153 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-03T00:05:30.153Z,1556841930.153 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-05-03T00:05:30.805Z,1556841930.805 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:34.037Z,1556841934.037 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:36.869Z,1556841936.869 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:39.689Z,1556841939.689 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:42.921Z,1556841942.921 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:45.749Z,1556841945.749 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:49.005Z,1556841949.005 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:51.809Z,1556841951.809 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:55.053Z,1556841955.053 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:05:57.877Z,1556841957.877 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:00.705Z,1556841960.705 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:01.174Z,1556841961.174 [CommandLine](IMPORTANT): got command show variable range
2019-05-03T00:06:01.177Z,1556841961.177 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-03T00:06:01.313Z,1556841961.313 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-03T00:06:01.314Z,1556841961.314 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-03T00:06:01.333Z,1556841961.333 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-03T00:06:01.334Z,1556841961.334 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-03T00:06:01.335Z,1556841961.335 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-03T00:06:01.338Z,1556841961.338 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-03T00:06:01.339Z,1556841961.339 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-03T00:06:01.339Z,1556841961.339 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-03T00:06:01.339Z,1556841961.339 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-03T00:06:03.945Z,1556841963.945 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:06.785Z,1556841966.785 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:09.081Z,1556841969.081 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-03T00:06:10.033Z,1556841970.033 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:12.909Z,1556841972.909 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:15.542Z,1556841975.542 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-03T00:06:15.543Z,1556841975.543 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-03T00:06:15.587Z,1556841975.587 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-03T00:06:15.592Z,1556841975.592 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-03T00:06:15.596Z,1556841975.596 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-03T00:06:15.600Z,1556841975.600 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-03T00:06:15.604Z,1556841975.604 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-03T00:06:15.605Z,1556841975.605 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-03T00:06:15.611Z,1556841975.611 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-03T00:06:15.620Z,1556841975.620 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-03T00:06:15.624Z,1556841975.624 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

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

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-05-03T00:06:15.627Z,1556841975.627 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-03T00:06:15.721Z,1556841975.721 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:15.746Z,1556841975.746 [Default] Stopped
2019-05-03T00:06:15.746Z,1556841975.746 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-03T00:06:15.746Z,1556841975.746 [Default:B.GoToSurface] Stopped
2019-05-03T00:06:15.746Z,1556841975.746 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-03T00:06:15.746Z,1556841975.746 [Default:CheckIn] Stopped
2019-05-03T00:06:15.746Z,1556841975.746 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-03T00:06:15.746Z,1556841975.746 [Default:CheckIn:Read_GPS] Stopped
2019-05-03T00:06:15.746Z,1556841975.746 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-03T00:06:15.747Z,1556841975.747 [DUSBL] Running Loop=1
2019-05-03T00:06:15.747Z,1556841975.747 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-03T00:06:15.747Z,1556841975.747 [DUSBL:A.Pitch] Running Loop=1
2019-05-03T00:06:15.747Z,1556841975.747 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-03T00:06:15.747Z,1556841975.747 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-03T00:06:15.747Z,1556841975.747 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-03T00:06:15.747Z,1556841975.747 [DUSBL:C] Running Loop=1
2019-05-03T00:06:15.748Z,1556841975.748 [DUSBL:RequestRepeater] Running Loop=1
2019-05-03T00:06:15.748Z,1556841975.748 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:06:15.748Z,1556841975.748 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:06:15.748Z,1556841975.748 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:06:15.748Z,1556841975.748 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:06:15.748Z,1556841975.748 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:06:15.748Z,1556841975.748 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:06:15.749Z,1556841975.749 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:06:15.750Z,1556841975.750 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-03T00:06:15.750Z,1556841975.750 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-03T00:06:15.750Z,1556841975.750 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-03T00:06:15.751Z,1556841975.751 [DUSBL:A.Pitch] Running Loop=1
2019-05-03T00:06:17.287Z,1556841977.287 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:17.287Z,1556841977.287 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:17.287Z,1556841977.287 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:17.287Z,1556841977.287 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:17.288Z,1556841977.288 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:18.098Z,1556841978.098 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:06:18.098Z,1556841978.098 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:06:18.917Z,1556841978.917 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:21.326Z,1556841981.326 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.038236
2019-05-03T00:06:21.326Z,1556841981.326 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:21.327Z,1556841981.327 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:21.327Z,1556841981.327 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:21.327Z,1556841981.327 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:21.327Z,1556841981.327 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:21.731Z,1556841981.731 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,0C5,000,00000,187,80,81,04,FF
2019-05-03T00:06:21.749Z,1556841981.749 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:06:22.138Z,1556841982.138 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:22.139Z,1556841982.139 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:22.139Z,1556841982.139 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:22.139Z,1556841982.139 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:22.140Z,1556841982.140 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:22.168Z,1556841982.168 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000549.00,A,3648.16196,N,12147.28003,W,0.214,148.70,030519,,,A*7F
2019-05-03T00:06:22.183Z,1556841982.183 [NAL9602](INFO): GPS fix at 20190503T000549: (36.802699, -121.788000)
2019-05-03T00:06:22.550Z,1556841982.550 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:06:22.550Z,1556841982.550 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:06:25.813Z,1556841985.813 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:06:25.813Z,1556841985.813 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:06:25.813Z,1556841985.813 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater] Running Loop=2
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:06:25.814Z,1556841985.814 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:06:25.815Z,1556841985.815 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:06:25.815Z,1556841985.815 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:06:25.815Z,1556841985.815 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:06:26.182Z,1556841986.182 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.042351
2019-05-03T00:06:26.182Z,1556841986.182 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:26.182Z,1556841986.182 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:26.183Z,1556841986.182 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:26.183Z,1556841986.183 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:26.183Z,1556841986.183 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:26.596Z,1556841986.596 [DUSBL_Hydroid](INFO): USBL response received:00000,187,80,81,08,FF
2019-05-03T00:06:26.596Z,1556841986.596 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,08,FF
2019-05-03T00:06:30.222Z,1556841990.222 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.039064
2019-05-03T00:06:30.222Z,1556841990.222 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:30.223Z,1556841990.223 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:30.223Z,1556841990.223 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:30.223Z,1556841990.223 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:30.224Z,1556841990.224 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:30.626Z,1556841990.626 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,187,80,81,06,FF
2019-05-03T00:06:30.627Z,1556841990.627 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,187,80,81,06,FF
2019-05-03T00:06:30.642Z,1556841990.642 [Micromodem](ERROR): Response from modem unexpected: $CADQF,194,1*5C

2019-05-03T00:06:30.643Z,1556841990.643 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-03T00:06:31.044Z,1556841991.044 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190503000629.690683,06,91,13,0093,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,194,0.05,-999,9760,4000*69

2019-05-03T00:06:34.269Z,1556841994.269 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.045114
2019-05-03T00:06:34.269Z,1556841994.269 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:34.269Z,1556841994.269 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:34.269Z,1556841994.269 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:34.270Z,1556841994.270 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:34.271Z,1556841994.271 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:34.666Z,1556841994.666 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,BF2,00,81,04,FF
2019-05-03T00:06:34.667Z,1556841994.667 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,BF2,00,81,04,FF
2019-05-03T00:06:36.317Z,1556841996.317 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:06:36.317Z,1556841996.317 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:06:36.317Z,1556841996.317 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater] Running Loop=3
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:06:36.318Z,1556841996.318 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:06:36.319Z,1556841996.319 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:06:38.302Z,1556841998.302 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.031634
2019-05-03T00:06:38.302Z,1556841998.302 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:38.302Z,1556841998.302 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:38.303Z,1556841998.303 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:38.303Z,1556841998.303 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:38.304Z,1556841998.304 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:38.711Z,1556841998.711 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,BDD,000,00291,188,80,80,0A,FF
2019-05-03T00:06:38.711Z,1556841998.711 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-03T00:06:38.762Z,1556841998.762 [Reporter](INFO): acoustic_contact_range 1.920001 m
2019-05-03T00:06:41.142Z,1556842001.142 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:06:41.143Z,1556842001.143 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:06:41.143Z,1556842001.143 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:41.143Z,1556842001.143 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:41.144Z,1556842001.144 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:41.145Z,1556842001.145 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:41.146Z,1556842001.146 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:41.537Z,1556842001.537 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,184,80,81,05,FF
2019-05-03T00:06:41.538Z,1556842001.538 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,184,80,81,05,FF
2019-05-03T00:06:45.174Z,1556842005.174 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.027742
2019-05-03T00:06:45.174Z,1556842005.174 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:45.174Z,1556842005.174 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:45.174Z,1556842005.174 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:45.175Z,1556842005.175 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:45.176Z,1556842005.176 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:45.575Z,1556842005.575 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,188,80,81,06,FF
2019-05-03T00:06:45.575Z,1556842005.575 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,188,80,81,06,FF
2019-05-03T00:06:47.232Z,1556842007.232 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:06:47.232Z,1556842007.232 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:06:47.232Z,1556842007.232 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater] Running Loop=4
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:06:47.234Z,1556842007.234 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:06:47.235Z,1556842007.235 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:06:47.235Z,1556842007.235 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:06:47.235Z,1556842007.235 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:06:49.214Z,1556842009.214 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.038951
2019-05-03T00:06:49.215Z,1556842009.215 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:49.215Z,1556842009.215 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:49.215Z,1556842009.215 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:49.215Z,1556842009.215 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:49.216Z,1556842009.216 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:49.618Z,1556842009.618 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,63,E4
2019-05-03T00:06:49.619Z,1556842009.619 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
2019-05-03T00:06:49.619Z,1556842009.619 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-03T00:06:50.029Z,1556842010.029 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:06:50.029Z,1556842010.029 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:06:50.030Z,1556842010.030 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:50.030Z,1556842010.030 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:50.031Z,1556842010.031 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:50.032Z,1556842010.032 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:50.033Z,1556842010.033 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:54.058Z,1556842014.058 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.025284
2019-05-03T00:06:54.059Z,1556842014.059 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:54.059Z,1556842014.059 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:54.059Z,1556842014.059 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:54.059Z,1556842014.059 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:54.059Z,1556842014.059 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:54.466Z,1556842014.466 [DUSBL_Hydroid](INFO): USBL response received:!0000,18B,80,81,04,FF
2019-05-03T00:06:54.466Z,1556842014.466 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !0000,18B,80,81,04,FF
2019-05-03T00:06:54.867Z,1556842014.867 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-03T00:06:56.909Z,1556842016.909 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-03T00:06:56.912Z,1556842016.912 [BPC1](INFO): Received data from all battery sticks.
2019-05-03T00:06:57.756Z,1556842017.756 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:06:57.756Z,1556842017.756 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:06:57.756Z,1556842017.756 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:06:57.765Z,1556842017.765 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:06:57.765Z,1556842017.765 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:06:57.765Z,1556842017.765 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:06:57.765Z,1556842017.765 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:06:57.765Z,1556842017.765 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:06:57.765Z,1556842017.765 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-03T00:06:57.765Z,1556842017.765 [DUSBL:RequestRepeater] Running Loop=5
2019-05-03T00:06:57.766Z,1556842017.766 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:06:57.766Z,1556842017.766 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:06:57.766Z,1556842017.766 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:06:57.766Z,1556842017.766 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:06:57.766Z,1556842017.766 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:06:58.098Z,1556842018.098 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.038524
2019-05-03T00:06:58.098Z,1556842018.098 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:06:58.098Z,1556842018.098 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:06:58.099Z,1556842018.099 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:06:58.099Z,1556842018.099 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:06:58.099Z,1556842018.099 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:06:58.502Z,1556842018.502 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,186,80,81,07,FF
2019-05-03T00:06:58.503Z,1556842018.503 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,186,80,81,07,FF
2019-05-03T00:07:02.143Z,1556842022.143 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.043325
2019-05-03T00:07:02.143Z,1556842022.143 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:02.143Z,1556842022.143 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:02.143Z,1556842022.143 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:02.143Z,1556842022.143 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:02.144Z,1556842022.144 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:02.543Z,1556842022.543 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,B85,80,81,05,FF
2019-05-03T00:07:02.543Z,1556842022.543 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,B85,80,81,05,FF
2019-05-03T00:07:06.182Z,1556842026.182 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.038175
2019-05-03T00:07:06.182Z,1556842026.182 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:06.182Z,1556842026.182 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:06.183Z,1556842026.183 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:06.183Z,1556842026.183 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:06.184Z,1556842026.184 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:06.583Z,1556842026.583 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,BF7,000,00000,18A,80,81,07,FF
2019-05-03T00:07:06.994Z,1556842026.994 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:07:06.994Z,1556842026.994 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:07:06.995Z,1556842026.995 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:06.995Z,1556842026.995 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:06.995Z,1556842026.995 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:06.996Z,1556842026.996 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:06.998Z,1556842026.998 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:08.243Z,1556842028.243 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:07:08.243Z,1556842028.243 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:07:08.243Z,1556842028.243 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater] Running Loop=6
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:07:08.244Z,1556842028.244 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:07:08.245Z,1556842028.245 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:07:08.245Z,1556842028.245 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:07:08.245Z,1556842028.245 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:07:11.034Z,1556842031.034 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.036820
2019-05-03T00:07:11.034Z,1556842031.034 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:11.035Z,1556842031.035 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:11.035Z,1556842031.035 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:11.035Z,1556842031.035 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:11.035Z,1556842031.035 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:11.430Z,1556842031.430 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,CB3,000,0003,FF
2019-05-03T00:07:11.431Z,1556842031.431 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,CB3,000,0003,FF
2019-05-03T00:07:15.066Z,1556842035.066 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.030672
2019-05-03T00:07:15.066Z,1556842035.066 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:15.066Z,1556842035.066 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:15.067Z,1556842035.067 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:15.067Z,1556842035.067 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:15.068Z,1556842035.068 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:15.490Z,1556842035.490 [DUSBL_Hydroid](INFO): USBL response received:!0000,18A,80,81,07,FF
2019-05-03T00:07:15.491Z,1556842035.491 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !0000,18A,80,81,07,FF
2019-05-03T00:07:15.516Z,1556842035.516 [Micromodem](ERROR): Response from modem unexpected: $CADQF,188,1*51

2019-05-03T00:07:15.518Z,1556842035.518 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-03T00:07:15.880Z,1556842035.880 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190503000714.521666,06,460,14,0105,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,188,0.05,-999,9760,4000*59

2019-05-03T00:07:18.743Z,1556842038.743 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:07:18.743Z,1556842038.743 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:07:18.743Z,1556842038.743 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:07:18.743Z,1556842038.743 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater] Running Loop=7
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:07:18.744Z,1556842038.744 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:07:19.106Z,1556842039.106 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.038681
2019-05-03T00:07:19.106Z,1556842039.106 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:19.106Z,1556842039.106 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:19.107Z,1556842039.107 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:19.107Z,1556842039.107 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:19.108Z,1556842039.108 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:19.515Z,1556842039.515 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,CE3,000,002BD,188,80,80,0E,FF
2019-05-03T00:07:19.515Z,1556842039.515 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-03T00:07:19.611Z,1556842039.611 [Reporter](INFO): acoustic_contact_range 4.559999 m
2019-05-03T00:07:21.934Z,1556842041.934 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:07:21.934Z,1556842041.934 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:07:21.935Z,1556842041.935 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:21.935Z,1556842041.935 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:21.935Z,1556842041.935 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:21.935Z,1556842041.935 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:21.936Z,1556842041.936 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:22.743Z,1556842042.743 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,C66,000,002BE,189,80,80,12,FF
2019-05-03T00:07:22.743Z,1556842042.743 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-03T00:07:22.782Z,1556842042.782 [Reporter](INFO): acoustic_contact_range 4.619999 m
2019-05-03T00:07:25.166Z,1556842045.166 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:25.166Z,1556842045.166 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:25.166Z,1556842045.166 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:25.167Z,1556842045.167 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:25.168Z,1556842045.168 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:25.574Z,1556842045.574 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,0A3,000,05C2E,186,80,81,04,FF
2019-05-03T00:07:25.575Z,1556842045.575 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-03T00:07:25.656Z,1556842045.656 [Reporter](INFO): acoustic_contact_range 1378.380005 m
2019-05-03T00:07:27.994Z,1556842047.994 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:07:27.994Z,1556842047.994 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:07:27.995Z,1556842047.995 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:27.995Z,1556842047.995 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:27.995Z,1556842047.995 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:27.995Z,1556842047.995 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:27.996Z,1556842047.996 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:28.406Z,1556842048.406 [DUSBL_Hydroid](INFO): USBL response received:00000,189,80,81,0B,FF
2019-05-03T00:07:28.406Z,1556842048.406 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,189,80,81,0B,FF
2019-05-03T00:07:28.418Z,1556842048.418 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-03T00:07:28.433Z,1556842048.433 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190503000727.508575,06,425,14,0099,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,196,-0.05,-999,9760,4000*77

2019-05-03T00:07:29.256Z,1556842049.256 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:07:29.256Z,1556842049.256 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:07:29.256Z,1556842049.256 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:07:29.257Z,1556842049.257 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:07:29.257Z,1556842049.257 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:07:29.257Z,1556842049.257 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:07:29.257Z,1556842049.257 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:07:29.257Z,1556842049.257 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:07:29.257Z,1556842049.257 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-03T00:07:29.257Z,1556842049.257 [DUSBL:RequestRepeater] Running Loop=8
2019-05-03T00:07:29.258Z,1556842049.258 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:07:29.258Z,1556842049.258 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:07:29.258Z,1556842049.258 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:07:29.258Z,1556842049.258 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:07:29.258Z,1556842049.258 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:07:32.034Z,1556842052.034 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.038304
2019-05-03T00:07:32.034Z,1556842052.034 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:32.034Z,1556842052.034 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:32.035Z,1556842052.035 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:32.035Z,1556842052.035 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:32.036Z,1556842052.036 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:32.439Z,1556842052.439 [DUSBL_Hydroid](INFO): USBL response received:!U000,185,80,81,05,FF
2019-05-03T00:07:32.439Z,1556842052.439 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,185,80,81,05,FF
2019-05-03T00:07:36.078Z,1556842056.078 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.042420
2019-05-03T00:07:36.078Z,1556842056.078 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:36.078Z,1556842056.078 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:36.078Z,1556842056.078 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:36.079Z,1556842056.079 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:36.080Z,1556842056.080 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:36.482Z,1556842056.482 [DUSBL_Hydroid](INFO): USBL response received:!0000,18A,80,81,04,FF
2019-05-03T00:07:36.483Z,1556842056.483 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !0000,18A,80,81,04,FF
2019-05-03T00:07:39.737Z,1556842059.737 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:07:39.737Z,1556842059.737 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:07:39.737Z,1556842059.737 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:07:39.738Z,1556842059.738 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:07:39.738Z,1556842059.738 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:07:39.738Z,1556842059.738 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:07:39.738Z,1556842059.738 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater] Running Loop=9
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:07:39.739Z,1556842059.739 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:07:40.114Z,1556842060.114 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.034903
2019-05-03T00:07:40.115Z,1556842060.115 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:40.115Z,1556842060.115 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:40.115Z,1556842060.115 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:40.115Z,1556842060.115 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:40.116Z,1556842060.116 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:40.518Z,1556842060.518 [DUSBL_Hydroid](INFO): USBL response received:!U000,185,80,81,06,FF
2019-05-03T00:07:40.519Z,1556842060.519 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,185,80,81,06,FF
2019-05-03T00:07:44.154Z,1556842064.154 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.038290
2019-05-03T00:07:44.154Z,1556842064.154 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:44.154Z,1556842064.154 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:44.154Z,1556842064.154 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:44.155Z,1556842064.155 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:44.155Z,1556842064.155 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:44.559Z,1556842064.559 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,D34,000,002B7,189,80,80,09,FF
2019-05-03T00:07:44.559Z,1556842064.559 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-03T00:07:44.566Z,1556842064.566 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190503000743.287992,06,147,15,0109,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,190,0.00,-999,9760,4000*56

2019-05-03T00:07:44.606Z,1556842064.606 [Reporter](INFO): acoustic_contact_range 4.199998 m
2019-05-03T00:07:46.982Z,1556842066.982 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:07:46.982Z,1556842066.982 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:07:46.983Z,1556842066.983 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:46.983Z,1556842066.983 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:46.983Z,1556842066.983 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:46.983Z,1556842066.983 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:46.984Z,1556842066.984 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:47.386Z,1556842067.386 [DUSBL_Hydroid](INFO): USBL response received:!U100,187,80,81,08,FF
2019-05-03T00:07:47.387Z,1556842067.387 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,187,80,81,08,FF
2019-05-03T00:07:50.245Z,1556842070.245 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:07:50.245Z,1556842070.245 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:07:50.246Z,1556842070.246 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:07:50.246Z,1556842070.246 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:07:50.246Z,1556842070.246 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:07:50.246Z,1556842070.246 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:07:50.246Z,1556842070.246 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:07:50.246Z,1556842070.246 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:07:50.247Z,1556842070.247 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-03T00:07:50.247Z,1556842070.247 [DUSBL:RequestRepeater] Running Loop=10
2019-05-03T00:07:50.247Z,1556842070.247 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-03T00:07:50.247Z,1556842070.247 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-03T00:07:50.247Z,1556842070.247 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-03T00:07:50.247Z,1556842070.247 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-03T00:07:50.247Z,1556842070.247 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:07:51.030Z,1556842071.030 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.046195
2019-05-03T00:07:51.030Z,1556842071.030 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:51.030Z,1556842071.030 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:51.030Z,1556842071.030 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:51.031Z,1556842071.031 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:51.032Z,1556842071.032 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:51.426Z,1556842071.426 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,26D,000,00327,189,80,80,09,FF
2019-05-03T00:07:51.427Z,1556842071.427 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-03T00:07:51.482Z,1556842071.482 [Reporter](INFO): acoustic_contact_range 10.920002 m
2019-05-03T00:07:53.858Z,1556842073.858 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-03T00:07:53.858Z,1556842073.858 [DUSBL_Hydroid](INFO): Command Ack
2019-05-03T00:07:53.858Z,1556842073.858 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:53.859Z,1556842073.859 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:53.859Z,1556842073.859 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:53.859Z,1556842073.859 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:53.860Z,1556842073.860 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:54.255Z,1556842074.255 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,187,80,81,07,FF
2019-05-03T00:07:54.255Z,1556842074.255 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,187,80,81,07,FF
2019-05-03T00:07:57.890Z,1556842077.890 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:4.030631
2019-05-03T00:07:57.891Z,1556842077.891 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-03T00:07:57.891Z,1556842077.891 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-03T00:07:57.891Z,1556842077.891 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-03T00:07:57.891Z,1556842077.891 [DUSBL_Hydroid](DEBUG): Arming DUSBL
2019-05-03T00:07:57.892Z,1556842077.892 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-03T00:07:58.299Z,1556842078.299 [DUSBL_Hydroid](INFO): USBL response received:00000,187,80,81,05,FF
2019-05-03T00:07:58.299Z,1556842078.299 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,05,FF
2019-05-03T00:08:00.759Z,1556842080.759 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-03T00:08:00.759Z,1556842080.759 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-03T00:08:00.759Z,1556842080.759 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:08:00.760Z,1556842080.760 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-03T00:08:00.760Z,1556842080.760 [DUSBL:RequestRepeater] Stopped
2019-05-03T00:08:00.760Z,1556842080.760 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-03T00:08:00.760Z,1556842080.760 [DUSBL:RequestRepeater:A] Stopped
2019-05-03T00:08:00.760Z,1556842080.760 [DUSBL:RequestRepeater:B] Stopped
2019-05-03T00:08:00.762Z,1556842080.762 [DUSBL](INFO): Completed DUSBL
2019-05-03T00:08:00.762Z,1556842080.762 [MissionManager](INFO): DUSBL is completed.
2019-05-03T00:08:00.762Z,1556842080.762 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-03T00:08:00.762Z,1556842080.762 [DUSBL] Stopped
2019-05-03T00:08:00.762Z,1556842080.762 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-03T00:08:00.762Z,1556842080.762 [DUSBL:A.Pitch] Stopped
2019-05-03T00:08:00.763Z,1556842080.763 [DUSBL:B.SetSpeed] Stopped
2019-05-03T00:08:00.763Z,1556842080.763 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-03T00:08:00.763Z,1556842080.763 [DUSBL:C] Stopped
2019-05-03T00:08:01.160Z,1556842081.160 [MissionManager](IMPORTANT): Started mission Default
2019-05-03T00:08:01.160Z,1556842081.160 [Default] Running Loop=1
2019-05-03T00:08:01.160Z,1556842081.160 [Default](DEBUG): Aggregate::initialize Default
2019-05-03T00:08:01.160Z,1556842081.160 [Default:B.GoToSurface] Running Loop=1
2019-05-03T00:08:01.160Z,1556842081.160 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-03T00:08:01.161Z,1556842081.161 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-03T00:08:01.161Z,1556842081.161 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-03T00:08:01.161Z,1556842081.161 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-03T00:08:01.162Z,1556842081.162 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-03T00:08:01.162Z,1556842081.162 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-03T00:08:01.162Z,1556842081.162 [Default:A.Wait] Running Loop=1
2019-05-03T00:08:01.162Z,1556842081.162 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:08:14.484Z,1556842094.484 [Default:A.Wait](INFO): Done Waiting.
2019-05-03T00:08:14.484Z,1556842094.484 [Default:A.Wait] Stopped
2019-05-03T00:08:14.484Z,1556842094.484 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:08:14.896Z,1556842094.896 [Default:CheckIn] Running Loop=1
2019-05-03T00:08:14.896Z,1556842094.896 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-03T00:08:14.896Z,1556842094.896 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-03T00:08:16.489Z,1556842096.489 [NAL9602](DEBUG): Fix Requested
2019-05-03T00:08:16.880Z,1556842096.880 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000743.00,A,3648.16895,N,12147.27687,W,0.272,21.47,030519,,,A*42
2019-05-03T00:08:16.882Z,1556842096.882 [NAL9602](INFO): GPS fix at 20190503T000743: (36.802816, -121.787948)
2019-05-03T00:08:16.912Z,1556842096.912 [Default:CheckIn:Read_GPS] Stopped
2019-05-03T00:08:16.912Z,1556842096.912 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-03T00:08:17.330Z,1556842097.330 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-03T00:08:22.567Z,1556842102.567 [DataOverHttps](INFO): Sending 301 bytes from file Logs/20190502T235918/Courier0004.lzma
2019-05-03T00:08:23.370Z,1556842103.370 [DataOverHttps](INFO): Moved sent file to Logs/20190502T235918/Courier0004.lzma.bak
2019-05-03T00:08:23.370Z,1556842103.371 [DataOverHttps](INFO): SBD MOMSN=10914233
2019-05-03T00:08:35.043Z,1556842115.043 [DataOverHttps](INFO): Sending 1258 bytes from file Logs/20190502T235918/Express0005.lzma
2019-05-03T00:08:35.846Z,1556842115.846 [DataOverHttps](INFO): Moved sent file to Logs/20190502T235918/Express0005.lzma.bak
2019-05-03T00:08:35.847Z,1556842115.847 [DataOverHttps](INFO): SBD MOMSN=10914236
2019-05-03T00:08:36.780Z,1556842116.780 [Default:CheckIn:Read_Iridium] Stopped
2019-05-03T00:08:36.780Z,1556842116.780 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-03T00:08:36.780Z,1556842116.780 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-03T00:08:50.904Z,1556842130.904 [NAL9602](INFO): SBD MO Status=2, MOMSN=3796, MT Status=2, MTMSN=0
2019-05-03T00:08:50.904Z,1556842130.904 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-03T00:09:17.160Z,1556842157.160 [NAL9602](INFO): SBD MO Status=2, MOMSN=3796, MT Status=2, MTMSN=0
2019-05-03T00:09:17.160Z,1556842157.160 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-03T00:11:58.398Z,1556842318.398 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-03T00:11:58.398Z,1556842318.398 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190502172032390.1,   0.0,1448.9,  0
2019-05-03T00:12:19.795Z,1556842339.795 [NAL9602](INFO): SBD MO Status=2, MOMSN=3796, MT Status=2, MTMSN=0
2019-05-03T00:12:19.795Z,1556842339.795 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-03T00:13:05.453Z,1556842385.453 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-03T00:13:05.454Z,1556842385.454 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-03T00:13:15.302Z,1556842395.302 [CommandLine](IMPORTANT): got command restart application
2019-05-03T00:13:16.305Z,1556842396.305 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-03T00:13:16.305Z,1556842396.305 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:16.305Z,1556842396.305 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.489Z,1556842396.489 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-03T00:13:16.489Z,1556842396.489 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.490Z,1556842396.490 [CommandLine](INFO): Join timeout helper Thread ID is 9428
2019-05-03T00:13:16.490Z,1556842396.490 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-03T00:13:16.490Z,1556842396.490 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.491Z,1556842396.491 [NavChartDb](INFO): Join timeout helper Thread ID is 9429
2019-05-03T00:13:16.697Z,1556842396.697 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:16.697Z,1556842396.697 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.709Z,1556842396.709 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-03T00:13:16.709Z,1556842396.709 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.709Z,1556842396.709 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 9430
2019-05-03T00:13:16.785Z,1556842396.785 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:16.786Z,1556842396.786 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-03T00:13:16.786Z,1556842396.786 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.793Z,1556842396.793 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-03T00:13:16.793Z,1556842396.793 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.793Z,1556842396.793 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 9431
2019-05-03T00:13:16.805Z,1556842396.805 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:16.805Z,1556842396.805 [CTD_NeilBrown](INFO): Powering down
2019-05-03T00:13:16.817Z,1556842396.817 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.833Z,1556842396.833 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-03T00:13:16.833Z,1556842396.833 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:16.833Z,1556842396.833 [Radio_Surface](INFO): Join timeout helper Thread ID is 9432
2019-05-03T00:13:17.189Z,1556842397.189 [Radio_Surface](INFO): Powering down
2019-05-03T00:13:17.190Z,1556842397.190 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:17.190Z,1556842397.190 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.210Z,1556842397.210 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-03T00:13:17.210Z,1556842397.210 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.210Z,1556842397.210 [DataOverHttps](INFO): Join timeout helper Thread ID is 9433
2019-05-03T00:13:17.225Z,1556842397.225 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:17.225Z,1556842397.225 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.238Z,1556842397.238 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-03T00:13:17.238Z,1556842397.238 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.238Z,1556842397.238 [logger](INFO): Join timeout helper Thread ID is 9434
2019-05-03T00:13:17.275Z,1556842397.275 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:17.275Z,1556842397.275 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.286Z,1556842397.286 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-03T00:13:17.286Z,1556842397.286 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.286Z,1556842397.286 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-03T00:13:17.286Z,1556842397.286 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.286Z,1556842397.286 [controlThread](INFO): Join timeout helper Thread ID is 9435
2019-05-03T00:13:17.537Z,1556842397.537 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-03T00:13:17.537Z,1556842397.537 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-03T00:13:17.538Z,1556842397.538 [AHRS_M2](INFO): Powering down
2019-05-03T00:13:17.610Z,1556842397.610 [DUSBL_Hydroid](INFO): Powering down
2019-05-03T00:13:17.681Z,1556842397.681 [Micromodem](INFO): Powering down
2019-05-03T00:13:17.777Z,1556842397.777 [NAL9602](INFO): Powering down
2019-05-03T00:13:17.849Z,1556842397.849 [RDI_Pathfinder](INFO): Powering down
2019-05-03T00:13:17.850Z,1556842397.850 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-03T00:13:17.851Z,1556842397.851 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-03T00:13:17.851Z,1556842397.851 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-03T00:13:17.852Z,1556842397.852 [MissionManager](INFO): Uninitializing Mission Default
2019-05-03T00:13:17.852Z,1556842397.852 [Default] Stopped
2019-05-03T00:13:17.852Z,1556842397.852 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-03T00:13:17.852Z,1556842397.852 [Default:B.GoToSurface] Stopped
2019-05-03T00:13:17.852Z,1556842397.852 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-03T00:13:17.852Z,1556842397.852 [Default:CheckIn] Stopped
2019-05-03T00:13:17.853Z,1556842397.853 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-03T00:13:17.853Z,1556842397.853 [Default:CheckIn:C.Wait] Stopped
2019-05-03T00:13:17.853Z,1556842397.853 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-03T00:13:17.855Z,1556842397.855 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-03T00:13:17.855Z,1556842397.855 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-03T00:13:17.856Z,1556842397.856 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-03T00:13:17.856Z,1556842397.856 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-03T00:13:17.856Z,1556842397.856 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-03T00:13:17.856Z,1556842397.856 [BuoyancyServo](INFO): Powering down
2019-05-03T00:13:17.869Z,1556842397.869 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-03T00:13:17.869Z,1556842397.869 [ElevatorServo](INFO): Powering down
2019-05-03T00:13:17.870Z,1556842397.870 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-03T00:13:17.870Z,1556842397.870 [MassServo](INFO): Powering down
2019-05-03T00:13:17.871Z,1556842397.871 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-03T00:13:17.871Z,1556842397.871 [RudderServo](INFO): Powering down
2019-05-03T00:13:17.872Z,1556842397.872 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-03T00:13:17.872Z,1556842397.872 [ThrusterServo](INFO): Powering down
2019-05-03T00:13:17.872Z,1556842397.872 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-03T00:13:17.873Z,1556842397.873 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-03T00:13:17.873Z,1556842397.873 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-03T00:13:17.873Z,1556842397.873 [CBIT](DEBUG): Powering off loads.
2019-05-03T00:13:17.885Z,1556842397.885 [CBIT](DEBUG): Disabling WDT.
2019-05-03T00:13:17.897Z,1556842397.897 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-03T00:13:17.898Z,1556842397.898 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.941Z,1556842397.941 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.950Z,1556842397.950 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.994Z,1556842397.994 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:17.996Z,1556842397.996 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:18.050Z,1556842398.050 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-03T00:13:18.120Z,1556842398.120 [logger ThreadHandler](INFO): Thread cancelled.