2019-05-07T21:10:26.098Z,1557263426.098 [Supervisor](DEBUG): Initializing supervisor.
2019-05-07T21:10:26.101Z,1557263426.101 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-07T21:10:26.101Z,1557263426.101 [SyncHandler](INFO): Protected caller Thread ID is 4564
2019-05-07T21:10:26.102Z,1557263426.102 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-07T21:10:26.103Z,1557263426.103 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-07T21:10:26.104Z,1557263426.104 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 4565
2019-05-07T21:10:26.107Z,1557263426.107 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-07T21:10:26.119Z,1557263426.119 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-07T21:10:26.120Z,1557263426.120 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-07T21:10:26.121Z,1557263426.121 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 4566
2019-05-07T21:10:26.121Z,1557263426.121 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-07T21:10:26.122Z,1557263426.122 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-07T21:10:26.123Z,1557263426.123 [logger ThreadHandler](INFO): Protected caller Thread ID is 4567
2019-05-07T21:10:26.125Z,1557263426.125 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-07T21:10:26.125Z,1557263426.125 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-07T21:10:26.127Z,1557263426.127 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-07T21:10:26.559Z,1557263426.559 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-07T21:10:26.560Z,1557263426.560 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-07T21:10:26.659Z,1557263426.659 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-07T21:10:26.659Z,1557263426.659 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-07T21:10:26.993Z,1557263426.993 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-07T21:10:26.994Z,1557263426.994 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-07T21:10:27.251Z,1557263427.251 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-07T21:10:27.252Z,1557263427.252 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-07T21:10:27.443Z,1557263427.443 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-07T21:10:27.444Z,1557263427.444 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-07T21:10:27.899Z,1557263427.899 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-07T21:10:27.900Z,1557263427.900 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-07T21:10:28.110Z,1557263428.110 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-07T21:10:28.111Z,1557263428.111 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-07T21:10:28.258Z,1557263428.258 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-07T21:10:28.258Z,1557263428.258 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-07T21:10:28.454Z,1557263428.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-07T21:10:28.454Z,1557263428.454 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-07T21:10:28.551Z,1557263428.551 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-07T21:10:28.552Z,1557263428.552 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-07T21:10:28.875Z,1557263428.875 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-07T21:10:28.876Z,1557263428.876 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-07T21:10:28.957Z,1557263428.957 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-07T21:10:29.061Z,1557263429.061 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-07T21:10:29.061Z,1557263429.061 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-07T21:10:29.638Z,1557263429.638 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-07T21:10:29.639Z,1557263429.639 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-07T21:10:30.032Z,1557263430.032 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-07T21:10:30.034Z,1557263430.034 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-07T21:10:30.035Z,1557263430.035 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-07T21:10:30.244Z,1557263430.244 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-07T21:10:30.345Z,1557263430.345 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-07T21:10:30.444Z,1557263430.444 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-07T21:10:30.671Z,1557263430.671 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-07T21:10:30.671Z,1557263430.671 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-07T21:10:30.757Z,1557263430.757 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-07T21:10:30.851Z,1557263430.851 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-07T21:10:30.948Z,1557263430.948 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-07T21:10:31.032Z,1557263431.032 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-07T21:10:31.141Z,1557263431.141 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-07T21:10:31.312Z,1557263431.312 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-07T21:10:31.444Z,1557263431.444 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-07T21:10:31.445Z,1557263431.445 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-07T21:10:31.458Z,1557263431.458 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-07T21:10:31.838Z,1557263431.838 [AHRS_M2] Loaded
2019-05-07T21:10:31.838Z,1557263431.838 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-07T21:10:31.911Z,1557263431.911 [DataOverHttps] Loaded
2019-05-07T21:10:31.912Z,1557263431.912 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-07T21:10:31.913Z,1557263431.913 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-07T21:10:31.913Z,1557263431.913 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 4646
2019-05-07T21:10:31.926Z,1557263431.926 [Depth_Keller] Loaded
2019-05-07T21:10:31.926Z,1557263431.926 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-07T21:10:31.931Z,1557263431.931 [DropWeight] Loaded
2019-05-07T21:10:31.931Z,1557263431.931 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-07T21:10:31.987Z,1557263431.987 [DUSBL_Hydroid] Loaded
2019-05-07T21:10:31.988Z,1557263431.988 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-07T21:10:32.027Z,1557263432.027 [Micromodem] Loaded
2019-05-07T21:10:32.027Z,1557263432.027 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-07T21:10:32.166Z,1557263432.166 [NAL9602] Loaded
2019-05-07T21:10:32.166Z,1557263432.166 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-07T21:10:32.182Z,1557263432.182 [Onboard] Loaded
2019-05-07T21:10:32.182Z,1557263432.182 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-07T21:10:32.188Z,1557263432.188 [PowerOnly] Loaded
2019-05-07T21:10:32.188Z,1557263432.188 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-07T21:10:32.199Z,1557263432.199 [Radio_Surface] Loaded
2019-05-07T21:10:32.199Z,1557263432.199 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-07T21:10:32.201Z,1557263432.201 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-07T21:10:32.201Z,1557263432.201 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 4647
2019-05-07T21:10:32.283Z,1557263432.283 [RDI_Pathfinder] Loaded
2019-05-07T21:10:32.291Z,1557263432.291 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-07T21:10:34.234Z,1557263434.234 [BPC1] Loaded
2019-05-07T21:10:34.235Z,1557263434.235 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-07T21:10:34.235Z,1557263434.235 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-07T21:10:34.236Z,1557263434.236 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-07T21:10:34.248Z,1557263434.248 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-07T21:10:34.249Z,1557263434.249 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-07T21:10:34.354Z,1557263434.354 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-07T21:10:34.354Z,1557263434.354 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-07T21:10:34.375Z,1557263434.375 [NavChart] Loaded
2019-05-07T21:10:34.375Z,1557263434.375 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-07T21:10:34.379Z,1557263434.379 [UniversalFixResidualReporter] Loaded
2019-05-07T21:10:34.379Z,1557263434.379 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-07T21:10:34.380Z,1557263434.380 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-07T21:10:34.380Z,1557263434.380 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-07T21:10:34.488Z,1557263434.488 [BuoyancyServo] Loaded
2019-05-07T21:10:34.488Z,1557263434.488 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-07T21:10:34.503Z,1557263434.503 [ElevatorServo] Loaded
2019-05-07T21:10:34.503Z,1557263434.503 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-07T21:10:34.518Z,1557263434.518 [MassServo] Loaded
2019-05-07T21:10:34.519Z,1557263434.519 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-07T21:10:34.533Z,1557263434.533 [RudderServo] Loaded
2019-05-07T21:10:34.534Z,1557263434.534 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-07T21:10:34.548Z,1557263434.548 [ThrusterServo] Loaded
2019-05-07T21:10:34.548Z,1557263434.548 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-07T21:10:34.549Z,1557263434.549 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-07T21:10:34.549Z,1557263434.549 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-07T21:10:34.795Z,1557263434.795 [CTD_NeilBrown] Loaded
2019-05-07T21:10:34.795Z,1557263434.795 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-07T21:10:34.796Z,1557263434.796 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-07T21:10:34.797Z,1557263434.797 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 4648
2019-05-07T21:10:34.840Z,1557263434.840 [WetLabsSeaOWL_UV_A] Loaded
2019-05-07T21:10:34.841Z,1557263434.841 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-07T21:10:34.842Z,1557263434.842 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-07T21:10:34.842Z,1557263434.842 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 4649
2019-05-07T21:10:34.843Z,1557263434.843 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-07T21:10:34.843Z,1557263434.843 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-07T21:10:35.132Z,1557263435.132 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-07T21:10:35.132Z,1557263435.132 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-07T21:10:35.172Z,1557263435.172 [DepthRateCalculator] Loaded
2019-05-07T21:10:35.172Z,1557263435.172 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-07T21:10:35.178Z,1557263435.178 [PitchRateCalculator] Loaded
2019-05-07T21:10:35.178Z,1557263435.178 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-07T21:10:35.191Z,1557263435.191 [SpeedCalculator] Loaded
2019-05-07T21:10:35.191Z,1557263435.191 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-07T21:10:35.211Z,1557263435.211 [TempGradientCalculator] Loaded
2019-05-07T21:10:35.212Z,1557263435.212 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-07T21:10:35.217Z,1557263435.217 [YawRateCalculator] Loaded
2019-05-07T21:10:35.218Z,1557263435.218 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-07T21:10:35.258Z,1557263435.258 [ElevatorOffsetCalculator] Loaded
2019-05-07T21:10:35.258Z,1557263435.258 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-07T21:10:35.258Z,1557263435.258 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-07T21:10:35.259Z,1557263435.259 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-07T21:10:35.394Z,1557263435.394 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-07T21:10:35.416Z,1557263435.416 [SBIT] Loaded
2019-05-07T21:10:35.416Z,1557263435.416 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-07T21:10:35.417Z,1557263435.417 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-07T21:10:35.428Z,1557263435.428 [IBIT] Loaded
2019-05-07T21:10:35.428Z,1557263435.428 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-07T21:10:35.432Z,1557263435.432 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-07T21:10:35.569Z,1557263435.569 [CBIT] Loaded
2019-05-07T21:10:35.569Z,1557263435.569 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-07T21:10:35.569Z,1557263435.569 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-07T21:10:35.570Z,1557263435.570 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-07T21:10:35.640Z,1557263435.640 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-07T21:10:35.641Z,1557263435.641 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-07T21:10:35.738Z,1557263435.738 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-07T21:10:35.739Z,1557263435.739 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-07T21:10:35.804Z,1557263435.804 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-07T21:10:35.888Z,1557263435.888 [VerticalControl] Loaded
2019-05-07T21:10:35.888Z,1557263435.888 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-07T21:10:35.889Z,1557263435.889 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-07T21:10:35.947Z,1557263435.947 [HorizontalControl] Loaded
2019-05-07T21:10:35.947Z,1557263435.947 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-07T21:10:35.947Z,1557263435.947 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-07T21:10:35.949Z,1557263435.949 [SpeedControl] Loaded
2019-05-07T21:10:35.949Z,1557263435.949 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-07T21:10:35.950Z,1557263435.950 [LoopControl](DEBUG): Construct LoopControl.
2019-05-07T21:10:35.951Z,1557263435.951 [LoopControl] Loaded
2019-05-07T21:10:35.951Z,1557263435.951 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-07T21:10:35.951Z,1557263435.951 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-07T21:10:35.952Z,1557263435.952 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-07T21:10:35.978Z,1557263435.978 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-07T21:10:35.982Z,1557263435.982 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-07T21:10:35.983Z,1557263435.983 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-07T21:10:35.989Z,1557263435.989 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-07T21:10:35.991Z,1557263435.991 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-07T21:10:35.991Z,1557263435.991 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 4650
2019-05-07T21:10:35.996Z,1557263435.996 [Supervisor](INFO): Main Thread ID is 802
2019-05-07T21:10:35.996Z,1557263435.996 [Supervisor](DEBUG): Running supervisor.
2019-05-07T21:10:35.996Z,1557263435.996 [CommandLine ThreadHandler](INFO): Handler Thread ID is 4651
2019-05-07T21:10:35.999Z,1557263435.999 [controlThread ThreadHandler](INFO): Handler Thread ID is 4652
2019-05-07T21:10:35.999Z,1557263435.999 [controlThread](DEBUG): Initializing ControlThread
2019-05-07T21:10:36.005Z,1557263436.005 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-07T21:10:36.006Z,1557263436.006 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-07T21:10:36.007Z,1557263436.007 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-07T21:10:36.007Z,1557263436.007 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-07T21:10:36.007Z,1557263436.007 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-07T21:10:36.008Z,1557263436.008 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-07T21:10:36.008Z,1557263436.008 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-07T21:10:36.009Z,1557263436.009 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-07T21:10:36.009Z,1557263436.009 [SBIT](INFO): Initialize SBIT Component.
2019-05-07T21:10:36.009Z,1557263436.009 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-07T21:10:36.010Z,1557263436.010 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-07T21:10:36.010Z,1557263436.010 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-07T21:10:36.011Z,1557263436.011 [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-07T21:10:36.012Z,1557263436.012 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-07T21:10:36.013Z,1557263436.013 [IBIT](INFO): Initialize IBIT Component.
2019-05-07T21:10:36.014Z,1557263436.014 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-07T21:10:36.015Z,1557263436.015 [logger ThreadHandler](INFO): Handler Thread ID is 4653
2019-05-07T21:10:36.026Z,1557263436.026 [CBIT](DEBUG): Initialized mux pins.
2019-05-07T21:10:36.026Z,1557263436.026 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-07T21:10:36.035Z,1557263436.035 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 4654
2019-05-07T21:10:36.036Z,1557263436.036 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-07T21:10:36.047Z,1557263436.047 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 4655
2019-05-07T21:10:36.050Z,1557263436.050 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-07T21:10:36.050Z,1557263436.050 [CBIT](DEBUG): Initializing heartbeat.
2019-05-07T21:10:36.059Z,1557263436.059 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 4656
2019-05-07T21:10:36.060Z,1557263436.060 [CTD_NeilBrown](INFO): Powering down
2019-05-07T21:10:36.087Z,1557263436.087 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 4657
2019-05-07T21:10:36.087Z,1557263436.087 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T21:10:36.119Z,1557263436.119 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 4658
2019-05-07T21:10:36.122Z,1557263436.122 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-07T21:10:36.122Z,1557263436.122 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-07T21:10:36.123Z,1557263436.123 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-07T21:10:36.123Z,1557263436.123 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-07T21:10:36.123Z,1557263436.123 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-07T21:10:36.124Z,1557263436.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-07T21:10:36.124Z,1557263436.124 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-07T21:10:36.124Z,1557263436.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-07T21:10:36.124Z,1557263436.124 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-07T21:10:36.124Z,1557263436.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-07T21:10:36.125Z,1557263436.125 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-07T21:10:36.125Z,1557263436.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-07T21:10:36.125Z,1557263436.125 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-07T21:10:36.125Z,1557263436.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-07T21:10:36.125Z,1557263436.125 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-07T21:10:36.125Z,1557263436.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-07T21:10:36.126Z,1557263436.126 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-07T21:10:36.126Z,1557263436.126 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-07T21:10:36.158Z,1557263436.158 [CBIT](DEBUG): Backplane powered.
2019-05-07T21:10:36.159Z,1557263436.159 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-07T21:10:36.160Z,1557263436.160 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-07T21:10:36.161Z,1557263436.161 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-07T21:10:36.161Z,1557263436.161 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-07T21:10:36.162Z,1557263436.162 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-07T21:10:36.172Z,1557263436.172 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T21:10:36.195Z,1557263436.195 [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-07T21:10:36.196Z,1557263436.196 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-07T21:10:36.271Z,1557263436.271 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-07T21:10:36.272Z,1557263436.272 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-07T21:10:36.273Z,1557263436.273 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T21:10:36.292Z,1557263436.292 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-07T21:10:36.319Z,1557263436.319 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-07T21:10:36.324Z,1557263436.324 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-07T21:10:36.344Z,1557263436.344 [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-07T21:10:36.348Z,1557263436.348 [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-07T21:10:36.358Z,1557263436.358 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-07T21:10:36.388Z,1557263436.388 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-07T21:10:36.389Z,1557263436.389 [DUSBL_Hydroid](INFO): Powering up
2019-05-07T21:10:36.389Z,1557263436.389 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-07T21:10:36.450Z,1557263436.450 [Radio_Surface](INFO): Powering up
2019-05-07T21:10:36.471Z,1557263436.471 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T21:10:36.481Z,1557263436.481 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:10:36.487Z,1557263436.487 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-07T21:10:36.488Z,1557263436.488 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:10:36.503Z,1557263436.503 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-07T21:10:36.503Z,1557263436.503 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:10:36.511Z,1557263436.511 [MassServo](DEBUG): Initializing MassServo.
2019-05-07T21:10:36.512Z,1557263436.512 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:10:36.523Z,1557263436.523 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T21:10:36.523Z,1557263436.523 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:10:36.531Z,1557263436.531 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-07T21:10:36.772Z,1557263436.772 [Micromodem](INFO): Powering up
2019-05-07T21:10:36.773Z,1557263436.773 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-07T21:10:36.810Z,1557263436.810 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T21:10:49.714Z,1557263449.714 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T21:10:52.924Z,1557263452.924 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-05-07T21:10:54.536Z,1557263454.536 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-07T21:11:02.214Z,1557263462.214 [NAL9602](INFO): Powering up NAL9602
2019-05-07T21:11:04.232Z,1557263464.232 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-05-07T21:11:13.121Z,1557263473.121 [NAL9602](INFO): NAL9602 initialized
2019-05-07T21:11:13.942Z,1557263473.942 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:11:19.628Z,1557263479.628 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-05-07T21:11:19.628Z,1557263479.628 [RDI_Pathfinder](ERROR): Failed to parse:
:BS   -41,   +10,A
2019-05-07T21:11:20.436Z,1557263480.436 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-07T21:11:20.445Z,1557263480.445 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-07T21:11:31.499Z,1557263491.499 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.023328
CHAN A1 (24V): -0.026500
CHAN A2 (12V): -0.006655
CHAN A3 (5V): -0.002227
CHAN B0 (3.3V): 0.000076
CHAN B1 (3.15aV): 0.000442
CHAN B2 (3.15bV): 0.000146
CHAN B3 (GND): 0.001957
OPEN: 0.006625
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-07T21:12:14.068Z,1557263534.068 [SBIT](IMPORTANT): SBIT PASSED
2019-05-07T21:12:14.166Z,1557263534.166 [CommandLine](IMPORTANT): got command configSet list
2019-05-07T21:12:14.167Z,1557263534.167 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-07T21:12:14.168Z,1557263534.168 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-07T21:12:14.168Z,1557263534.168 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-07T21:12:14.168Z,1557263534.168 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-07T21:12:14.168Z,1557263534.168 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-07T21:12:14.168Z,1557263534.168 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-07T21:12:14.168Z,1557263534.168 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-07T21:12:14.168Z,1557263534.168 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-07T21:12:14.169Z,1557263534.169 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-07T21:12:14.169Z,1557263534.169 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-07T21:12:14.169Z,1557263534.169 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-07T21:12:14.169Z,1557263534.169 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-07T21:12:14.169Z,1557263534.169 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-07T21:12:14.169Z,1557263534.169 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-07T21:12:14.464Z,1557263534.464 [MissionManager](IMPORTANT): Started mission Startup
2019-05-07T21:12:14.464Z,1557263534.464 [Startup] Running Loop=1
2019-05-07T21:12:14.464Z,1557263534.464 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-07T21:12:14.464Z,1557263534.464 [Startup:A.GoToSurface] Running Loop=1
2019-05-07T21:12:14.464Z,1557263534.464 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:12:14.465Z,1557263534.465 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:12:14.465Z,1557263534.465 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:12:14.466Z,1557263534.466 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:12:14.466Z,1557263534.466 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:12:14.467Z,1557263534.467 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:12:14.468Z,1557263534.468 [Startup:StartupSatComms] Running Loop=1
2019-05-07T21:12:14.468Z,1557263534.468 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-07T21:12:14.468Z,1557263534.468 [Startup:StartupSatComms:A] Running Loop=1
2019-05-07T21:12:14.904Z,1557263534.904 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-07T21:13:02.377Z,1557263582.377 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004935
2019-05-07T21:13:06.980Z,1557263586.980 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T21:13:06.980Z,1557263586.980 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050714205134,35.0, -0.1,   0.0,1448.9A,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T21:13:14.688Z,1557263594.688 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-07T21:12:14.5Z
2019-05-07T21:13:14.688Z,1557263594.688 [Startup:StartupSatComms:A] Stopped
2019-05-07T21:13:14.688Z,1557263594.688 [Startup:StartupSatComms:B] Running Loop=1
2019-05-07T21:13:15.078Z,1557263595.078 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T21:13:20.150Z,1557263600.150 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190507T210343/Courier0004.lzma
2019-05-07T21:13:20.956Z,1557263600.956 [DataOverHttps](INFO): Moved sent file to Logs/20190507T210343/Courier0004.lzma.bak
2019-05-07T21:13:20.956Z,1557263600.956 [DataOverHttps](INFO): SBD MOMSN=10958984
2019-05-07T21:13:32.639Z,1557263612.639 [DataOverHttps](INFO): Sending 467 bytes from file Logs/20190507T165739/Express0143.lzma
2019-05-07T21:13:33.444Z,1557263613.444 [DataOverHttps](INFO): Moved sent file to Logs/20190507T165739/Express0143.lzma.bak
2019-05-07T21:13:33.444Z,1557263613.444 [DataOverHttps](INFO): SBD MOMSN=10958987
2019-05-07T21:13:34.839Z,1557263614.839 [NAL9602](INFO): SBD MO Status=0, MOMSN=3871, MT Status=0, MTMSN=0
2019-05-07T21:13:34.839Z,1557263614.839 [NAL9602](INFO): No messages in MT queue
2019-05-07T21:13:35.662Z,1557263615.662 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:36.098Z,1557263616.098 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-07T21:13:36.098Z,1557263616.098 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T21:13:36.117Z,1557263616.117 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T21:13:36.516Z,1557263616.516 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T21:13:36.516Z,1557263616.516 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-07T21:13:38.082Z,1557263618.082 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:40.922Z,1557263620.922 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:44.146Z,1557263624.146 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:45.284Z,1557263625.284 [DataOverHttps](INFO): Sending 1597 bytes from file Logs/20190507T210343/Express0001.lzma
2019-05-07T21:13:46.088Z,1557263626.088 [DataOverHttps](INFO): Moved sent file to Logs/20190507T210343/Express0001.lzma.bak
2019-05-07T21:13:46.088Z,1557263626.088 [DataOverHttps](INFO): SBD MOMSN=10958991
2019-05-07T21:13:46.970Z,1557263626.970 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:48.000Z,1557263629.000 [RDI_Pathfinder](ERROR): Failed to parse:
:0,   0.00,   0.00,   0.00,   0.00
2019-05-07T21:13:50.218Z,1557263630.218 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:53.034Z,1557263633.034 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:56.266Z,1557263636.266 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:13:57.790Z,1557263637.790 [DataOverHttps](INFO): Sending 920 bytes from file Logs/20190507T210343/Express0005.lzma
2019-05-07T21:13:58.593Z,1557263638.593 [DataOverHttps](INFO): Moved sent file to Logs/20190507T210343/Express0005.lzma.bak
2019-05-07T21:13:58.593Z,1557263638.593 [DataOverHttps](INFO): SBD MOMSN=10959033
2019-05-07T21:13:59.098Z,1557263639.098 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:01.918Z,1557263641.918 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:05.154Z,1557263645.154 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:08.006Z,1557263648.006 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:10.508Z,1557263650.508 [DataOverHttps](INFO): Sending 1289 bytes from file Logs/20190507T211026/Express0001.lzma
2019-05-07T21:14:11.214Z,1557263651.214 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:11.312Z,1557263651.312 [DataOverHttps](INFO): Moved sent file to Logs/20190507T211026/Express0001.lzma.bak
2019-05-07T21:14:11.312Z,1557263651.312 [DataOverHttps](INFO): SBD MOMSN=10959049
2019-05-07T21:14:12.558Z,1557263652.558 [Startup:StartupSatComms:B] Stopped
2019-05-07T21:14:12.559Z,1557263652.559 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-07T21:14:12.559Z,1557263652.559 [Startup:StartupSatComms] Stopped
2019-05-07T21:14:12.559Z,1557263652.559 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-07T21:14:12.559Z,1557263652.559 [Startup](INFO): Completed Startup
2019-05-07T21:14:12.560Z,1557263652.560 [MissionManager](INFO): Startup is completed.
2019-05-07T21:14:12.560Z,1557263652.560 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-07T21:14:12.560Z,1557263652.560 [Startup] Stopped
2019-05-07T21:14:12.560Z,1557263652.560 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-07T21:14:12.560Z,1557263652.560 [Startup:A.GoToSurface] Stopped
2019-05-07T21:14:12.560Z,1557263652.560 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T21:14:12.869Z,1557263652.869 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T21:14:12.869Z,1557263652.869 [Default] Running Loop=1
2019-05-07T21:14:12.869Z,1557263652.869 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T21:14:12.869Z,1557263652.869 [Default:B.GoToSurface] Running Loop=1
2019-05-07T21:14:12.869Z,1557263652.869 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:14:12.870Z,1557263652.870 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:14:12.870Z,1557263652.870 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:14:12.871Z,1557263652.871 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:14:12.871Z,1557263652.871 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:14:12.871Z,1557263652.871 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:14:12.872Z,1557263652.872 [Default:A.Wait] Running Loop=1
2019-05-07T21:14:12.872Z,1557263652.872 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:14:14.038Z,1557263654.038 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:17.274Z,1557263657.274 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:20.113Z,1557263660.113 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:22.938Z,1557263662.938 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:25.873Z,1557263665.873 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T21:14:25.873Z,1557263665.873 [Default:A.Wait] Stopped
2019-05-07T21:14:25.873Z,1557263665.873 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:14:26.166Z,1557263666.166 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:26.195Z,1557263666.195 [Default:CheckIn] Running Loop=1
2019-05-07T21:14:26.196Z,1557263666.196 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T21:14:26.196Z,1557263666.196 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T21:14:26.627Z,1557263666.627 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-07T21:14:28.994Z,1557263668.994 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:32.218Z,1557263672.218 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:35.046Z,1557263675.046 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:37.503Z,1557263677.503 [CommandLine](IMPORTANT): got command show variable range
2019-05-07T21:14:37.506Z,1557263677.506 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-07T21:14:37.648Z,1557263677.648 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-07T21:14:37.648Z,1557263677.648 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-07T21:14:37.665Z,1557263677.665 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-07T21:14:37.666Z,1557263677.666 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-07T21:14:37.667Z,1557263677.667 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-07T21:14:37.669Z,1557263677.669 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-07T21:14:37.670Z,1557263677.670 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-07T21:14:37.670Z,1557263677.670 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-07T21:14:37.671Z,1557263677.671 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-07T21:14:37.878Z,1557263677.878 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:41.106Z,1557263681.106 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:43.619Z,1557263683.619 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-07T21:14:43.934Z,1557263683.934 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:47.166Z,1557263687.166 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:49.352Z,1557263689.352 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:14:49.352Z,1557263689.352 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:14:49.397Z,1557263689.397 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T21:14:49.400Z,1557263689.400 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T21:14:49.404Z,1557263689.404 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T21:14:49.408Z,1557263689.408 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T21:14:49.411Z,1557263689.411 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T21:14:49.413Z,1557263689.413 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T21:14:49.420Z,1557263689.420 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T21:14:49.429Z,1557263689.429 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T21:14:49.433Z,1557263689.433 [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-07T21:14:49.435Z,1557263689.435 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:14:49.625Z,1557263689.625 [Default] Stopped
2019-05-07T21:14:49.626Z,1557263689.626 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T21:14:49.626Z,1557263689.626 [Default:B.GoToSurface] Stopped
2019-05-07T21:14:49.631Z,1557263689.631 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T21:14:49.631Z,1557263689.631 [Default:CheckIn] Stopped
2019-05-07T21:14:49.631Z,1557263689.631 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T21:14:49.632Z,1557263689.632 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T21:14:49.632Z,1557263689.632 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T21:14:49.633Z,1557263689.633 [DUSBL] Running Loop=1
2019-05-07T21:14:49.634Z,1557263689.634 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T21:14:49.634Z,1557263689.634 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T21:14:49.639Z,1557263689.639 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T21:14:49.640Z,1557263689.640 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T21:14:49.640Z,1557263689.640 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T21:14:49.640Z,1557263689.640 [DUSBL:C] Running Loop=1
2019-05-07T21:14:49.641Z,1557263689.641 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T21:14:49.641Z,1557263689.641 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:14:49.641Z,1557263689.641 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:14:49.642Z,1557263689.642 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:14:49.646Z,1557263689.646 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:14:49.647Z,1557263689.647 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:14:49.648Z,1557263689.648 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:14:49.648Z,1557263689.648 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:14:49.652Z,1557263689.652 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T21:14:49.654Z,1557263689.654 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T21:14:49.663Z,1557263689.663 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T21:14:49.663Z,1557263689.663 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T21:14:49.994Z,1557263689.994 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:51.196Z,1557263691.196 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:14:51.196Z,1557263691.196 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:14:51.197Z,1557263691.197 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:14:51.199Z,1557263691.199 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:51.600Z,1557263691.600 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:14:51.600Z,1557263691.600 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
O
2019-05-07T21:14:51.600Z,1557263691.600 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:14:51.600Z,1557263691.600 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:14:51.601Z,1557263691.601 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:14:52.014Z,1557263692.014 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:52.412Z,1557263692.412 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:52.816Z,1557263692.816 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:53.226Z,1557263693.226 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:53.258Z,1557263693.258 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:53.624Z,1557263693.624 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:54.020Z,1557263694.020 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:54.424Z,1557263694.424 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:54.832Z,1557263694.832 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T21:14:54.832Z,1557263694.832 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,
2019-05-07T21:14:54.833Z,1557263694.833 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,
2019-05-07T21:14:54.833Z,1557263694.833 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T21:14:55.231Z,1557263695.231 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:14:55.232Z,1557263695.232 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:14:55.232Z,1557263695.232 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:14:55.232Z,1557263695.232 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:14:55.640Z,1557263695.640 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T21:14:55.640Z,1557263695.640 [DUSBL_Hydroid](INFO): USBL response received:63,E4
!U1,P
2019-05-07T21:14:55.640Z,1557263695.640 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:14:55.641Z,1557263695.641 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:14:55.641Z,1557263695.641 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:14:56.048Z,1557263696.048 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:14:56.074Z,1557263696.074 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:56.444Z,1557263696.444 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T21:14:56.848Z,1557263696.848 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:57.252Z,1557263697.252 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:57.660Z,1557263697.660 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:58.060Z,1557263698.060 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:58.464Z,1557263698.464 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:58.868Z,1557263698.868 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:58.882Z,1557263698.882 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:14:59.276Z,1557263699.276 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:59.692Z,1557263699.692 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:14:59.751Z,1557263699.751 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:14:59.751Z,1557263699.751 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:14:59.751Z,1557263699.751 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:14:59.752Z,1557263699.752 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:14:59.752Z,1557263699.752 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:14:59.752Z,1557263699.752 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:14:59.752Z,1557263699.752 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:14:59.752Z,1557263699.752 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:14:59.753Z,1557263699.753 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T21:14:59.753Z,1557263699.753 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T21:14:59.753Z,1557263699.753 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:14:59.753Z,1557263699.753 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:14:59.753Z,1557263699.753 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:14:59.753Z,1557263699.753 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:14:59.753Z,1557263699.753 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:15:00.080Z,1557263700.080 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:00.488Z,1557263700.488 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:00.907Z,1557263700.907 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:01.300Z,1557263701.300 [DUSBL_Hydroid](INFO): IN QUEUE:!U000,187,80,81,07,FF
2019-05-07T21:15:01.314Z,1557263701.314 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.082312
2019-05-07T21:15:01.315Z,1557263701.315 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:01.315Z,1557263701.315 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:01.315Z,1557263701.315 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:01.317Z,1557263701.317 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:01.703Z,1557263701.703 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:01.704Z,1557263701.704 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,07,FF
2019-05-07T21:15:01.704Z,1557263701.704 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:01.705Z,1557263701.705 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:01.706Z,1557263701.706 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:02.106Z,1557263702.106 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:02.134Z,1557263702.134 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:02.516Z,1557263702.516 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:02.516Z,1557263702.516 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E2,000,00000,186,80,81,09,FF
2019-05-07T21:15:02.933Z,1557263702.933 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:02.933Z,1557263702.933 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:02.936Z,1557263702.936 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:02.939Z,1557263702.939 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:03.320Z,1557263703.320 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:03.320Z,1557263703.320 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E2,000,00000,186,80,81,09,FF
2019-05-07T21:15:03.320Z,1557263703.320 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:03.320Z,1557263703.320 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:03.321Z,1557263703.321 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:03.720Z,1557263703.720 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:04.124Z,1557263704.124 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:04.124Z,1557263704.124 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F9,000,00000,187,80,81,09,FF
2019-05-07T21:15:04.524Z,1557263704.524 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:04.524Z,1557263704.524 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:04.524Z,1557263704.524 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:04.526Z,1557263704.526 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:04.932Z,1557263704.932 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:04.932Z,1557263704.932 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F9,000,00000,187,80,81,09,FF
2019-05-07T21:15:04.932Z,1557263704.932 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:04.932Z,1557263704.932 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:04.933Z,1557263704.933 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:04.951Z,1557263704.951 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:05.332Z,1557263705.332 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:05.740Z,1557263705.740 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T21:15:06.148Z,1557263706.148 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:06.556Z,1557263706.556 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:06.952Z,1557263706.952 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:07.352Z,1557263707.352 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:07.760Z,1557263707.760 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:08.164Z,1557263708.164 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:08.178Z,1557263708.178 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:08.568Z,1557263708.568 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:08.972Z,1557263708.972 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:09.376Z,1557263709.376 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:09.776Z,1557263709.776 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:10.180Z,1557263710.180 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:10.219Z,1557263710.219 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:15:10.219Z,1557263710.219 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:15:10.219Z,1557263710.219 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:15:10.220Z,1557263710.220 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:15:10.220Z,1557263710.220 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:15:10.220Z,1557263710.220 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:15:10.220Z,1557263710.220 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:15:10.220Z,1557263710.220 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:15:10.221Z,1557263710.221 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T21:15:10.221Z,1557263710.221 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T21:15:10.221Z,1557263710.221 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:15:10.221Z,1557263710.221 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:15:10.221Z,1557263710.221 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:15:10.221Z,1557263710.221 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:15:10.221Z,1557263710.221 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:15:10.584Z,1557263710.584 [DUSBL_Hydroid](INFO): IN QUEUE:!U000,187,80,81,05,FF
7,80,81,09,FF
2019-05-07T21:15:10.598Z,1557263710.598 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.073863
2019-05-07T21:15:10.598Z,1557263710.598 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:10.599Z,1557263710.599 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:10.599Z,1557263710.599 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:10.601Z,1557263710.601 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:10.988Z,1557263710.988 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:10.988Z,1557263710.988 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,05,FF
7,80,81,09,FF
2019-05-07T21:15:10.988Z,1557263710.988 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:10.988Z,1557263710.988 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:10.989Z,1557263710.989 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:11.007Z,1557263711.007 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:11.396Z,1557263711.396 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:11.796Z,1557263711.796 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:11.796Z,1557263711.796 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,185,000,00000,185,80,81,0F,FF
2019-05-07T21:15:12.204Z,1557263712.204 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:12.204Z,1557263712.204 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:12.205Z,1557263712.205 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:12.206Z,1557263712.206 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:12.608Z,1557263712.608 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:12.608Z,1557263712.608 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
185,000,00000,185,80,81,0F,FF
2019-05-07T21:15:12.608Z,1557263712.608 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:12.608Z,1557263712.608 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:12.609Z,1557263712.609 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:13.012Z,1557263713.012 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:13.416Z,1557263713.416 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:13.416Z,1557263713.416 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1FE,000,00000,187,80,81,08,FF
2019-05-07T21:15:13.820Z,1557263713.820 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:13.820Z,1557263713.820 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:13.820Z,1557263713.820 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:13.823Z,1557263713.823 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:14.220Z,1557263714.220 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:14.220Z,1557263714.220 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1FE,000,00000,187,80,81,08,FF
2019-05-07T21:15:14.220Z,1557263714.220 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:14.220Z,1557263714.220 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:14.222Z,1557263714.222 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:14.239Z,1557263714.239 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:14.628Z,1557263714.628 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:15.032Z,1557263715.032 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:15.032Z,1557263715.032 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1DD,000,00000,186,80,81,10,FF
2019-05-07T21:15:15.436Z,1557263715.436 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:15.436Z,1557263715.436 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:15.436Z,1557263715.436 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:15.438Z,1557263715.438 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:15.840Z,1557263715.840 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:15.840Z,1557263715.840 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1DD,000,00000,186,80,81,10,FF
2019-05-07T21:15:15.840Z,1557263715.840 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:15.840Z,1557263715.840 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:15.841Z,1557263715.841 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:16.244Z,1557263716.244 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:16.648Z,1557263716.648 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:17.052Z,1557263717.052 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:17.066Z,1557263717.066 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:17.456Z,1557263717.456 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:17.860Z,1557263717.860 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:18.264Z,1557263718.264 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:18.664Z,1557263718.664 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:19.072Z,1557263719.072 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:19.476Z,1557263719.476 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:19.880Z,1557263719.880 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:19.894Z,1557263719.894 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:20.284Z,1557263720.284 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:20.688Z,1557263720.688 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:20.757Z,1557263720.757 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:15:20.757Z,1557263720.757 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:15:20.757Z,1557263720.757 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:15:20.760Z,1557263720.760 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:15:20.760Z,1557263720.760 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:15:20.761Z,1557263720.761 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:15:20.761Z,1557263720.761 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:15:20.761Z,1557263720.761 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:15:20.761Z,1557263720.761 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T21:15:20.762Z,1557263720.762 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T21:15:20.762Z,1557263720.762 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:15:20.763Z,1557263720.763 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:15:20.763Z,1557263720.763 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:15:20.763Z,1557263720.763 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:15:20.763Z,1557263720.763 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:15:21.092Z,1557263721.092 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:21.496Z,1557263721.496 [DUSBL_Hydroid](INFO): IN QUEUE:00000,187,80,81,0C,FF
6,80,81,10,FF
2019-05-07T21:15:21.506Z,1557263721.506 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.069935
2019-05-07T21:15:21.506Z,1557263721.506 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:21.507Z,1557263721.507 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:21.507Z,1557263721.507 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:21.509Z,1557263721.509 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:21.904Z,1557263721.904 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:21.904Z,1557263721.904 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,0C,FF
6,80,81,10,FF
2019-05-07T21:15:21.904Z,1557263721.904 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:21.904Z,1557263721.904 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:21.905Z,1557263721.905 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:22.304Z,1557263722.304 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:22.708Z,1557263722.708 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:22.708Z,1557263722.708 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,212,000,00000,186,80,81,0D,FF
2019-05-07T21:15:23.112Z,1557263723.112 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:23.112Z,1557263723.112 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:23.112Z,1557263723.112 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:23.114Z,1557263723.114 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:23.130Z,1557263723.130 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:23.516Z,1557263723.516 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:23.516Z,1557263723.516 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
212,000,00000,186,80,81,0D,FF
2019-05-07T21:15:23.516Z,1557263723.516 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:23.516Z,1557263723.516 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:23.517Z,1557263723.517 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:23.920Z,1557263723.920 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:24.324Z,1557263724.324 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:24.324Z,1557263724.324 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1AF,000,00000,186,80,81,09,FF
2019-05-07T21:15:24.728Z,1557263724.728 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:24.728Z,1557263724.728 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:24.728Z,1557263724.728 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:24.731Z,1557263724.731 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:25.128Z,1557263725.128 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:25.128Z,1557263725.128 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1AF,000,00000,186,80,81,09,FF
2019-05-07T21:15:25.128Z,1557263725.128 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:25.128Z,1557263725.128 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:25.129Z,1557263725.129 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:25.538Z,1557263725.538 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:25.936Z,1557263725.936 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T21:15:25.950Z,1557263725.950 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:26.340Z,1557263726.340 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:26.747Z,1557263726.747 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:27.168Z,1557263727.168 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:27.565Z,1557263727.565 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:27.956Z,1557263727.956 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:28.375Z,1557263728.375 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:28.768Z,1557263728.768 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:29.176Z,1557263729.176 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:29.194Z,1557263729.194 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:29.588Z,1557263729.588 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:29.976Z,1557263729.976 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:30.380Z,1557263730.380 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:30.784Z,1557263730.784 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,186,80,81,08,FF
6,80,81,09,FF
2019-05-07T21:15:30.794Z,1557263730.794 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.066018
2019-05-07T21:15:30.795Z,1557263730.795 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:30.795Z,1557263730.795 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:30.795Z,1557263730.795 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:30.796Z,1557263730.796 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:31.188Z,1557263731.188 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:31.188Z,1557263731.188 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,08,FF
6,80,81,09,FF
2019-05-07T21:15:31.188Z,1557263731.188 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:31.188Z,1557263731.188 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:31.189Z,1557263731.189 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:31.250Z,1557263731.250 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:15:31.251Z,1557263731.251 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:15:31.251Z,1557263731.251 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:15:31.252Z,1557263731.252 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:15:31.252Z,1557263731.252 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:15:31.252Z,1557263731.252 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:15:31.252Z,1557263731.252 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:15:31.252Z,1557263731.252 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:15:31.252Z,1557263731.252 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T21:15:31.252Z,1557263731.252 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T21:15:31.253Z,1557263731.253 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:15:31.253Z,1557263731.253 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:15:31.253Z,1557263731.253 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:15:31.253Z,1557263731.253 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:15:31.253Z,1557263731.253 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:15:31.604Z,1557263731.604 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:31.996Z,1557263731.996 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:31.996Z,1557263731.996 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1FC,000,00000,186,80,81,0A,FF
2019-05-07T21:15:32.010Z,1557263732.010 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:32.399Z,1557263732.399 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:32.400Z,1557263732.400 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:32.400Z,1557263732.400 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:32.400Z,1557263732.400 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:32.804Z,1557263732.804 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:32.804Z,1557263732.804 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1FC,000,00000,186,80,81,0A,FF
2019-05-07T21:15:32.804Z,1557263732.804 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:32.804Z,1557263732.804 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:32.805Z,1557263732.805 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:33.216Z,1557263733.216 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:33.620Z,1557263733.620 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:34.016Z,1557263734.016 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:34.016Z,1557263734.016 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,206,000,00000,187,80,81,07,FF
2019-05-07T21:15:34.419Z,1557263734.419 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:34.420Z,1557263734.420 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:34.420Z,1557263734.420 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:34.420Z,1557263734.420 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:34.824Z,1557263734.824 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:34.824Z,1557263734.824 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
206,000,00000,187,80,81,07,FF
2019-05-07T21:15:34.824Z,1557263734.824 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:34.824Z,1557263734.824 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:34.825Z,1557263734.825 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:35.228Z,1557263735.228 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:35.255Z,1557263735.255 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:35.632Z,1557263735.632 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:35.632Z,1557263735.632 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F4,000,00000,186,80,81,10,FF
2019-05-07T21:15:36.036Z,1557263736.036 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:36.036Z,1557263736.036 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:36.036Z,1557263736.036 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:36.038Z,1557263736.038 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:36.458Z,1557263736.458 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:36.458Z,1557263736.458 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F4,000,00000,186,80,81,10,FF
2019-05-07T21:15:36.459Z,1557263736.459 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:36.459Z,1557263736.459 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:36.460Z,1557263736.460 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:36.844Z,1557263736.844 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:37.248Z,1557263737.248 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:37.657Z,1557263737.657 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:38.064Z,1557263738.064 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:38.078Z,1557263738.078 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:38.472Z,1557263738.472 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:38.864Z,1557263738.864 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:39.268Z,1557263739.268 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:39.672Z,1557263739.672 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T21:15:40.080Z,1557263740.080 [DUSBL_Hydroid](INFO): 18 bytes available.****
2019-05-07T21:15:40.080Z,1557263740.080 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,63,E4
0,186,80,81,10,FF
2019-05-07T21:15:40.080Z,1557263740.080 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
0,186,80,81,10,FF
2019-05-07T21:15:40.080Z,1557263740.080 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T21:15:40.484Z,1557263740.484 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:40.484Z,1557263740.484 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:40.484Z,1557263740.484 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:40.487Z,1557263740.487 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:40.892Z,1557263740.892 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:40.892Z,1557263740.892 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
80,80,63,E4
0,186,80,81,10,FF
2019-05-07T21:15:40.892Z,1557263740.892 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:40.892Z,1557263740.892 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:40.893Z,1557263740.893 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:40.911Z,1557263740.911 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:41.292Z,1557263741.292 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:41.700Z,1557263741.700 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T21:15:41.755Z,1557263741.755 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:15:41.755Z,1557263741.755 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:15:41.755Z,1557263741.755 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:15:41.756Z,1557263741.756 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:15:41.756Z,1557263741.756 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:15:41.756Z,1557263741.756 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:15:41.756Z,1557263741.756 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:15:41.756Z,1557263741.756 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:15:41.756Z,1557263741.756 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T21:15:41.757Z,1557263741.757 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T21:15:41.757Z,1557263741.757 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:15:41.757Z,1557263741.757 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:15:41.757Z,1557263741.757 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:15:41.757Z,1557263741.757 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:15:41.757Z,1557263741.757 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:15:42.096Z,1557263742.096 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:42.500Z,1557263742.500 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:42.904Z,1557263742.904 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:43.317Z,1557263743.317 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:43.712Z,1557263743.712 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:44.120Z,1557263744.120 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:44.134Z,1557263744.134 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:44.524Z,1557263744.524 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:44.924Z,1557263744.924 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:45.336Z,1557263745.336 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:45.732Z,1557263745.732 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:46.136Z,1557263746.136 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:46.543Z,1557263746.543 [DUSBL_Hydroid](INFO): IN QUEUE:!U000,186,80,81,0B,FF
6,80,81,10,FF
2019-05-07T21:15:46.555Z,1557263746.555 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.069999
2019-05-07T21:15:46.556Z,1557263746.556 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:46.556Z,1557263746.556 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:46.557Z,1557263746.557 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:46.560Z,1557263746.560 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:46.944Z,1557263746.944 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:46.944Z,1557263746.944 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0B,FF
6,80,81,10,FF
2019-05-07T21:15:46.944Z,1557263746.944 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:46.944Z,1557263746.944 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:46.946Z,1557263746.946 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:46.963Z,1557263746.963 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:47.352Z,1557263747.352 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:47.752Z,1557263747.752 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:47.752Z,1557263747.752 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E2,000,00000,187,80,81,07,FF
2019-05-07T21:15:48.160Z,1557263748.160 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:48.160Z,1557263748.160 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:48.161Z,1557263748.161 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:48.162Z,1557263748.162 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:48.564Z,1557263748.564 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:48.564Z,1557263748.564 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E2,000,00000,187,80,81,07,FF
2019-05-07T21:15:48.564Z,1557263748.564 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:48.564Z,1557263748.564 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:48.565Z,1557263748.565 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:48.975Z,1557263748.975 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:49.372Z,1557263749.372 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T21:15:49.772Z,1557263749.772 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:50.176Z,1557263750.176 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:50.190Z,1557263750.190 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:50.580Z,1557263750.580 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:50.984Z,1557263750.984 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:51.392Z,1557263751.392 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:51.796Z,1557263751.796 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:52.204Z,1557263752.204 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:52.260Z,1557263752.260 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:15:52.260Z,1557263752.260 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:15:52.260Z,1557263752.260 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:15:52.260Z,1557263752.260 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:15:52.260Z,1557263752.260 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:15:52.261Z,1557263752.261 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:15:52.608Z,1557263752.608 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:53.004Z,1557263753.004 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:53.018Z,1557263753.018 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:53.412Z,1557263753.412 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:53.816Z,1557263753.816 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:54.216Z,1557263754.216 [DUSBL_Hydroid](INFO): IN QUEUE:!U000,188,80,81,05,FF
7,80,81,07,FF
2019-05-07T21:15:54.230Z,1557263754.230 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.069814
2019-05-07T21:15:54.231Z,1557263754.231 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:54.231Z,1557263754.231 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:54.231Z,1557263754.231 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:54.233Z,1557263754.233 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:54.624Z,1557263754.624 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:54.624Z,1557263754.624 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
188,80,81,05,FF
7,80,81,07,FF
2019-05-07T21:15:54.624Z,1557263754.624 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:54.624Z,1557263754.624 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:54.625Z,1557263754.625 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:55.024Z,1557263755.024 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:55.432Z,1557263755.432 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:15:55.432Z,1557263755.432 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,20D,000,00000,187,80,81,07,FF
2019-05-07T21:15:55.842Z,1557263755.842 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:15:55.842Z,1557263755.842 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:15:55.843Z,1557263755.843 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:15:55.844Z,1557263755.844 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:56.244Z,1557263756.244 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:15:56.244Z,1557263756.244 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
20D,000,00000,187,80,81,07,FF
2019-05-07T21:15:56.244Z,1557263756.244 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:15:56.245Z,1557263756.245 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:15:56.245Z,1557263756.245 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:15:56.263Z,1557263756.263 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:56.644Z,1557263756.644 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:15:57.044Z,1557263757.044 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T21:15:57.448Z,1557263757.448 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:57.852Z,1557263757.852 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:58.260Z,1557263758.260 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:58.664Z,1557263758.664 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:59.068Z,1557263759.068 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:59.086Z,1557263759.086 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:15:59.476Z,1557263759.476 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:15:59.872Z,1557263759.872 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:00.284Z,1557263760.284 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:00.684Z,1557263760.684 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:01.088Z,1557263761.088 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:01.488Z,1557263761.488 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:01.896Z,1557263761.896 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,187,80,81,05,FF
7,80,81,07,FF
2019-05-07T21:16:01.911Z,1557263761.911 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.067371
2019-05-07T21:16:01.911Z,1557263761.911 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:16:01.912Z,1557263761.912 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:16:01.913Z,1557263761.913 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:16:01.915Z,1557263761.915 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:01.931Z,1557263761.931 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:02.300Z,1557263762.300 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:16:02.300Z,1557263762.300 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,05,FF
7,80,81,07,FF
2019-05-07T21:16:02.300Z,1557263762.300 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:16:02.301Z,1557263762.301 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:16:02.301Z,1557263762.301 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:16:02.704Z,1557263762.704 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:02.756Z,1557263762.756 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:16:02.756Z,1557263762.756 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:16:02.756Z,1557263762.756 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T21:16:02.757Z,1557263762.757 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:16:02.758Z,1557263762.758 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:16:02.758Z,1557263762.758 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:16:02.758Z,1557263762.758 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:16:02.758Z,1557263762.758 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:16:03.104Z,1557263763.104 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:03.508Z,1557263763.508 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:03.912Z,1557263763.912 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:04.316Z,1557263764.316 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:04.720Z,1557263764.720 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:05.128Z,1557263765.128 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:05.142Z,1557263765.142 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:05.532Z,1557263765.532 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:05.932Z,1557263765.932 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:06.344Z,1557263766.344 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:06.740Z,1557263766.740 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:07.144Z,1557263767.144 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:07.551Z,1557263767.551 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:07.952Z,1557263767.952 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,09,FF
7,80,81,07,FF
2019-05-07T21:16:07.962Z,1557263767.962 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.049399
2019-05-07T21:16:07.963Z,1557263767.963 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:16:07.963Z,1557263767.963 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:16:07.963Z,1557263767.963 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:16:07.963Z,1557263767.963 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:07.978Z,1557263767.978 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:08.360Z,1557263768.360 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:16:08.360Z,1557263768.360 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,09,FF
7,80,81,07,FF
2019-05-07T21:16:08.360Z,1557263768.360 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:16:08.360Z,1557263768.360 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:16:08.361Z,1557263768.361 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:16:08.764Z,1557263768.764 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:09.164Z,1557263769.164 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:16:09.164Z,1557263769.164 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,200,000,00000,187,80,81,08,FF
2019-05-07T21:16:09.567Z,1557263769.567 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:16:09.568Z,1557263769.568 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:16:09.568Z,1557263769.568 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:16:09.568Z,1557263769.568 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:09.976Z,1557263769.976 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:16:09.976Z,1557263769.976 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
200,000,00000,187,80,81,08,FF
2019-05-07T21:16:09.976Z,1557263769.976 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:16:09.976Z,1557263769.976 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:16:09.977Z,1557263769.977 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:16:10.376Z,1557263770.376 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:10.796Z,1557263770.796 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:11.184Z,1557263771.184 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:11.198Z,1557263771.198 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:11.588Z,1557263771.588 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:12.010Z,1557263772.010 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:12.396Z,1557263772.396 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:12.808Z,1557263772.808 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:13.212Z,1557263773.212 [DUSBL_Hydroid](INFO): 13 bytes available.****
2019-05-07T21:16:13.213Z,1557263773.213 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,6,00000,187,80,81,08,FF
2019-05-07T21:16:13.213Z,1557263773.213 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,6,00000,187,80,81,08,FF
2019-05-07T21:16:13.213Z,1557263773.213 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T21:16:13.249Z,1557263773.249 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:16:13.249Z,1557263773.249 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:16:13.249Z,1557263773.249 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T21:16:13.250Z,1557263773.250 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:16:13.251Z,1557263773.251 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:16:13.251Z,1557263773.251 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:16:13.251Z,1557263773.251 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:16:13.251Z,1557263773.251 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:16:13.628Z,1557263773.628 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:16:13.628Z,1557263773.628 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:16:13.628Z,1557263773.628 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:16:13.630Z,1557263773.630 [DUSBL_Hydroid](INFO): 5 bytes available.****
2019-05-07T21:16:14.020Z,1557263774.020 [DUSBL_Hydroid](INFO): 11 bytes available.****
2019-05-07T21:16:14.020Z,1557263774.020 [DUSBL_Hydroid](INFO): USBL response received:3,E4
!U1,P
,6,00000,187,80,81,08,FF
2019-05-07T21:16:14.020Z,1557263774.020 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:16:14.020Z,1557263774.020 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:16:14.021Z,1557263774.021 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:16:14.039Z,1557263774.039 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:14.416Z,1557263774.416 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:14.824Z,1557263774.824 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:16:14.824Z,1557263774.824 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,241,000,00000,189,80,81,0F,FF
2019-05-07T21:16:15.224Z,1557263775.224 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:16:15.224Z,1557263775.224 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:16:15.225Z,1557263775.225 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:16:15.226Z,1557263775.226 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:15.636Z,1557263775.636 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:16:15.637Z,1557263775.637 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
241,000,00000,189,80,81,0F,FF
2019-05-07T21:16:15.637Z,1557263775.637 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:16:15.637Z,1557263775.637 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:16:15.638Z,1557263775.638 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:16:16.032Z,1557263776.032 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:16.440Z,1557263776.440 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:16.840Z,1557263776.840 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:17.248Z,1557263777.248 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:17.262Z,1557263777.262 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:17.656Z,1557263777.656 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:18.056Z,1557263778.056 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:18.456Z,1557263778.456 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:18.864Z,1557263778.864 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:19.264Z,1557263779.264 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:19.672Z,1557263779.672 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:20.080Z,1557263780.080 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:20.094Z,1557263780.094 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:20.476Z,1557263780.476 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:20.479Z,1557263780.479 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211453.00,A,3648.16332,N,12147.28475,W,1.827,130.21,070519,,,A*7A
2019-05-07T21:16:20.482Z,1557263780.482 [NAL9602](INFO): GPS fix at 20190507T211453: (36.802722, -121.788079)
2019-05-07T21:16:20.888Z,1557263780.888 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:16:21.291Z,1557263781.291 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,07,FF
9,80,81,0F,FF
2019-05-07T21:16:21.302Z,1557263781.302 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.077402
2019-05-07T21:16:21.302Z,1557263781.302 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:16:21.303Z,1557263781.303 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:16:21.303Z,1557263781.303 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:16:21.305Z,1557263781.305 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:21.696Z,1557263781.696 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:16:21.696Z,1557263781.696 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,07,FF
9,80,81,0F,FF
2019-05-07T21:16:21.696Z,1557263781.696 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:16:21.696Z,1557263781.696 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:16:21.697Z,1557263781.697 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:16:22.099Z,1557263782.099 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:16:22.227Z,1557263782.227 [CommandLine](IMPORTANT): got command stop
2019-05-07T21:16:22.227Z,1557263782.227 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-07T21:16:22.228Z,1557263782.228 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-07T21:16:22.503Z,1557263782.503 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:16:22.504Z,1557263782.504 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1AC,000,00000,186,80,81,06,FF
2019-05-07T21:16:22.546Z,1557263782.546 [MissionManager](INFO): MissionManager is completed.
2019-05-07T21:16:22.546Z,1557263782.546 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T21:16:22.546Z,1557263782.546 [DUSBL] Stopped
2019-05-07T21:16:22.546Z,1557263782.546 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T21:16:22.550Z,1557263782.550 [DUSBL:A.Pitch] Stopped
2019-05-07T21:16:22.550Z,1557263782.550 [DUSBL:B.SetSpeed] Stopped
2019-05-07T21:16:22.550Z,1557263782.550 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T21:16:22.550Z,1557263782.550 [DUSBL:C] Stopped
2019-05-07T21:16:22.550Z,1557263782.550 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:16:22.551Z,1557263782.551 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:16:22.551Z,1557263782.551 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:16:22.551Z,1557263782.551 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:16:22.551Z,1557263782.551 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:16:22.551Z,1557263782.551 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:16:22.975Z,1557263782.975 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T21:16:22.975Z,1557263782.975 [Default] Running Loop=1
2019-05-07T21:16:22.975Z,1557263782.975 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T21:16:22.975Z,1557263782.975 [Default:B.GoToSurface] Running Loop=1
2019-05-07T21:16:22.975Z,1557263782.975 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:16:22.976Z,1557263782.976 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:16:22.976Z,1557263782.976 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:16:22.976Z,1557263782.976 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:16:22.976Z,1557263782.976 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:16:22.977Z,1557263782.977 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:16:22.977Z,1557263782.977 [Default:A.Wait] Running Loop=1
2019-05-07T21:16:22.977Z,1557263782.977 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:16:36.268Z,1557263796.268 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T21:16:36.268Z,1557263796.268 [Default:A.Wait] Stopped
2019-05-07T21:16:36.268Z,1557263796.268 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:16:36.699Z,1557263796.699 [Default:CheckIn] Running Loop=1
2019-05-07T21:16:36.699Z,1557263796.699 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T21:16:36.699Z,1557263796.699 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T21:16:38.274Z,1557263798.274 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:16:38.666Z,1557263798.666 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211511.00,A,3648.16546,N,12147.28544,W,0.175,130.21,070519,,,A*74
2019-05-07T21:16:38.668Z,1557263798.668 [NAL9602](INFO): GPS fix at 20190507T211511: (36.802758, -121.788091)
2019-05-07T21:16:38.737Z,1557263798.737 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T21:16:38.737Z,1557263798.737 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T21:16:39.110Z,1557263799.110 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T21:16:45.386Z,1557263805.386 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190507T211026/Courier0004.lzma
2019-05-07T21:16:46.192Z,1557263806.192 [DataOverHttps](INFO): Moved sent file to Logs/20190507T211026/Courier0004.lzma.bak
2019-05-07T21:16:46.192Z,1557263806.192 [DataOverHttps](INFO): SBD MOMSN=10959100
2019-05-07T21:16:58.711Z,1557263818.711 [DataOverHttps](INFO): Sending 892 bytes from file Logs/20190507T211026/Express0005.lzma
2019-05-07T21:16:59.517Z,1557263819.517 [DataOverHttps](INFO): Moved sent file to Logs/20190507T211026/Express0005.lzma.bak
2019-05-07T21:16:59.517Z,1557263819.517 [DataOverHttps](INFO): SBD MOMSN=10959106
2019-05-07T21:17:00.822Z,1557263820.822 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T21:17:00.822Z,1557263820.822 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T21:17:00.822Z,1557263820.822 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:17:10.881Z,1557263830.881 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T21:18:42.250Z,1557263922.250 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-07T21:18:42.257Z,1557263922.257 [BPC1](INFO): Received data from all battery sticks.
2019-05-07T21:19:09.207Z,1557263949.207 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:19:09.208Z,1557263949.208 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:19:09.292Z,1557263949.292 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T21:19:09.298Z,1557263949.298 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T21:19:09.301Z,1557263949.301 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T21:19:09.307Z,1557263949.307 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T21:19:09.309Z,1557263949.309 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T21:19:09.310Z,1557263949.310 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T21:19:09.347Z,1557263949.347 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T21:19:09.367Z,1557263949.367 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T21:19:09.375Z,1557263949.375 [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-07T21:19:09.377Z,1557263949.377 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:19:09.717Z,1557263949.717 [Default] Stopped
2019-05-07T21:19:09.717Z,1557263949.717 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T21:19:09.717Z,1557263949.717 [Default:B.GoToSurface] Stopped
2019-05-07T21:19:09.717Z,1557263949.717 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T21:19:09.717Z,1557263949.717 [Default:CheckIn] Stopped
2019-05-07T21:19:09.717Z,1557263949.717 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T21:19:09.718Z,1557263949.718 [Default:CheckIn:C.Wait] Stopped
2019-05-07T21:19:09.718Z,1557263949.718 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:19:09.718Z,1557263949.718 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T21:19:09.718Z,1557263949.718 [DUSBL] Running Loop=1
2019-05-07T21:19:09.718Z,1557263949.718 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T21:19:09.718Z,1557263949.718 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T21:19:09.718Z,1557263949.718 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T21:19:09.719Z,1557263949.719 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T21:19:09.719Z,1557263949.719 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T21:19:09.719Z,1557263949.719 [DUSBL:C] Running Loop=1
2019-05-07T21:19:09.719Z,1557263949.719 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T21:19:09.719Z,1557263949.719 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:19:09.719Z,1557263949.719 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:19:09.719Z,1557263949.719 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:19:09.720Z,1557263949.720 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:19:09.720Z,1557263949.720 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:19:09.720Z,1557263949.720 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:19:09.720Z,1557263949.720 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:19:09.721Z,1557263949.721 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T21:19:09.721Z,1557263949.721 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T21:19:09.722Z,1557263949.722 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T21:19:09.722Z,1557263949.722 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T21:19:11.283Z,1557263951.283 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:11.284Z,1557263951.284 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:11.284Z,1557263951.284 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:11.287Z,1557263951.287 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:11.691Z,1557263951.691 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:11.692Z,1557263951.692 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1AC,000,00000,186,80,81,06,FF
2019-05-07T21:19:11.692Z,1557263951.692 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:11.692Z,1557263951.692 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:11.693Z,1557263951.693 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:12.092Z,1557263952.092 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:12.500Z,1557263952.500 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:19:12.500Z,1557263952.500 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C6,000,002CD,186,80,80,26,FF
2019-05-07T21:19:12.500Z,1557263952.500 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T21:19:12.555Z,1557263952.555 [Reporter](INFO): acoustic_contact_range 5.520000 m
2019-05-07T21:19:14.917Z,1557263954.917 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:14.917Z,1557263954.917 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:14.918Z,1557263954.918 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:14.919Z,1557263954.919 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:15.323Z,1557263955.323 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:15.324Z,1557263955.324 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C6,000,002CD,186,80,80,26,FF
2019-05-07T21:19:15.324Z,1557263955.324 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:15.324Z,1557263955.324 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:15.325Z,1557263955.325 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:15.728Z,1557263955.728 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:16.147Z,1557263956.147 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T21:19:16.559Z,1557263956.559 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:16.591Z,1557263956.591 [RDI_Pathfinder](ERROR): Failed to parse:
68,-32768,-32768,V
2019-05-07T21:19:16.944Z,1557263956.944 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:17.359Z,1557263957.359 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:17.748Z,1557263957.748 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:18.169Z,1557263958.169 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:18.563Z,1557263958.563 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:18.961Z,1557263958.961 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:19.372Z,1557263959.372 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:19.771Z,1557263959.771 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:19.809Z,1557263959.809 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:19:19.809Z,1557263959.809 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:19:19.809Z,1557263959.809 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:19:19.810Z,1557263959.810 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:19:19.810Z,1557263959.810 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:19:19.810Z,1557263959.810 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:19:19.810Z,1557263959.810 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:19:19.810Z,1557263959.810 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:19:19.811Z,1557263959.811 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T21:19:19.811Z,1557263959.811 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T21:19:19.811Z,1557263959.811 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:19:19.811Z,1557263959.811 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:19:19.811Z,1557263959.811 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:19:19.811Z,1557263959.811 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:19:19.811Z,1557263959.811 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:19:20.172Z,1557263960.172 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:20.591Z,1557263960.591 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:20.980Z,1557263960.980 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,186,80,81,0A,FF
6,80,80,26,FF
2019-05-07T21:19:20.994Z,1557263960.994 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.076487
2019-05-07T21:19:20.994Z,1557263960.994 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:20.995Z,1557263960.995 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:20.995Z,1557263960.995 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:20.997Z,1557263960.997 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:21.384Z,1557263961.384 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:21.384Z,1557263961.384 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0A,FF
6,80,80,26,FF
2019-05-07T21:19:21.384Z,1557263961.384 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:21.385Z,1557263961.385 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:21.385Z,1557263961.385 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:21.788Z,1557263961.788 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:22.195Z,1557263962.195 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:22.620Z,1557263962.620 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:23.004Z,1557263963.004 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:23.404Z,1557263963.404 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:23.819Z,1557263963.819 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:24.212Z,1557263964.212 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:24.627Z,1557263964.627 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:25.023Z,1557263965.023 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:25.428Z,1557263965.428 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:25.831Z,1557263965.831 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:26.240Z,1557263966.240 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:26.636Z,1557263966.636 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:27.047Z,1557263967.047 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,0B,FF
6,80,80,26,FF
2019-05-07T21:19:27.060Z,1557263967.060 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.064132
2019-05-07T21:19:27.060Z,1557263967.060 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:27.060Z,1557263967.060 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:27.060Z,1557263967.060 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:27.060Z,1557263967.060 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:27.447Z,1557263967.447 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:27.448Z,1557263967.448 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0B,FF
6,80,80,26,FF
2019-05-07T21:19:27.448Z,1557263967.448 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:27.448Z,1557263967.448 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:27.449Z,1557263967.449 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:27.848Z,1557263967.848 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:28.255Z,1557263968.255 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:28.656Z,1557263968.656 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:29.064Z,1557263969.064 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:29.464Z,1557263969.464 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:29.867Z,1557263969.867 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:30.276Z,1557263970.276 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:30.301Z,1557263970.301 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:19:30.301Z,1557263970.301 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:19:30.301Z,1557263970.301 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:19:30.302Z,1557263970.302 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:19:30.302Z,1557263970.302 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:19:30.302Z,1557263970.302 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:19:30.303Z,1557263970.303 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:19:30.684Z,1557263970.684 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:31.079Z,1557263971.079 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:31.484Z,1557263971.484 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:31.888Z,1557263971.888 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:32.291Z,1557263972.291 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:32.696Z,1557263972.696 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:33.099Z,1557263973.099 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,0D,FF
6,80,80,26,FF
2019-05-07T21:19:33.110Z,1557263973.110 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.050033
2019-05-07T21:19:33.110Z,1557263973.110 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:33.111Z,1557263973.111 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:33.111Z,1557263973.111 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:33.113Z,1557263973.113 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:33.503Z,1557263973.503 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:33.504Z,1557263973.504 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0D,FF
6,80,80,26,FF
2019-05-07T21:19:33.504Z,1557263973.504 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:33.504Z,1557263973.504 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:33.505Z,1557263973.505 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:33.916Z,1557263973.916 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:34.312Z,1557263974.312 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:19:34.312Z,1557263974.312 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,222,000,00000,188,80,81,04,FF
2019-05-07T21:19:34.719Z,1557263974.719 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:34.719Z,1557263974.719 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:34.720Z,1557263974.720 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:34.721Z,1557263974.721 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:35.124Z,1557263975.124 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:35.124Z,1557263975.124 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
222,000,00000,188,80,81,04,FF
2019-05-07T21:19:35.124Z,1557263975.124 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:35.124Z,1557263975.124 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:35.125Z,1557263975.125 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:35.524Z,1557263975.524 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:35.931Z,1557263975.931 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T21:19:36.332Z,1557263976.332 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:36.739Z,1557263976.739 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:37.146Z,1557263977.146 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:37.548Z,1557263977.548 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:37.948Z,1557263977.948 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:38.355Z,1557263978.355 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:38.760Z,1557263978.760 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:39.164Z,1557263979.164 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:39.568Z,1557263979.568 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:39.968Z,1557263979.968 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:40.379Z,1557263980.379 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:40.779Z,1557263980.779 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,186,80,81,0B,FF
8,80,81,04,FF
2019-05-07T21:19:40.790Z,1557263980.790 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070368
2019-05-07T21:19:40.791Z,1557263980.791 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:40.791Z,1557263980.791 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:40.802Z,1557263980.802 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:40.802Z,1557263980.802 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T21:19:40.871Z,1557263980.871 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:19:40.871Z,1557263980.871 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:19:40.871Z,1557263980.871 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:19:40.872Z,1557263980.872 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:19:40.873Z,1557263980.873 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:19:40.873Z,1557263980.873 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:19:40.873Z,1557263980.873 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:19:41.180Z,1557263981.180 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:41.180Z,1557263981.180 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0B,FF
8,80,81,04,FF
2019-05-07T21:19:41.180Z,1557263981.180 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:41.180Z,1557263981.180 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:41.181Z,1557263981.181 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:41.597Z,1557263981.597 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:41.988Z,1557263981.988 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:42.396Z,1557263982.396 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:42.799Z,1557263982.799 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:43.199Z,1557263983.199 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:43.612Z,1557263983.612 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:44.008Z,1557263984.008 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:44.415Z,1557263984.415 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:44.813Z,1557263984.813 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:45.223Z,1557263985.223 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:45.661Z,1557263985.661 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:46.032Z,1557263986.032 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:46.435Z,1557263986.435 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:46.836Z,1557263986.836 [DUSBL_Hydroid](INFO): IN QUEUE:00000,187,80,81,0A,FF
8,80,81,04,FF
2019-05-07T21:19:46.846Z,1557263986.846 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.044608
2019-05-07T21:19:46.846Z,1557263986.846 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:46.847Z,1557263986.847 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:46.847Z,1557263986.847 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:46.849Z,1557263986.849 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:47.244Z,1557263987.244 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:47.244Z,1557263987.244 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,0A,FF
8,80,81,04,FF
2019-05-07T21:19:47.244Z,1557263987.244 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:47.244Z,1557263987.244 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:47.245Z,1557263987.245 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:47.644Z,1557263987.644 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:48.047Z,1557263988.047 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:19:48.048Z,1557263988.048 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1CA,000,00000,187,80,81,07,FF
2019-05-07T21:19:48.455Z,1557263988.455 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:48.455Z,1557263988.455 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:48.456Z,1557263988.456 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:48.459Z,1557263988.459 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:48.859Z,1557263988.859 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:48.860Z,1557263988.860 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1CA,000,00000,187,80,81,07,FF
2019-05-07T21:19:48.860Z,1557263988.860 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:48.860Z,1557263988.860 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:48.861Z,1557263988.861 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:49.260Z,1557263989.260 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:49.689Z,1557263989.689 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:50.071Z,1557263990.071 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:50.472Z,1557263990.472 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:50.876Z,1557263990.876 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:51.283Z,1557263991.283 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:51.332Z,1557263991.332 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:19:51.332Z,1557263991.332 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:19:51.332Z,1557263991.332 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:19:51.332Z,1557263991.332 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:19:51.333Z,1557263991.333 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:19:51.684Z,1557263991.684 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:52.092Z,1557263992.092 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:52.509Z,1557263992.509 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:52.899Z,1557263992.899 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:53.307Z,1557263993.307 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:53.707Z,1557263993.707 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:54.120Z,1557263994.120 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:19:54.519Z,1557263994.519 [DUSBL_Hydroid](INFO): IN QUEUE:00000,187,80,81,09,FF
7,80,81,07,FF
2019-05-07T21:19:54.530Z,1557263994.530 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.074365
2019-05-07T21:19:54.531Z,1557263994.531 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:54.531Z,1557263994.531 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:54.537Z,1557263994.537 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:54.538Z,1557263994.538 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:54.918Z,1557263994.918 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:54.918Z,1557263994.918 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,09,FF
7,80,81,07,FF
2019-05-07T21:19:54.918Z,1557263994.918 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:54.918Z,1557263994.918 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:54.920Z,1557263994.920 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:55.320Z,1557263995.320 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:55.728Z,1557263995.728 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:19:55.728Z,1557263995.728 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F1,000,00000,186,80,81,0C,FF
2019-05-07T21:19:56.131Z,1557263996.131 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:56.131Z,1557263996.131 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:56.132Z,1557263996.132 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:56.133Z,1557263996.133 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:56.529Z,1557263996.529 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:56.529Z,1557263996.529 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F1,000,00000,186,80,81,0C,FF
2019-05-07T21:19:56.529Z,1557263996.529 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:56.529Z,1557263996.529 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:56.530Z,1557263996.530 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:56.933Z,1557263996.933 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:57.337Z,1557263997.337 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:19:57.337Z,1557263997.337 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,17B,000,00000,186,80,81,04,FF
2019-05-07T21:19:57.742Z,1557263997.742 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:57.742Z,1557263997.742 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:57.743Z,1557263997.743 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:57.744Z,1557263997.744 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:58.145Z,1557263998.145 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:58.145Z,1557263998.145 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
17B,000,00000,186,80,81,04,FF
2019-05-07T21:19:58.145Z,1557263998.145 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:58.146Z,1557263998.146 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:58.147Z,1557263998.147 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:19:58.549Z,1557263998.549 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:58.953Z,1557263998.953 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:19:58.953Z,1557263998.953 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,20A,000,00000,187,80,81,09,FF
2019-05-07T21:19:59.359Z,1557263999.359 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:19:59.359Z,1557263999.359 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:19:59.360Z,1557263999.360 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:19:59.360Z,1557263999.360 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:19:59.767Z,1557263999.767 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:19:59.768Z,1557263999.768 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
20A,000,00000,187,80,81,09,FF
2019-05-07T21:19:59.768Z,1557263999.768 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:19:59.768Z,1557263999.768 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:19:59.769Z,1557263999.769 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:00.165Z,1557264000.165 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:00.573Z,1557264000.573 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:00.973Z,1557264000.973 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:00.993Z,1557264000.993 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T21:20:00.993Z,1557264000.993 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T21:20:01.377Z,1557264001.377 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:01.781Z,1557264001.781 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:01.815Z,1557264001.815 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:20:01.815Z,1557264001.815 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:20:01.815Z,1557264001.815 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:20:01.816Z,1557264001.816 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:20:01.817Z,1557264001.817 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:20:01.817Z,1557264001.817 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:20:01.817Z,1557264001.817 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:20:02.185Z,1557264002.185 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:02.614Z,1557264002.614 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:02.000Z,1557264003.000 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:03.397Z,1557264003.397 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:03.801Z,1557264003.801 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:04.208Z,1557264004.208 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:04.629Z,1557264004.629 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:05.015Z,1557264005.015 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:05.419Z,1557264005.419 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,0B,FF
7,80,81,09,FF
2019-05-07T21:20:05.430Z,1557264005.430 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070451
2019-05-07T21:20:05.431Z,1557264005.431 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:05.431Z,1557264005.431 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:05.431Z,1557264005.431 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:05.432Z,1557264005.432 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:05.824Z,1557264005.824 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:05.824Z,1557264005.824 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0B,FF
7,80,81,09,FF
2019-05-07T21:20:05.824Z,1557264005.824 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:05.824Z,1557264005.824 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:05.825Z,1557264005.825 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:06.227Z,1557264006.227 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:06.636Z,1557264006.636 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T21:20:07.036Z,1557264007.036 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:07.439Z,1557264007.439 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:07.841Z,1557264007.841 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:08.246Z,1557264008.246 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:08.649Z,1557264008.649 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:09.054Z,1557264009.054 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:09.458Z,1557264009.458 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:09.861Z,1557264009.861 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:10.265Z,1557264010.265 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:10.669Z,1557264010.669 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:11.073Z,1557264011.073 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:11.477Z,1557264011.477 [DUSBL_Hydroid](INFO): IN QUEUE:!U000,185,80,81,08,FF
7,80,81,09,FF
2019-05-07T21:20:11.490Z,1557264011.490 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059117
2019-05-07T21:20:11.490Z,1557264011.490 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:11.491Z,1557264011.491 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:11.491Z,1557264011.491 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:11.494Z,1557264011.494 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:11.881Z,1557264011.881 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:11.881Z,1557264011.881 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
185,80,81,08,FF
7,80,81,09,FF
2019-05-07T21:20:11.882Z,1557264011.882 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:11.882Z,1557264011.882 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:11.883Z,1557264011.883 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:12.285Z,1557264012.285 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:12.330Z,1557264012.330 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:20:12.330Z,1557264012.330 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:20:12.330Z,1557264012.330 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T21:20:12.331Z,1557264012.331 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:20:12.332Z,1557264012.332 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:20:12.332Z,1557264012.332 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:20:12.332Z,1557264012.332 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:20:12.332Z,1557264012.332 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:20:12.689Z,1557264012.689 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:12.689Z,1557264012.689 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1CB,000,00000,187,80,81,06,FF
2019-05-07T21:20:13.093Z,1557264013.093 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:13.093Z,1557264013.093 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:13.094Z,1557264013.094 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:13.095Z,1557264013.095 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:13.497Z,1557264013.497 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:13.497Z,1557264013.497 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1CB,000,00000,187,80,81,06,FF
2019-05-07T21:20:13.497Z,1557264013.497 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:13.497Z,1557264013.497 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:13.498Z,1557264013.498 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:13.901Z,1557264013.901 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:14.305Z,1557264014.305 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:14.709Z,1557264014.709 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:15.113Z,1557264015.113 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:15.520Z,1557264015.520 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:15.924Z,1557264015.924 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:16.325Z,1557264016.325 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:16.731Z,1557264016.731 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T21:20:16.732Z,1557264016.732 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,0,00000,187,80,81,06,FF
2019-05-07T21:20:16.732Z,1557264016.732 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,0,00000,187,80,81,06,FF
2019-05-07T21:20:16.732Z,1557264016.732 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T21:20:17.133Z,1557264017.133 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:17.133Z,1557264017.133 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:17.134Z,1557264017.134 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:17.135Z,1557264017.135 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:17.537Z,1557264017.537 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T21:20:17.537Z,1557264017.537 [DUSBL_Hydroid](INFO): USBL response received:63,E4
!U1,P
0,00000,187,80,81,06,FF
2019-05-07T21:20:17.537Z,1557264017.537 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:17.538Z,1557264017.538 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:17.539Z,1557264017.539 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:17.941Z,1557264017.941 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:18.345Z,1557264018.345 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:18.345Z,1557264018.345 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,220,000,00000,187,80,81,09,FF
2019-05-07T21:20:18.755Z,1557264018.755 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:18.755Z,1557264018.755 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:18.756Z,1557264018.756 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:18.759Z,1557264018.759 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:19.159Z,1557264019.159 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:19.160Z,1557264019.160 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
220,000,00000,187,80,81,09,FF
2019-05-07T21:20:19.160Z,1557264019.160 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:19.160Z,1557264019.160 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:19.161Z,1557264019.161 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:19.557Z,1557264019.557 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:19.961Z,1557264019.961 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:19.961Z,1557264019.961 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1A6,000,00000,186,80,81,07,FF
2019-05-07T21:20:20.371Z,1557264020.371 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:20.371Z,1557264020.371 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:20.372Z,1557264020.372 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:20.373Z,1557264020.373 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:20.769Z,1557264020.769 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:20.769Z,1557264020.769 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1A6,000,00000,186,80,81,07,FF
2019-05-07T21:20:20.769Z,1557264020.769 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:20.770Z,1557264020.770 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:20.770Z,1557264020.770 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:21.173Z,1557264021.173 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:21.585Z,1557264021.585 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:21.585Z,1557264021.585 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F9,000,00000,186,80,81,0A,FF
2019-05-07T21:20:21.981Z,1557264021.981 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:21.981Z,1557264021.981 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:21.982Z,1557264021.982 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:21.984Z,1557264021.984 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:22.385Z,1557264022.385 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:22.385Z,1557264022.385 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F9,000,00000,186,80,81,0A,FF
2019-05-07T21:20:22.386Z,1557264022.386 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:22.386Z,1557264022.386 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:22.387Z,1557264022.387 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:22.789Z,1557264022.789 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:22.835Z,1557264022.835 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:20:22.835Z,1557264022.835 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:20:22.835Z,1557264022.835 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:20:22.836Z,1557264022.836 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:20:22.837Z,1557264022.837 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:20:22.837Z,1557264022.837 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:20:23.193Z,1557264023.193 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:23.622Z,1557264023.622 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:24.001Z,1557264024.001 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:24.405Z,1557264024.405 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:24.816Z,1557264024.816 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:25.213Z,1557264025.213 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:25.634Z,1557264025.634 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:26.021Z,1557264026.021 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:26.425Z,1557264026.425 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:26.829Z,1557264026.829 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:27.233Z,1557264027.233 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:27.637Z,1557264027.637 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:28.041Z,1557264028.041 [DUSBL_Hydroid](INFO): IN QUEUE:00000,187,80,81,08,FF
6,80,81,0A,FF
2019-05-07T21:20:28.055Z,1557264028.055 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.072836
2019-05-07T21:20:28.056Z,1557264028.056 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:28.056Z,1557264028.056 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:28.058Z,1557264028.058 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:28.059Z,1557264028.059 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:28.446Z,1557264028.446 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:28.446Z,1557264028.446 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,08,FF
6,80,81,0A,FF
2019-05-07T21:20:28.446Z,1557264028.446 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:28.446Z,1557264028.446 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:28.449Z,1557264028.449 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:28.867Z,1557264028.867 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:28.869Z,1557264028.869 [Micromodem](ERROR): Response from modem unexpected: $CADQF,189,1*50

2019-05-07T21:20:28.870Z,1557264028.870 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T21:20:29.258Z,1557264029.258 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:29.264Z,1557264029.264 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507212027.600357,06,149,15,0093,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,189,0.10,-999,9760,4000*5B

2019-05-07T21:20:29.664Z,1557264029.664 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:30.066Z,1557264030.066 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:30.469Z,1557264030.469 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:30.870Z,1557264030.870 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:31.273Z,1557264031.273 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:31.679Z,1557264031.679 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:32.084Z,1557264032.084 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:32.485Z,1557264032.485 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:32.889Z,1557264032.889 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:33.293Z,1557264033.293 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:33.317Z,1557264033.317 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:20:33.317Z,1557264033.317 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:20:33.317Z,1557264033.317 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:20:33.318Z,1557264033.318 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:20:33.318Z,1557264033.318 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:20:33.318Z,1557264033.318 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:20:33.318Z,1557264033.318 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:20:33.318Z,1557264033.318 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:20:33.319Z,1557264033.319 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T21:20:33.319Z,1557264033.319 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T21:20:33.319Z,1557264033.319 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:20:33.319Z,1557264033.319 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:20:33.319Z,1557264033.319 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:20:33.319Z,1557264033.319 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:20:33.319Z,1557264033.319 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:20:33.697Z,1557264033.697 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:34.101Z,1557264034.101 [DUSBL_Hydroid](INFO): IN QUEUE:00000,187,80,81,0A,FF
6,80,81,0A,FF
2019-05-07T21:20:34.114Z,1557264034.114 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.056685
2019-05-07T21:20:34.114Z,1557264034.114 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:34.115Z,1557264034.115 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:34.115Z,1557264034.115 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:34.117Z,1557264034.117 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:34.505Z,1557264034.505 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:34.505Z,1557264034.505 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,0A,FF
6,80,81,0A,FF
2019-05-07T21:20:34.505Z,1557264034.505 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:34.506Z,1557264034.506 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:34.507Z,1557264034.507 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:34.909Z,1557264034.909 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:35.319Z,1557264035.319 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:35.320Z,1557264035.320 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,206,000,00000,187,80,81,05,FF
2019-05-07T21:20:35.723Z,1557264035.723 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:35.723Z,1557264035.723 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:35.724Z,1557264035.724 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:35.727Z,1557264035.727 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:36.121Z,1557264036.121 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:36.122Z,1557264036.122 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
206,000,00000,187,80,81,05,FF
2019-05-07T21:20:36.122Z,1557264036.122 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:36.122Z,1557264036.122 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:36.123Z,1557264036.123 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:36.527Z,1557264036.527 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:36.929Z,1557264036.929 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:36.929Z,1557264036.929 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1FE,000,00000,187,80,81,09,FF
2019-05-07T21:20:37.333Z,1557264037.333 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:37.333Z,1557264037.333 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:37.334Z,1557264037.334 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:37.336Z,1557264037.336 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:37.737Z,1557264037.737 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:37.737Z,1557264037.737 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1FE,000,00000,187,80,81,09,FF
2019-05-07T21:20:37.737Z,1557264037.737 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:37.737Z,1557264037.737 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:37.738Z,1557264037.738 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:38.141Z,1557264038.141 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:38.545Z,1557264038.545 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:38.546Z,1557264038.546 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,231,000,00000,187,80,81,04,FF
2019-05-07T21:20:38.949Z,1557264038.949 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:38.949Z,1557264038.949 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:38.950Z,1557264038.950 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:38.951Z,1557264038.951 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:39.356Z,1557264039.356 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:39.356Z,1557264039.356 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
231,000,00000,187,80,81,04,FF
2019-05-07T21:20:39.356Z,1557264039.356 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:39.356Z,1557264039.356 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:39.357Z,1557264039.357 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:39.760Z,1557264039.760 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:40.163Z,1557264040.163 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:40.568Z,1557264040.568 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:40.972Z,1557264040.972 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:41.380Z,1557264041.380 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:41.780Z,1557264041.780 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:42.184Z,1557264042.184 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:42.610Z,1557264042.610 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:42.989Z,1557264042.989 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:43.393Z,1557264043.393 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:43.797Z,1557264043.797 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:43.834Z,1557264043.834 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:20:43.834Z,1557264043.834 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:20:43.834Z,1557264043.834 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater] Running Loop=10
2019-05-07T21:20:43.835Z,1557264043.835 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:20:43.836Z,1557264043.836 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:20:43.836Z,1557264043.836 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:20:43.836Z,1557264043.836 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:20:43.836Z,1557264043.836 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:20:44.201Z,1557264044.201 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:44.624Z,1557264044.624 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:20:45.009Z,1557264045.009 [DUSBL_Hydroid](INFO): IN QUEUE:00000,187,80,81,0A,FF
7,80,81,04,FF
2019-05-07T21:20:45.022Z,1557264045.022 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.072842
2019-05-07T21:20:45.022Z,1557264045.022 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:45.023Z,1557264045.023 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:45.023Z,1557264045.023 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:45.025Z,1557264045.025 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:45.413Z,1557264045.413 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:45.413Z,1557264045.413 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,0A,FF
7,80,81,04,FF
2019-05-07T21:20:45.413Z,1557264045.413 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:45.414Z,1557264045.414 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:20:45.415Z,1557264045.415 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:20:45.817Z,1557264045.817 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:46.221Z,1557264046.221 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:20:46.221Z,1557264046.221 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,19C,000,00000,186,80,81,07,FF
2019-05-07T21:20:46.631Z,1557264046.631 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:20:46.631Z,1557264046.631 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:20:46.632Z,1557264046.632 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:20:46.635Z,1557264046.635 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:20:47.029Z,1557264047.029 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:20:47.030Z,1557264047.030 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
19C,000,00000,186,80,81,07,FF
2019-05-07T21:20:47.030Z,1557264047.030 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:20:47.030Z,1557264047.030 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2