2019-05-07T21:55:31.895Z,1557266131.895 [Supervisor](DEBUG): Initializing supervisor.
2019-05-07T21:55:31.898Z,1557266131.898 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-07T21:55:31.899Z,1557266131.899 [SyncHandler](INFO): Protected caller Thread ID is 1213
2019-05-07T21:55:31.900Z,1557266131.900 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-07T21:55:31.901Z,1557266131.901 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-07T21:55:31.901Z,1557266131.901 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1214
2019-05-07T21:55:31.904Z,1557266131.904 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-07T21:55:31.916Z,1557266131.916 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-07T21:55:31.917Z,1557266131.917 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-07T21:55:31.917Z,1557266131.917 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1215
2019-05-07T21:55:31.918Z,1557266131.918 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-07T21:55:31.919Z,1557266131.919 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-07T21:55:31.920Z,1557266131.920 [logger ThreadHandler](INFO): Protected caller Thread ID is 1216
2019-05-07T21:55:31.921Z,1557266131.921 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-07T21:55:31.922Z,1557266131.922 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-07T21:55:31.923Z,1557266131.923 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-07T21:55:32.352Z,1557266132.352 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-07T21:55:32.353Z,1557266132.353 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-07T21:55:32.463Z,1557266132.463 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-07T21:55:32.463Z,1557266132.463 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-07T21:55:32.788Z,1557266132.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-07T21:55:32.789Z,1557266132.789 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-07T21:55:32.931Z,1557266132.931 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-07T21:55:32.932Z,1557266132.932 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-07T21:55:33.124Z,1557266133.124 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-07T21:55:33.124Z,1557266133.124 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-07T21:55:33.577Z,1557266133.577 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-07T21:55:33.578Z,1557266133.578 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-07T21:55:33.788Z,1557266133.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-07T21:55:33.788Z,1557266133.788 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-07T21:55:33.934Z,1557266133.934 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-07T21:55:33.935Z,1557266133.935 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-07T21:55:34.129Z,1557266134.129 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-07T21:55:34.130Z,1557266134.130 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-07T21:55:34.226Z,1557266134.226 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-07T21:55:34.227Z,1557266134.227 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-07T21:55:34.549Z,1557266134.549 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-07T21:55:34.549Z,1557266134.549 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-07T21:55:34.629Z,1557266134.629 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-07T21:55:34.733Z,1557266134.733 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-07T21:55:34.733Z,1557266134.733 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-07T21:55:35.309Z,1557266135.309 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-07T21:55:35.310Z,1557266135.310 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-07T21:55:35.701Z,1557266135.701 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-07T21:55:35.703Z,1557266135.703 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-07T21:55:35.704Z,1557266135.704 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-07T21:55:35.913Z,1557266135.913 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-07T21:55:36.013Z,1557266136.013 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-07T21:55:36.112Z,1557266136.112 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-07T21:55:36.337Z,1557266136.337 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-07T21:55:36.338Z,1557266136.338 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-07T21:55:36.423Z,1557266136.423 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-07T21:55:36.516Z,1557266136.516 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-07T21:55:36.613Z,1557266136.613 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-07T21:55:36.696Z,1557266136.696 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-07T21:55:36.804Z,1557266136.804 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-07T21:55:36.975Z,1557266136.975 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-07T21:55:37.107Z,1557266137.107 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-07T21:55:37.107Z,1557266137.107 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-07T21:55:37.120Z,1557266137.120 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-07T21:55:37.490Z,1557266137.490 [AHRS_M2] Loaded
2019-05-07T21:55:37.490Z,1557266137.490 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-07T21:55:37.563Z,1557266137.563 [DataOverHttps] Loaded
2019-05-07T21:55:37.563Z,1557266137.563 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-07T21:55:37.564Z,1557266137.564 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-07T21:55:37.565Z,1557266137.565 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1295
2019-05-07T21:55:37.578Z,1557266137.578 [Depth_Keller] Loaded
2019-05-07T21:55:37.578Z,1557266137.578 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-07T21:55:37.583Z,1557266137.583 [DropWeight] Loaded
2019-05-07T21:55:37.583Z,1557266137.583 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-07T21:55:37.639Z,1557266137.639 [DUSBL_Hydroid] Loaded
2019-05-07T21:55:37.639Z,1557266137.639 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-07T21:55:37.679Z,1557266137.679 [Micromodem] Loaded
2019-05-07T21:55:37.679Z,1557266137.679 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-07T21:55:37.776Z,1557266137.776 [NAL9602] Loaded
2019-05-07T21:55:37.776Z,1557266137.776 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-07T21:55:37.792Z,1557266137.792 [Onboard] Loaded
2019-05-07T21:55:37.792Z,1557266137.792 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-07T21:55:37.798Z,1557266137.798 [PowerOnly] Loaded
2019-05-07T21:55:37.798Z,1557266137.798 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-07T21:55:37.805Z,1557266137.805 [Radio_Surface] Loaded
2019-05-07T21:55:37.805Z,1557266137.805 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-07T21:55:37.806Z,1557266137.806 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-07T21:55:37.806Z,1557266137.806 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1296
2019-05-07T21:55:37.850Z,1557266137.850 [RDI_Pathfinder] Loaded
2019-05-07T21:55:37.850Z,1557266137.850 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-07T21:55:39.320Z,1557266139.320 [BPC1] Loaded
2019-05-07T21:55:39.320Z,1557266139.320 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-07T21:55:39.320Z,1557266139.320 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-07T21:55:39.321Z,1557266139.321 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-07T21:55:39.357Z,1557266139.357 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-07T21:55:39.357Z,1557266139.357 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-07T21:55:39.828Z,1557266139.828 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-07T21:55:39.828Z,1557266139.828 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-07T21:55:39.899Z,1557266139.899 [NavChart] Loaded
2019-05-07T21:55:39.900Z,1557266139.900 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-07T21:55:39.904Z,1557266139.904 [UniversalFixResidualReporter] Loaded
2019-05-07T21:55:39.904Z,1557266139.904 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-07T21:55:39.904Z,1557266139.904 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-07T21:55:39.905Z,1557266139.905 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-07T21:55:40.231Z,1557266140.231 [BuoyancyServo] Loaded
2019-05-07T21:55:40.231Z,1557266140.231 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-07T21:55:40.246Z,1557266140.246 [ElevatorServo] Loaded
2019-05-07T21:55:40.247Z,1557266140.247 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-07T21:55:40.261Z,1557266140.261 [MassServo] Loaded
2019-05-07T21:55:40.262Z,1557266140.262 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-07T21:55:40.277Z,1557266140.277 [RudderServo] Loaded
2019-05-07T21:55:40.277Z,1557266140.277 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-07T21:55:40.291Z,1557266140.291 [ThrusterServo] Loaded
2019-05-07T21:55:40.292Z,1557266140.292 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-07T21:55:40.292Z,1557266140.292 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-07T21:55:40.293Z,1557266140.293 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-07T21:55:40.540Z,1557266140.540 [CTD_NeilBrown] Loaded
2019-05-07T21:55:40.540Z,1557266140.540 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-07T21:55:40.541Z,1557266140.541 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-07T21:55:40.542Z,1557266140.542 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1297
2019-05-07T21:55:40.585Z,1557266140.585 [WetLabsSeaOWL_UV_A] Loaded
2019-05-07T21:55:40.586Z,1557266140.586 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-07T21:55:40.587Z,1557266140.587 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-07T21:55:40.587Z,1557266140.587 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1298
2019-05-07T21:55:40.588Z,1557266140.588 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-07T21:55:40.588Z,1557266140.588 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-07T21:55:40.874Z,1557266140.874 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-07T21:55:40.875Z,1557266140.875 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-07T21:55:40.914Z,1557266140.914 [DepthRateCalculator] Loaded
2019-05-07T21:55:40.914Z,1557266140.914 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-07T21:55:40.920Z,1557266140.920 [PitchRateCalculator] Loaded
2019-05-07T21:55:40.920Z,1557266140.920 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-07T21:55:40.932Z,1557266140.932 [SpeedCalculator] Loaded
2019-05-07T21:55:40.933Z,1557266140.933 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-07T21:55:40.953Z,1557266140.953 [TempGradientCalculator] Loaded
2019-05-07T21:55:40.953Z,1557266140.953 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-07T21:55:40.959Z,1557266140.959 [YawRateCalculator] Loaded
2019-05-07T21:55:40.959Z,1557266140.959 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-07T21:55:40.999Z,1557266140.999 [ElevatorOffsetCalculator] Loaded
2019-05-07T21:55:40.000Z,1557266141.000 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-07T21:55:40.000Z,1557266141.000 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-07T21:55:41.000Z,1557266141.000 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-07T21:55:41.135Z,1557266141.135 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-07T21:55:41.156Z,1557266141.156 [SBIT] Loaded
2019-05-07T21:55:41.157Z,1557266141.157 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-07T21:55:41.158Z,1557266141.158 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-07T21:55:41.169Z,1557266141.169 [IBIT] Loaded
2019-05-07T21:55:41.170Z,1557266141.170 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-07T21:55:41.173Z,1557266141.173 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-07T21:55:41.309Z,1557266141.309 [CBIT] Loaded
2019-05-07T21:55:41.310Z,1557266141.310 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-07T21:55:41.310Z,1557266141.310 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-07T21:55:41.311Z,1557266141.311 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-07T21:55:41.380Z,1557266141.380 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-07T21:55:41.381Z,1557266141.381 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-07T21:55:41.477Z,1557266141.477 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-07T21:55:41.478Z,1557266141.478 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-07T21:55:41.543Z,1557266141.543 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-07T21:55:41.627Z,1557266141.627 [VerticalControl] Loaded
2019-05-07T21:55:41.627Z,1557266141.627 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-07T21:55:41.628Z,1557266141.628 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-07T21:55:41.685Z,1557266141.685 [HorizontalControl] Loaded
2019-05-07T21:55:41.685Z,1557266141.685 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-07T21:55:41.686Z,1557266141.686 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-07T21:55:41.688Z,1557266141.688 [SpeedControl] Loaded
2019-05-07T21:55:41.688Z,1557266141.688 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-07T21:55:41.689Z,1557266141.689 [LoopControl](DEBUG): Construct LoopControl.
2019-05-07T21:55:41.689Z,1557266141.689 [LoopControl] Loaded
2019-05-07T21:55:41.690Z,1557266141.690 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-07T21:55:41.690Z,1557266141.690 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-07T21:55:41.691Z,1557266141.691 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-07T21:55:41.717Z,1557266141.717 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-07T21:55:41.720Z,1557266141.720 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-07T21:55:41.721Z,1557266141.721 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-07T21:55:41.728Z,1557266141.728 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-07T21:55:41.729Z,1557266141.729 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-07T21:55:41.729Z,1557266141.729 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1299
2019-05-07T21:55:41.734Z,1557266141.734 [Supervisor](INFO): Main Thread ID is 805
2019-05-07T21:55:41.734Z,1557266141.734 [Supervisor](DEBUG): Running supervisor.
2019-05-07T21:55:41.735Z,1557266141.735 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1300
2019-05-07T21:55:41.737Z,1557266141.737 [controlThread ThreadHandler](INFO): Handler Thread ID is 1301
2019-05-07T21:55:41.737Z,1557266141.737 [controlThread](DEBUG): Initializing ControlThread
2019-05-07T21:55:41.745Z,1557266141.745 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-07T21:55:41.746Z,1557266141.746 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-07T21:55:41.747Z,1557266141.747 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-07T21:55:41.747Z,1557266141.747 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-07T21:55:41.748Z,1557266141.748 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-07T21:55:41.748Z,1557266141.748 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-07T21:55:41.748Z,1557266141.748 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-07T21:55:41.749Z,1557266141.749 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-07T21:55:41.749Z,1557266141.749 [SBIT](INFO): Initialize SBIT Component.
2019-05-07T21:55:41.750Z,1557266141.750 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-07T21:55:41.750Z,1557266141.750 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-07T21:55:41.750Z,1557266141.750 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-07T21:55:41.751Z,1557266141.751 [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:55:41.753Z,1557266141.753 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-07T21:55:41.753Z,1557266141.753 [IBIT](INFO): Initialize IBIT Component.
2019-05-07T21:55:41.754Z,1557266141.754 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-07T21:55:41.755Z,1557266141.755 [logger ThreadHandler](INFO): Handler Thread ID is 1302
2019-05-07T21:55:41.766Z,1557266141.766 [CBIT](DEBUG): Initialized mux pins.
2019-05-07T21:55:41.766Z,1557266141.766 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-07T21:55:41.775Z,1557266141.775 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1303
2019-05-07T21:55:41.776Z,1557266141.776 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-07T21:55:41.787Z,1557266141.787 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1304
2019-05-07T21:55:41.790Z,1557266141.790 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-07T21:55:41.790Z,1557266141.790 [CBIT](DEBUG): Initializing heartbeat.
2019-05-07T21:55:41.799Z,1557266141.799 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1305
2019-05-07T21:55:41.800Z,1557266141.800 [CTD_NeilBrown](INFO): Powering down
2019-05-07T21:55:41.827Z,1557266141.827 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1306
2019-05-07T21:55:41.827Z,1557266141.827 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T21:55:41.859Z,1557266141.859 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1307
2019-05-07T21:55:41.862Z,1557266141.862 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-07T21:55:41.862Z,1557266141.862 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-07T21:55:41.863Z,1557266141.863 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-07T21:55:41.863Z,1557266141.863 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-07T21:55:41.863Z,1557266141.863 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-07T21:55:41.863Z,1557266141.863 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-07T21:55:41.863Z,1557266141.863 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-07T21:55:41.864Z,1557266141.864 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-07T21:55:41.864Z,1557266141.864 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-07T21:55:41.864Z,1557266141.864 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-07T21:55:41.864Z,1557266141.864 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-07T21:55:41.864Z,1557266141.864 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-07T21:55:41.865Z,1557266141.865 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-07T21:55:41.865Z,1557266141.865 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-07T21:55:41.865Z,1557266141.865 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-07T21:55:41.865Z,1557266141.865 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-07T21:55:41.865Z,1557266141.865 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-07T21:55:41.865Z,1557266141.865 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-07T21:55:41.898Z,1557266141.898 [CBIT](DEBUG): Backplane powered.
2019-05-07T21:55:41.899Z,1557266141.899 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-07T21:55:41.900Z,1557266141.900 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-07T21:55:41.901Z,1557266141.901 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-07T21:55:41.901Z,1557266141.901 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-07T21:55:41.902Z,1557266141.902 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-07T21:55:41.912Z,1557266141.912 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T21:55:41.935Z,1557266141.935 [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:55:41.936Z,1557266141.936 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-07T21:55:41.994Z,1557266141.994 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-07T21:55:42.011Z,1557266142.011 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-07T21:55:42.012Z,1557266142.012 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T21:55:42.032Z,1557266142.032 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-07T21:55:42.057Z,1557266142.057 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-07T21:55:42.079Z,1557266142.079 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-07T21:55:42.094Z,1557266142.094 [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:55:42.099Z,1557266142.099 [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:55:42.110Z,1557266142.110 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-07T21:55:42.164Z,1557266142.164 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-07T21:55:42.165Z,1557266142.165 [DUSBL_Hydroid](INFO): Powering up
2019-05-07T21:55:42.165Z,1557266142.165 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-07T21:55:42.190Z,1557266142.190 [Radio_Surface](INFO): Powering up
2019-05-07T21:55:42.239Z,1557266142.239 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T21:55:42.262Z,1557266142.262 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:55:42.275Z,1557266142.275 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-07T21:55:42.276Z,1557266142.276 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:55:42.283Z,1557266142.283 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-07T21:55:42.284Z,1557266142.284 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:55:42.291Z,1557266142.291 [MassServo](DEBUG): Initializing MassServo.
2019-05-07T21:55:42.291Z,1557266142.291 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:55:42.303Z,1557266142.303 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T21:55:42.303Z,1557266142.303 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:55:42.315Z,1557266142.315 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-07T21:55:42.524Z,1557266142.524 [Micromodem](INFO): Powering up
2019-05-07T21:55:42.525Z,1557266142.525 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-07T21:55:42.559Z,1557266142.559 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T21:55:43.242Z,1557266143.242 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-07T21:55:43.243Z,1557266143.243 [RudderServo](FAULT): Rudder failed to initialize
2019-05-07T21:55:43.243Z,1557266143.243 [RudderServo] Communications Fault, FailCount= 1
2019-05-07T21:55:43.243Z,1557266143.243 [RudderServo](ERROR): Communications Fault
2019-05-07T21:55:43.354Z,1557266143.354 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-07T21:55:43.511Z,1557266143.511 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T21:55:43.511Z,1557266143.511 [RudderServo](INFO): Powering down
2019-05-07T21:55:44.223Z,1557266144.223 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:55:44.343Z,1557266144.343 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T21:55:44.348Z,1557266144.348 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-07T21:55:44.348Z,1557266144.348 [RudderServo] No Fault, FailCount= 1
2019-05-07T21:55:55.535Z,1557266155.535 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T21:56:00.361Z,1557266160.361 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-07T21:56:08.040Z,1557266168.040 [NAL9602](INFO): Powering up NAL9602
2019-05-07T21:56:10.073Z,1557266170.073 [Micromodem](ERROR): Response from modem unexpected: $CADQF,191,1*59

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

2019-05-07T21:56:10.865Z,1557266170.865 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507215608.240961,05,336,13,0092,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,191,0.05,-999,9760,4000*58

2019-05-07T21:56:18.961Z,1557266178.961 [NAL9602](INFO): NAL9602 initialized
2019-05-07T21:56:19.762Z,1557266179.762 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:56:26.272Z,1557266186.272 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-07T21:56:26.280Z,1557266186.280 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-07T21:56:36.995Z,1557266196.995 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.023272
CHAN A1 (24V): -0.026533
CHAN A2 (12V): -0.006212
CHAN A3 (5V): -0.001854
CHAN B0 (3.3V): 0.000173
CHAN B1 (3.15aV): 0.000027
CHAN B2 (3.15bV): 0.000283
CHAN B3 (GND): 0.001986
OPEN: 0.006494
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-07T21:57:01.401Z,1557266221.401 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T21:57:01.402Z,1557266221.402 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  92.93,  87.44,   0.00
2019-05-07T21:57:14.763Z,1557266234.763 [NAL9602](INFO): SBD MO Status=2, MOMSN=3874, MT Status=2, MTMSN=0
2019-05-07T21:57:14.763Z,1557266234.763 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:57:19.644Z,1557266239.644 [SBIT](IMPORTANT): SBIT PASSED
2019-05-07T21:57:19.663Z,1557266239.663 [CommandLine](IMPORTANT): got command configSet list
2019-05-07T21:57:19.663Z,1557266239.663 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-07T21:57:19.664Z,1557266239.664 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-07T21:57:19.664Z,1557266239.664 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-07T21:57:19.664Z,1557266239.664 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-05-07T21:57:19.664Z,1557266239.664 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-07T21:57:19.665Z,1557266239.665 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-07T21:57:20.040Z,1557266240.040 [MissionManager](IMPORTANT): Started mission Startup
2019-05-07T21:57:20.040Z,1557266240.040 [Startup] Running Loop=1
2019-05-07T21:57:20.041Z,1557266240.041 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-07T21:57:20.041Z,1557266240.041 [Startup:A.GoToSurface] Running Loop=1
2019-05-07T21:57:20.041Z,1557266240.041 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:57:20.041Z,1557266240.041 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:57:20.042Z,1557266240.042 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:57:20.042Z,1557266240.042 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:57:20.043Z,1557266240.043 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:57:20.043Z,1557266240.043 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:57:20.044Z,1557266240.044 [Startup:StartupSatComms] Running Loop=1
2019-05-07T21:57:20.044Z,1557266240.044 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-07T21:57:20.045Z,1557266240.045 [Startup:StartupSatComms:A] Running Loop=1
2019-05-07T21:57:20.448Z,1557266240.448 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-07T21:57:30.938Z,1557266250.938 [NAL9602](INFO): SBD MO Status=2, MOMSN=3874, MT Status=2, MTMSN=0
2019-05-07T21:57:30.938Z,1557266250.938 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:57:57.595Z,1557266277.595 [NAL9602](INFO): SBD MO Status=2, MOMSN=3874, MT Status=2, MTMSN=0
2019-05-07T21:57:57.595Z,1557266277.595 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:58:08.044Z,1557266288.044 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005016
2019-05-07T21:58:20.236Z,1557266300.236 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-07T21:57:20.0Z
2019-05-07T21:58:20.236Z,1557266300.236 [Startup:StartupSatComms:A] Stopped
2019-05-07T21:58:20.236Z,1557266300.236 [Startup:StartupSatComms:B] Running Loop=1
2019-05-07T21:58:20.649Z,1557266300.649 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T21:58:25.726Z,1557266305.726 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190507T214802/Courier0007.lzma
2019-05-07T21:58:26.532Z,1557266306.532 [DataOverHttps](INFO): Moved sent file to Logs/20190507T214802/Courier0007.lzma.bak
2019-05-07T21:58:26.532Z,1557266306.532 [DataOverHttps](INFO): SBD MOMSN=10959722
2019-05-07T21:58:28.695Z,1557266308.695 [NAL9602](INFO): SBD MO Status=2, MOMSN=3874, MT Status=2, MTMSN=0
2019-05-07T21:58:28.695Z,1557266308.695 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:58:38.458Z,1557266318.458 [DataOverHttps](INFO): Sending 729 bytes from file Logs/20190507T214802/Express0005.lzma
2019-05-07T21:58:39.260Z,1557266319.260 [DataOverHttps](INFO): Moved sent file to Logs/20190507T214802/Express0005.lzma.bak
2019-05-07T21:58:39.260Z,1557266319.260 [DataOverHttps](INFO): SBD MOMSN=10959724
2019-05-07T21:58:42.050Z,1557266322.050 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-07T21:58:42.050Z,1557266322.050 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T21:58:42.085Z,1557266322.085 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T21:58:42.526Z,1557266322.526 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T21:58:42.526Z,1557266322.526 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-07T21:58:51.234Z,1557266331.234 [DataOverHttps](INFO): Sending 84 bytes from file Logs/20190507T214802/Express0006.lzma
2019-05-07T21:58:52.040Z,1557266332.040 [DataOverHttps](INFO): Moved sent file to Logs/20190507T214802/Express0006.lzma.bak
2019-05-07T21:58:52.040Z,1557266332.040 [DataOverHttps](INFO): SBD MOMSN=10959744
2019-05-07T21:58:54.954Z,1557266334.954 [NAL9602](INFO): SBD MO Status=2, MOMSN=3874, MT Status=2, MTMSN=0
2019-05-07T21:58:54.954Z,1557266334.954 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:59:03.650Z,1557266343.650 [DataOverHttps](INFO): Sending 638 bytes from file Logs/20190507T214802/Express0008.lzma
2019-05-07T21:59:03.849Z,1557266343.849 [NAL9602](INFO): SBD MO Status=0, MOMSN=3874, MT Status=0, MTMSN=0
2019-05-07T21:59:03.849Z,1557266343.849 [NAL9602](INFO): No messages in MT queue
2019-05-07T21:59:04.452Z,1557266344.452 [DataOverHttps](INFO): Moved sent file to Logs/20190507T214802/Express0008.lzma.bak
2019-05-07T21:59:04.452Z,1557266344.452 [DataOverHttps](INFO): SBD MOMSN=10959747
2019-05-07T21:59:04.662Z,1557266344.662 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:07.502Z,1557266347.502 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:10.322Z,1557266350.322 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:13.550Z,1557266353.550 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:16.213Z,1557266356.213 [DataOverHttps](INFO): Sending 1438 bytes from file Logs/20190507T215531/Express0001.lzma
2019-05-07T21:59:16.406Z,1557266356.406 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:17.016Z,1557266357.016 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Express0001.lzma.bak
2019-05-07T21:59:17.016Z,1557266357.016 [DataOverHttps](INFO): SBD MOMSN=10959758
2019-05-07T21:59:18.023Z,1557266358.023 [Startup:StartupSatComms:B] Stopped
2019-05-07T21:59:18.024Z,1557266358.024 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-07T21:59:18.024Z,1557266358.024 [Startup:StartupSatComms] Stopped
2019-05-07T21:59:18.024Z,1557266358.024 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-07T21:59:18.025Z,1557266358.025 [Startup](INFO): Completed Startup
2019-05-07T21:59:18.025Z,1557266358.025 [MissionManager](INFO): Startup is completed.
2019-05-07T21:59:18.025Z,1557266358.025 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-07T21:59:18.025Z,1557266358.025 [Startup] Stopped
2019-05-07T21:59:18.025Z,1557266358.025 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-07T21:59:18.025Z,1557266358.025 [Startup:A.GoToSurface] Stopped
2019-05-07T21:59:18.025Z,1557266358.025 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T21:59:18.468Z,1557266358.468 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T21:59:18.468Z,1557266358.468 [Default] Running Loop=1
2019-05-07T21:59:18.468Z,1557266358.468 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T21:59:18.469Z,1557266358.469 [Default:B.GoToSurface] Running Loop=1
2019-05-07T21:59:18.469Z,1557266358.469 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:59:18.469Z,1557266358.469 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:59:18.469Z,1557266358.469 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:59:18.469Z,1557266358.469 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:59:18.470Z,1557266358.470 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:59:18.474Z,1557266358.474 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:59:18.475Z,1557266358.475 [Default:A.Wait] Running Loop=1
2019-05-07T21:59:18.475Z,1557266358.475 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:59:19.611Z,1557266359.611 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:22.438Z,1557266362.438 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:25.270Z,1557266365.270 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:27.286Z,1557266367.286 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:29.718Z,1557266369.718 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:31.768Z,1557266371.768 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T21:59:31.768Z,1557266371.768 [Default:A.Wait] Stopped
2019-05-07T21:59:31.768Z,1557266371.768 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:59:32.155Z,1557266372.155 [Default:CheckIn] Running Loop=1
2019-05-07T21:59:32.155Z,1557266372.155 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T21:59:32.155Z,1557266372.155 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T21:59:32.542Z,1557266372.542 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:32.605Z,1557266372.605 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-07T21:59:35.371Z,1557266375.371 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:38.607Z,1557266378.607 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:41.426Z,1557266381.426 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:44.658Z,1557266384.658 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:47.486Z,1557266387.486 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:50.722Z,1557266390.722 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:53.550Z,1557266393.550 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:56.394Z,1557266396.394 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:59:59.606Z,1557266399.606 [NAL9602](DEBUG): Fix Requested
2019-05-07T22:00:02.434Z,1557266402.434 [NAL9602](DEBUG): Fix Requested
2019-05-07T22:00:02.830Z,1557266402.830 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215828.00,A,3648.16287,N,12147.28301,W,0.233,164.53,070519,,,A*7F
2019-05-07T22:00:02.833Z,1557266402.833 [NAL9602](INFO): GPS fix at 20190507T215828: (36.802715, -121.788050)
2019-05-07T22:00:02.858Z,1557266402.858 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T22:00:02.858Z,1557266402.858 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T22:00:03.277Z,1557266403.277 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T22:00:04.587Z,1557266404.587 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190507T215531/Courier0004.lzma
2019-05-07T22:00:05.132Z,1557266405.132 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Courier0004.lzma.bak
2019-05-07T22:00:05.132Z,1557266405.132 [DataOverHttps](INFO): SBD MOMSN=10959787
2019-05-07T22:00:07.493Z,1557266407.493 [CommandLine](IMPORTANT): got command show variable range
2019-05-07T22:00:07.496Z,1557266407.496 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-07T22:00:07.764Z,1557266407.764 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-07T22:00:07.764Z,1557266407.764 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-07T22:00:07.813Z,1557266407.813 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-07T22:00:07.822Z,1557266407.822 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-07T22:00:07.823Z,1557266407.823 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-07T22:00:07.825Z,1557266407.825 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-07T22:00:07.826Z,1557266407.826 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-07T22:00:07.835Z,1557266407.835 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-07T22:00:07.835Z,1557266407.835 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-07T22:00:13.898Z,1557266413.898 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-07T22:00:19.020Z,1557266419.020 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T22:00:19.021Z,1557266419.021 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T22:00:19.101Z,1557266419.101 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T22:00:19.114Z,1557266419.114 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T22:00:19.134Z,1557266419.134 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T22:00:19.138Z,1557266419.138 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T22:00:19.206Z,1557266419.206 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T22:00:19.239Z,1557266419.239 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T22:00:19.261Z,1557266419.261 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T22:00:19.285Z,1557266419.285 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T22:00:19.319Z,1557266419.319 [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-07T22:00:19.321Z,1557266419.321 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T22:00:19.689Z,1557266419.689 [Default] Stopped
2019-05-07T22:00:19.689Z,1557266419.689 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T22:00:19.689Z,1557266419.689 [Default:B.GoToSurface] Stopped
2019-05-07T22:00:19.689Z,1557266419.689 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T22:00:19.689Z,1557266419.689 [Default:CheckIn] Stopped
2019-05-07T22:00:19.690Z,1557266419.690 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T22:00:19.690Z,1557266419.690 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T22:00:19.690Z,1557266419.690 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T22:00:19.702Z,1557266419.702 [DUSBL] Running Loop=1
2019-05-07T22:00:19.702Z,1557266419.702 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:C] Running Loop=1
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:00:19.703Z,1557266419.703 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:00:19.704Z,1557266419.704 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:00:19.704Z,1557266419.704 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:00:19.704Z,1557266419.704 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:00:19.704Z,1557266419.704 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:00:19.704Z,1557266419.704 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:00:19.705Z,1557266419.705 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T22:00:19.706Z,1557266419.706 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T22:00:19.706Z,1557266419.706 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T22:00:19.718Z,1557266419.718 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T22:00:21.203Z,1557266421.203 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:21.204Z,1557266421.204 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:21.204Z,1557266421.204 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:21.205Z,1557266421.205 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:21.607Z,1557266421.607 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:21.608Z,1557266421.608 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
O
2019-05-07T22:00:21.608Z,1557266421.608 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:21.608Z,1557266421.608 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:21.609Z,1557266421.609 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:21.652Z,1557266421.652 [DataOverHttps](INFO): Sending 430 bytes from file Logs/20190507T215531/Express0005.lzma
2019-05-07T22:00:22.021Z,1557266422.021 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:22.417Z,1557266422.417 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:22.820Z,1557266422.820 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:23.094Z,1557266423.094 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Express0005.lzma.bak
2019-05-07T22:00:23.095Z,1557266423.095 [DataOverHttps](INFO): SBD MOMSN=10959790
2019-05-07T22:00:23.234Z,1557266423.234 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:23.631Z,1557266423.631 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:24.031Z,1557266424.031 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:24.436Z,1557266424.436 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:24.840Z,1557266424.840 [DUSBL_Hydroid](INFO): 10 bytes available.****
2019-05-07T22:00:24.840Z,1557266424.840 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,8
2019-05-07T22:00:24.842Z,1557266424.842 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,8
2019-05-07T22:00:24.842Z,1557266424.842 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T22:00:25.243Z,1557266425.243 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:25.243Z,1557266425.243 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:25.244Z,1557266425.244 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:25.244Z,1557266425.244 [DUSBL_Hydroid](INFO): 8 bytes available.****
2019-05-07T22:00:25.648Z,1557266425.648 [DUSBL_Hydroid](INFO): 14 bytes available.****
2019-05-07T22:00:25.648Z,1557266425.648 [DUSBL_Hydroid](INFO): USBL response received:0,63,F4
!U1,P
2019-05-07T22:00:25.648Z,1557266425.648 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:25.648Z,1557266425.648 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:25.649Z,1557266425.649 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:26.063Z,1557266426.063 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:26.475Z,1557266426.475 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:26.476Z,1557266426.476 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,F2D,000,002D7,186,80,80,13,FF
2019-05-07T22:00:26.476Z,1557266426.476 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:26.477Z,1557266426.477 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:00:26.552Z,1557266426.552 [Reporter](INFO): acoustic_contact_range 6.119999 m
2019-05-07T22:00:28.891Z,1557266428.891 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:28.891Z,1557266428.891 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:28.892Z,1557266428.892 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:28.892Z,1557266428.892 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:29.284Z,1557266429.284 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:29.284Z,1557266429.284 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
F2D,000,002D7,186,80,80,13,FF
2019-05-07T22:00:29.284Z,1557266429.284 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:29.284Z,1557266429.284 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:29.285Z,1557266429.285 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:29.694Z,1557266429.694 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:29.743Z,1557266429.743 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:00:29.743Z,1557266429.743 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:00:29.743Z,1557266429.743 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T22:00:29.744Z,1557266429.744 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:00:29.745Z,1557266429.745 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:00:29.745Z,1557266429.745 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:00:29.745Z,1557266429.745 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:00:29.745Z,1557266429.745 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:00:30.092Z,1557266430.092 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:30.092Z,1557266430.092 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,214,000,002D1,188,80,80,07,FF
2019-05-07T22:00:30.092Z,1557266430.092 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:30.092Z,1557266430.092 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:00:30.179Z,1557266430.179 [Reporter](INFO): acoustic_contact_range 5.759999 m
2019-05-07T22:00:32.524Z,1557266432.524 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:32.524Z,1557266432.524 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:32.525Z,1557266432.525 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:32.527Z,1557266432.527 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:32.927Z,1557266432.927 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:32.927Z,1557266432.927 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
214,000,002D1,188,80,80,07,FF
2019-05-07T22:00:32.927Z,1557266432.927 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:32.928Z,1557266432.928 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:32.929Z,1557266432.929 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:33.324Z,1557266433.324 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:33.728Z,1557266433.728 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:33.728Z,1557266433.728 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C1,000,002CB,186,80,80,64,FF
2019-05-07T22:00:33.728Z,1557266433.728 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:33.728Z,1557266433.728 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:00:33.839Z,1557266433.839 [Reporter](INFO): acoustic_contact_range 5.399999 m
2019-05-07T22:00:35.381Z,1557266435.381 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T22:00:36.155Z,1557266436.155 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:36.156Z,1557266436.156 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:36.156Z,1557266436.156 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:36.159Z,1557266436.159 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:36.556Z,1557266436.556 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:36.556Z,1557266436.556 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C1,000,002CB,186,80,80,64,FF
2019-05-07T22:00:36.556Z,1557266436.556 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:36.556Z,1557266436.556 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:36.557Z,1557266436.557 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:36.960Z,1557266436.960 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:37.385Z,1557266437.385 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:37.386Z,1557266437.386 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1CA,000,002CD,186,80,80,62,FF
2019-05-07T22:00:37.415Z,1557266437.415 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:37.416Z,1557266437.416 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:00:37.464Z,1557266437.464 [Reporter](INFO): acoustic_contact_range 5.520000 m
2019-05-07T22:00:39.807Z,1557266439.807 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:39.807Z,1557266439.807 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:39.808Z,1557266439.808 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:39.809Z,1557266439.809 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:40.219Z,1557266440.219 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:40.219Z,1557266440.219 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1CA,000,002CD,186,80,80,62,FF
2019-05-07T22:00:40.219Z,1557266440.219 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:40.220Z,1557266440.220 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:40.220Z,1557266440.220 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:40.269Z,1557266440.269 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:00:40.270Z,1557266440.270 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:00:40.270Z,1557266440.270 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:00:40.272Z,1557266440.272 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:00:40.273Z,1557266440.273 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:00:40.273Z,1557266440.273 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:00:40.273Z,1557266440.273 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:00:40.273Z,1557266440.273 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:00:40.273Z,1557266440.273 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T22:00:40.273Z,1557266440.273 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T22:00:40.273Z,1557266440.273 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:00:40.274Z,1557266440.274 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:00:40.274Z,1557266440.274 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:00:40.274Z,1557266440.274 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:00:40.274Z,1557266440.274 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:00:40.616Z,1557266440.616 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:41.016Z,1557266441.016 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:41.016Z,1557266441.016 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C0,000,002CB,186,80,80,68,FF
2019-05-07T22:00:41.016Z,1557266441.016 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:41.016Z,1557266441.016 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:00:41.172Z,1557266441.172 [Reporter](INFO): acoustic_contact_range 5.399999 m
2019-05-07T22:00:43.427Z,1557266443.427 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:43.428Z,1557266443.428 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:43.428Z,1557266443.428 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:43.431Z,1557266443.431 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:43.828Z,1557266443.828 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:44.239Z,1557266444.239 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:44.640Z,1557266444.640 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:45.040Z,1557266445.040 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:45.455Z,1557266445.455 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:45.853Z,1557266445.853 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:46.279Z,1557266446.279 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:46.655Z,1557266446.655 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:47.068Z,1557266447.068 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:47.479Z,1557266447.479 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:47.883Z,1557266447.883 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:48.276Z,1557266448.276 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:48.683Z,1557266448.683 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:49.080Z,1557266449.080 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:49.487Z,1557266449.487 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T22:00:49.498Z,1557266449.498 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070085
2019-05-07T22:00:49.499Z,1557266449.499 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:49.499Z,1557266449.499 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:49.499Z,1557266449.499 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:49.502Z,1557266449.502 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:49.887Z,1557266449.887 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:49.888Z,1557266449.888 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C0,000,002CB,186,80,80,68,FF
2019-05-07T22:00:49.888Z,1557266449.888 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:49.888Z,1557266449.888 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:49.889Z,1557266449.889 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:50.295Z,1557266450.295 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:50.700Z,1557266450.700 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:50.700Z,1557266450.700 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,013,000,00000,184,80,81,0C,FF
2019-05-07T22:00:50.700Z,1557266450.700 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:50.701Z,1557266450.701 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:00:50.734Z,1557266450.734 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:00:50.735Z,1557266450.735 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:00:50.735Z,1557266450.735 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:00:50.735Z,1557266450.735 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:00:50.735Z,1557266450.735 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:00:50.735Z,1557266450.735 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:00:50.736Z,1557266450.736 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:00:51.099Z,1557266451.099 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:51.100Z,1557266451.100 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:51.100Z,1557266451.100 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:51.102Z,1557266451.102 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:51.504Z,1557266451.504 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:51.504Z,1557266451.504 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
013,000,00000,184,80,81,0C,FF
2019-05-07T22:00:51.504Z,1557266451.504 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:51.504Z,1557266451.504 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:51.505Z,1557266451.505 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:51.908Z,1557266451.908 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:52.340Z,1557266452.340 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:52.726Z,1557266452.726 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:53.120Z,1557266453.120 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:53.524Z,1557266453.524 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:53.931Z,1557266453.931 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:54.338Z,1557266454.338 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:54.735Z,1557266454.735 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T22:00:54.735Z,1557266454.735 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,0,00000,184,80,81,0C,FF
2019-05-07T22:00:54.737Z,1557266454.737 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,0,00000,184,80,81,0C,FF
2019-05-07T22:00:54.737Z,1557266454.737 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T22:00:55.140Z,1557266455.140 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:55.140Z,1557266455.140 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:55.140Z,1557266455.140 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:55.142Z,1557266455.142 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:55.548Z,1557266455.548 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T22:00:55.548Z,1557266455.548 [DUSBL_Hydroid](INFO): USBL response received:63,F4
!U1,P
0,00000,184,80,81,0C,FF
2019-05-07T22:00:55.548Z,1557266455.548 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:55.548Z,1557266455.548 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:55.549Z,1557266455.549 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:55.948Z,1557266455.948 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:56.358Z,1557266456.358 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:56.358Z,1557266456.358 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1D7,000,002CE,186,80,80,6E,FF
2019-05-07T22:00:56.359Z,1557266456.359 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:56.359Z,1557266456.359 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:00:56.393Z,1557266456.393 [Reporter](INFO): acoustic_contact_range 5.580000 m
2019-05-07T22:00:58.779Z,1557266458.779 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:00:58.780Z,1557266458.780 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:00:58.780Z,1557266458.780 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:00:58.783Z,1557266458.783 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:59.227Z,1557266459.227 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:00:59.227Z,1557266459.227 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1D7,000,002CE,186,80,80,6E,FF
2019-05-07T22:00:59.227Z,1557266459.227 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:00:59.227Z,1557266459.227 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:00:59.229Z,1557266459.229 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:00:59.584Z,1557266459.584 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:00:59.988Z,1557266459.988 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:00:59.988Z,1557266459.988 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E8,000,002CD,186,80,80,5C,FF
2019-05-07T22:00:59.988Z,1557266459.988 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:00:59.988Z,1557266459.988 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:00.036Z,1557266460.036 [Reporter](INFO): acoustic_contact_range 5.520000 m
2019-05-07T22:01:01.225Z,1557266461.225 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:01:01.225Z,1557266461.225 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:01:01.226Z,1557266461.226 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:01:01.227Z,1557266461.227 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:01:01.228Z,1557266461.228 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:01:01.228Z,1557266461.228 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:01:01.228Z,1557266461.228 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:01:02.411Z,1557266462.411 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:02.411Z,1557266462.411 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:02.412Z,1557266462.412 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:02.412Z,1557266462.412 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:02.816Z,1557266462.816 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:03.232Z,1557266463.232 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:03.624Z,1557266463.624 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:04.031Z,1557266464.031 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:04.432Z,1557266464.432 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:04.836Z,1557266464.836 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:05.247Z,1557266465.247 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:05.644Z,1557266465.644 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:06.051Z,1557266466.051 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:06.455Z,1557266466.455 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:06.856Z,1557266466.856 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:07.264Z,1557266467.264 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:07.667Z,1557266467.667 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:08.068Z,1557266468.068 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:08.472Z,1557266468.472 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T22:01:08.482Z,1557266468.482 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070519
2019-05-07T22:01:08.483Z,1557266468.483 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:08.483Z,1557266468.483 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:08.484Z,1557266468.484 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:08.485Z,1557266468.485 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:08.880Z,1557266468.880 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:08.880Z,1557266468.880 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E8,000,002CD,186,80,80,5C,FF
2019-05-07T22:01:08.880Z,1557266468.880 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:08.880Z,1557266468.880 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:08.881Z,1557266468.881 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:09.280Z,1557266469.280 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:09.687Z,1557266469.687 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:09.688Z,1557266469.688 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E7,000,002CE,186,80,80,63,FF
2019-05-07T22:01:09.688Z,1557266469.688 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:09.688Z,1557266469.688 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:09.797Z,1557266469.797 [Reporter](INFO): acoustic_contact_range 5.580000 m
2019-05-07T22:01:11.866Z,1557266471.866 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:01:11.866Z,1557266471.866 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:01:11.866Z,1557266471.866 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:01:11.867Z,1557266471.867 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:01:11.867Z,1557266471.867 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:01:11.867Z,1557266471.867 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:01:11.867Z,1557266471.867 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:01:11.867Z,1557266471.867 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:01:11.867Z,1557266471.867 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T22:01:11.867Z,1557266471.867 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T22:01:11.868Z,1557266471.868 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:01:11.868Z,1557266471.868 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:01:11.868Z,1557266471.868 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:01:11.868Z,1557266471.868 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:01:11.868Z,1557266471.868 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:01:12.108Z,1557266472.108 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:12.108Z,1557266472.108 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:12.108Z,1557266472.108 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:12.111Z,1557266472.111 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:12.518Z,1557266472.518 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:12.519Z,1557266472.519 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E7,000,002CE,186,80,80,63,FF
2019-05-07T22:01:12.519Z,1557266472.519 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:12.519Z,1557266472.519 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:12.521Z,1557266472.521 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:12.916Z,1557266472.916 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:13.324Z,1557266473.324 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:13.324Z,1557266473.324 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,206,000,00000,187,80,81,0F,FF
2019-05-07T22:01:13.324Z,1557266473.324 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:13.324Z,1557266473.324 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:01:13.723Z,1557266473.723 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:13.724Z,1557266473.724 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:13.724Z,1557266473.724 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:13.726Z,1557266473.726 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:14.131Z,1557266474.131 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:14.132Z,1557266474.132 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
206,000,00000,187,80,81,0F,FF
2019-05-07T22:01:14.132Z,1557266474.132 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:14.132Z,1557266474.132 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:14.133Z,1557266474.133 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:14.536Z,1557266474.536 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:14.939Z,1557266474.939 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:15.344Z,1557266475.344 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T22:01:15.744Z,1557266475.744 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:16.147Z,1557266476.147 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:16.560Z,1557266476.560 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:16.956Z,1557266476.956 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:17.376Z,1557266477.376 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:17.767Z,1557266477.767 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:18.168Z,1557266478.168 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:18.572Z,1557266478.572 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:18.976Z,1557266478.976 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:19.384Z,1557266479.384 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:19.790Z,1557266479.790 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,187,80,81,0E,FF
7,80,81,0F,FF
2019-05-07T22:01:19.802Z,1557266479.802 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.078109
2019-05-07T22:01:19.803Z,1557266479.803 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:19.803Z,1557266479.803 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:19.803Z,1557266479.803 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:19.805Z,1557266479.805 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:20.200Z,1557266480.200 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:20.200Z,1557266480.200 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,0E,FF
7,80,81,0F,FF
2019-05-07T22:01:20.200Z,1557266480.200 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:20.200Z,1557266480.200 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:20.201Z,1557266480.201 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:20.606Z,1557266480.606 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:20.996Z,1557266480.996 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:20.996Z,1557266480.996 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,E6D,000,004B4,186,80,80,1B,FF
2019-05-07T22:01:20.996Z,1557266480.996 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:20.996Z,1557266480.996 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:21.148Z,1557266481.148 [Reporter](INFO): acoustic_contact_range 34.740002 m
2019-05-07T22:01:22.258Z,1557266482.258 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:01:22.258Z,1557266482.258 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:01:22.258Z,1557266482.258 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:01:22.260Z,1557266482.260 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:01:22.260Z,1557266482.260 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:01:22.260Z,1557266482.260 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:01:22.260Z,1557266482.260 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:01:22.260Z,1557266482.260 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:01:22.260Z,1557266482.260 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T22:01:22.261Z,1557266482.261 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T22:01:22.261Z,1557266482.261 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:01:22.261Z,1557266482.261 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:01:22.261Z,1557266482.261 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:01:22.261Z,1557266482.261 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:01:22.261Z,1557266482.261 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:01:23.423Z,1557266483.423 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:23.423Z,1557266483.423 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:23.424Z,1557266483.424 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:23.427Z,1557266483.427 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:23.828Z,1557266483.828 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:23.828Z,1557266483.828 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
E6D,000,004B4,186,80,80,1B,FF
2019-05-07T22:01:23.828Z,1557266483.828 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:23.828Z,1557266483.828 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:23.829Z,1557266483.829 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:24.228Z,1557266484.228 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:24.632Z,1557266484.632 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:24.632Z,1557266484.632 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1A7,000,0026C,185,80,80,13,FF
2019-05-07T22:01:24.632Z,1557266484.632 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:24.633Z,1557266484.633 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:01:25.039Z,1557266485.039 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:25.039Z,1557266485.039 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:25.040Z,1557266485.040 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:25.041Z,1557266485.041 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:25.437Z,1557266485.437 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:25.844Z,1557266485.844 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:26.251Z,1557266486.251 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:26.652Z,1557266486.652 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:27.060Z,1557266487.060 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:27.457Z,1557266487.457 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:27.867Z,1557266487.867 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:28.272Z,1557266488.272 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:28.671Z,1557266488.671 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:29.076Z,1557266489.076 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:29.484Z,1557266489.484 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:29.891Z,1557266489.891 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:30.292Z,1557266490.292 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:30.692Z,1557266490.692 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:31.095Z,1557266491.095 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T22:01:31.106Z,1557266491.106 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.066460
2019-05-07T22:01:31.107Z,1557266491.107 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:31.107Z,1557266491.107 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:31.108Z,1557266491.108 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:31.109Z,1557266491.109 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:31.500Z,1557266491.500 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:31.500Z,1557266491.500 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1A7,000,0026C,185,80,80,13,FF
2019-05-07T22:01:31.500Z,1557266491.500 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:31.500Z,1557266491.500 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:31.501Z,1557266491.501 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:31.904Z,1557266491.904 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:32.308Z,1557266492.308 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:32.308Z,1557266492.308 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C0,000,002CB,186,80,80,63,FF
2019-05-07T22:01:32.308Z,1557266492.308 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:32.308Z,1557266492.308 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:32.348Z,1557266492.348 [Reporter](INFO): acoustic_contact_range 5.399999 m
2019-05-07T22:01:32.745Z,1557266492.745 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:01:32.745Z,1557266492.745 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:01:32.745Z,1557266492.745 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:01:32.746Z,1557266492.746 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:01:32.746Z,1557266492.746 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:01:32.747Z,1557266492.747 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:01:34.731Z,1557266494.731 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:34.731Z,1557266494.731 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:34.732Z,1557266494.732 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:34.735Z,1557266494.735 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:35.140Z,1557266495.140 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:35.140Z,1557266495.140 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C0,000,002CB,186,80,80,63,FF
2019-05-07T22:01:35.140Z,1557266495.140 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:35.140Z,1557266495.140 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:35.141Z,1557266495.141 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:35.539Z,1557266495.539 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:35.944Z,1557266495.944 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:35.944Z,1557266495.944 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C6,000,002CA,186,80,80,5B,FF
2019-05-07T22:01:35.944Z,1557266495.944 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:35.944Z,1557266495.944 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:36.007Z,1557266496.007 [Reporter](INFO): acoustic_contact_range 5.339999 m
2019-05-07T22:01:38.427Z,1557266498.427 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:38.427Z,1557266498.427 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:38.427Z,1557266498.427 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:38.428Z,1557266498.428 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:38.772Z,1557266498.772 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:38.772Z,1557266498.772 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C6,000,002CA,186,80,80,5B,FF
2019-05-07T22:01:38.772Z,1557266498.772 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:38.772Z,1557266498.772 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:38.773Z,1557266498.773 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:39.180Z,1557266499.180 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:39.580Z,1557266499.580 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:39.580Z,1557266499.580 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1B8,000,0027E,186,80,80,0F,FF
2019-05-07T22:01:39.580Z,1557266499.580 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:39.580Z,1557266499.580 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:39.640Z,1557266499.640 [Reporter](INFO): acoustic_contact_range 0.780000 m
2019-05-07T22:01:42.003Z,1557266502.003 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:42.003Z,1557266502.003 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:42.004Z,1557266502.004 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:42.007Z,1557266502.007 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:42.408Z,1557266502.408 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:42.408Z,1557266502.408 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1B8,000,0027E,186,80,80,0F,FF
2019-05-07T22:01:42.408Z,1557266502.408 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:42.408Z,1557266502.408 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:42.409Z,1557266502.409 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:42.811Z,1557266502.811 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:43.223Z,1557266503.223 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T22:01:43.253Z,1557266503.253 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:01:43.253Z,1557266503.253 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:01:43.253Z,1557266503.253 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:01:43.254Z,1557266503.254 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:01:43.254Z,1557266503.254 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:01:43.254Z,1557266503.254 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:01:43.254Z,1557266503.254 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:01:43.255Z,1557266503.255 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:01:43.620Z,1557266503.620 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:44.027Z,1557266504.027 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:44.428Z,1557266504.428 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:44.836Z,1557266504.836 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:45.236Z,1557266505.236 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:45.644Z,1557266505.644 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:46.047Z,1557266506.047 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:46.451Z,1557266506.451 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:46.852Z,1557266506.852 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:47.256Z,1557266507.256 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:47.663Z,1557266507.663 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:01:48.067Z,1557266508.067 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,187,80,81,11,FF
6,80,80,0F,FF
2019-05-07T22:01:48.078Z,1557266508.078 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.074225
2019-05-07T22:01:48.079Z,1557266508.079 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:48.079Z,1557266508.079 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:48.079Z,1557266508.079 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:48.082Z,1557266508.082 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:48.471Z,1557266508.471 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:48.472Z,1557266508.472 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,11,FF
6,80,80,0F,FF
2019-05-07T22:01:48.472Z,1557266508.472 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:48.472Z,1557266508.472 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:48.473Z,1557266508.473 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:48.871Z,1557266508.871 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:49.280Z,1557266509.280 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:49.280Z,1557266509.280 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,0ED,000,00000,186,80,81,11,FF
2019-05-07T22:01:49.280Z,1557266509.280 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:49.280Z,1557266509.280 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:01:49.680Z,1557266509.680 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:49.680Z,1557266509.680 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:49.681Z,1557266509.681 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:49.682Z,1557266509.682 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:50.088Z,1557266510.088 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:50.088Z,1557266510.088 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
0ED,000,00000,186,80,81,11,FF
2019-05-07T22:01:50.088Z,1557266510.088 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:50.088Z,1557266510.088 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:50.089Z,1557266510.089 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:50.488Z,1557266510.488 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:50.895Z,1557266510.895 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:51.293Z,1557266511.293 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:51.700Z,1557266511.700 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:52.104Z,1557266512.104 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:52.507Z,1557266512.507 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:52.912Z,1557266512.912 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:53.317Z,1557266513.317 [DUSBL_Hydroid](INFO): 11 bytes available.****
2019-05-07T22:01:53.318Z,1557266513.318 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,8000,00000,186,80,81,11,FF
2019-05-07T22:01:53.320Z,1557266513.320 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,8000,00000,186,80,81,11,FF
2019-05-07T22:01:53.320Z,1557266513.320 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T22:01:53.719Z,1557266513.719 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:53.719Z,1557266513.719 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:53.720Z,1557266513.720 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:53.721Z,1557266513.721 [DUSBL_Hydroid](INFO): 7 bytes available.****
2019-05-07T22:01:53.791Z,1557266513.791 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:01:53.791Z,1557266513.791 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:01:53.791Z,1557266513.791 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:01:53.791Z,1557266513.791 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:01:53.791Z,1557266513.791 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater] Running Loop=10
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:01:53.792Z,1557266513.792 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:01:54.124Z,1557266514.124 [DUSBL_Hydroid](INFO): 13 bytes available.****
2019-05-07T22:01:54.124Z,1557266514.124 [DUSBL_Hydroid](INFO): USBL response received:,63,F4
!U1,P
,00000,186,80,81,11,FF
2019-05-07T22:01:54.124Z,1557266514.124 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:54.124Z,1557266514.124 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:54.126Z,1557266514.126 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:54.528Z,1557266514.528 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:54.534Z,1557266514.534 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507220152.314923,06,121,14,0100,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,200,0.00,-999,9760,4000*57

2019-05-07T22:01:54.932Z,1557266514.932 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:54.932Z,1557266514.932 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C1,000,002D1,186,80,80,60,FF
2019-05-07T22:01:54.933Z,1557266514.933 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:54.933Z,1557266514.933 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:55.043Z,1557266515.043 [Reporter](INFO): acoustic_contact_range 5.759999 m
2019-05-07T22:01:57.373Z,1557266517.373 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:01:57.374Z,1557266517.374 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:01:57.375Z,1557266517.375 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:01:57.387Z,1557266517.387 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:57.767Z,1557266517.767 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:01:57.767Z,1557266517.767 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C1,000,002D1,186,80,80,60,FF
2019-05-07T22:01:57.767Z,1557266517.767 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:01:57.767Z,1557266517.767 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:01:57.768Z,1557266517.768 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:01:58.166Z,1557266518.166 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:01:58.576Z,1557266518.576 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:01:58.576Z,1557266518.576 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,EC7,000,0037E,186,80,80,0A,FF
2019-05-07T22:01:58.576Z,1557266518.576 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:01:58.576Z,1557266518.576 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:01:58.679Z,1557266518.679 [Reporter](INFO): acoustic_contact_range 16.139999 m
2019-05-07T22:02:00.995Z,1557266520.995 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:02:00.995Z,1557266520.995 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:02:00.996Z,1557266520.996 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:02:00.997Z,1557266520.997 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:02:01.403Z,1557266521.403 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:02:01.403Z,1557266521.403 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
EC7,000,0037E,186,80,80,0A,FF
2019-05-07T22:02:01.403Z,1557266521.403 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:02:01.403Z,1557266521.403 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:02:01.404Z,1557266521.404 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:02:01.804Z,1557266521.804 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:02:02.207Z,1557266522.207 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:02:02.208Z,1557266522.208 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1CC,000,002D2,187,80,80,63,FF
2019-05-07T22:02:02.208Z,1557266522.208 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:02:02.208Z,1557266522.208 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:02:02.313Z,1557266522.313 [Reporter](INFO): acoustic_contact_range 5.820000 m
2019-05-07T22:02:04.264Z,1557266524.264 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:02:04.265Z,1557266524.265 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:02:04.265Z,1557266524.265 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:02:04.265Z,1557266524.265 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:02:04.265Z,1557266524.265 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:02:04.265Z,1557266524.265 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:02:04.265Z,1557266524.265 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:02:04.266Z,1557266524.266 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:02:04.266Z,1557266524.266 [DUSBL](INFO): Completed DUSBL
2019-05-07T22:02:04.267Z,1557266524.267 [MissionManager](INFO): DUSBL is completed.
2019-05-07T22:02:04.267Z,1557266524.267 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T22:02:04.267Z,1557266524.267 [DUSBL] Stopped
2019-05-07T22:02:04.267Z,1557266524.267 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T22:02:04.267Z,1557266524.267 [DUSBL:A.Pitch] Stopped
2019-05-07T22:02:04.267Z,1557266524.267 [DUSBL:B.SetSpeed] Stopped
2019-05-07T22:02:04.267Z,1557266524.267 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T22:02:04.267Z,1557266524.267 [DUSBL:C] Stopped
2019-05-07T22:02:04.686Z,1557266524.686 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T22:02:04.686Z,1557266524.686 [Default] Running Loop=1
2019-05-07T22:02:04.686Z,1557266524.686 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T22:02:04.686Z,1557266524.686 [Default:B.GoToSurface] Running Loop=1
2019-05-07T22:02:04.686Z,1557266524.686 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T22:02:04.687Z,1557266524.687 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T22:02:04.687Z,1557266524.687 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T22:02:04.687Z,1557266524.687 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T22:02:04.688Z,1557266524.688 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T22:02:04.688Z,1557266524.688 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T22:02:04.688Z,1557266524.688 [Default:A.Wait] Running Loop=1
2019-05-07T22:02:04.688Z,1557266524.688 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:02:18.001Z,1557266538.001 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T22:02:18.001Z,1557266538.001 [Default:A.Wait] Stopped
2019-05-07T22:02:18.001Z,1557266538.001 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:02:18.486Z,1557266538.486 [Default:CheckIn] Running Loop=1
2019-05-07T22:02:18.486Z,1557266538.486 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T22:02:18.490Z,1557266538.490 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T22:02:19.991Z,1557266539.991 [NAL9602](DEBUG): Fix Requested
2019-05-07T22:02:20.412Z,1557266540.412 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220045.00,A,3648.16346,N,12147.28157,W,0.253,164.53,070519,,,A*71
2019-05-07T22:02:20.414Z,1557266540.414 [NAL9602](INFO): GPS fix at 20190507T220045: (36.802724, -121.788026)
2019-05-07T22:02:20.471Z,1557266540.471 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T22:02:20.472Z,1557266540.472 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T22:02:27.558Z,1557266547.558 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190507T215531/Courier0007.lzma
2019-05-07T22:02:28.367Z,1557266548.367 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Courier0007.lzma.bak
2019-05-07T22:02:28.368Z,1557266548.368 [DataOverHttps](INFO): SBD MOMSN=10959795
2019-05-07T22:02:37.501Z,1557266557.501 [NAL9602](INFO): SBD MO Status=2, MOMSN=3875, MT Status=2, MTMSN=0
2019-05-07T22:02:37.501Z,1557266557.501 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T22:02:40.887Z,1557266560.887 [DataOverHttps](INFO): Sending 945 bytes from file Logs/20190507T215531/Express0008.lzma
2019-05-07T22:02:41.692Z,1557266561.692 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Express0008.lzma.bak
2019-05-07T22:02:41.692Z,1557266561.692 [DataOverHttps](INFO): SBD MOMSN=10959799
2019-05-07T22:02:42.789Z,1557266562.789 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T22:02:42.789Z,1557266562.789 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T22:02:42.790Z,1557266562.790 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:02:50.814Z,1557266570.814 [NAL9602](INFO): SBD MO Status=2, MOMSN=3875, MT Status=2, MTMSN=0
2019-05-07T22:02:50.835Z,1557266570.835 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T22:03:53.466Z,1557266633.466 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-07T22:03:53.469Z,1557266633.469 [BPC1](INFO): Received data from all battery sticks.
2019-05-07T22:06:05.543Z,1557266765.543 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T22:06:05.544Z,1557266765.544 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T22:06:05.594Z,1557266765.594 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T22:06:05.628Z,1557266765.628 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T22:06:05.639Z,1557266765.639 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T22:06:05.641Z,1557266765.641 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T22:06:05.647Z,1557266765.647 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T22:06:05.648Z,1557266765.648 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T22:06:05.673Z,1557266765.673 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T22:06:05.684Z,1557266765.684 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T22:06:05.692Z,1557266765.692 [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-07T22:06:05.694Z,1557266765.694 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T22:06:05.973Z,1557266765.973 [Default] Stopped
2019-05-07T22:06:05.973Z,1557266765.973 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T22:06:05.973Z,1557266765.973 [Default:B.GoToSurface] Stopped
2019-05-07T22:06:05.973Z,1557266765.973 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T22:06:05.973Z,1557266765.973 [Default:CheckIn] Stopped
2019-05-07T22:06:05.974Z,1557266765.974 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T22:06:05.974Z,1557266765.974 [Default:CheckIn:C.Wait] Stopped
2019-05-07T22:06:05.974Z,1557266765.974 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:06:05.974Z,1557266765.974 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T22:06:05.974Z,1557266765.974 [DUSBL] Running Loop=1
2019-05-07T22:06:05.974Z,1557266765.974 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T22:06:05.974Z,1557266765.974 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T22:06:05.975Z,1557266765.975 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T22:06:05.975Z,1557266765.975 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T22:06:05.975Z,1557266765.975 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T22:06:05.975Z,1557266765.975 [DUSBL:C] Running Loop=1
2019-05-07T22:06:05.975Z,1557266765.975 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T22:06:05.975Z,1557266765.975 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:06:05.975Z,1557266765.975 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:06:05.976Z,1557266765.976 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:06:05.976Z,1557266765.976 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:06:05.976Z,1557266765.976 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:06:05.976Z,1557266765.976 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:06:05.976Z,1557266765.976 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:06:05.977Z,1557266765.977 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T22:06:05.977Z,1557266765.977 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T22:06:05.978Z,1557266765.978 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T22:06:05.978Z,1557266765.978 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T22:06:07.563Z,1557266767.563 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:07.563Z,1557266767.563 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:07.564Z,1557266767.564 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:07.567Z,1557266767.567 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:07.967Z,1557266767.967 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:07.968Z,1557266767.968 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1CC,000,002D2,187,80,80,63,FF
2019-05-07T22:06:07.968Z,1557266767.968 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:07.968Z,1557266767.968 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:07.969Z,1557266767.969 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:08.392Z,1557266768.392 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:08.776Z,1557266768.776 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:09.176Z,1557266769.176 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:09.579Z,1557266769.579 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:09.988Z,1557266769.988 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:10.397Z,1557266770.397 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:10.791Z,1557266770.791 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:11.200Z,1557266771.200 [DUSBL_Hydroid](INFO): 14 bytes available.****
2019-05-07T22:06:11.200Z,1557266771.200 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,63002D2,187,80,80,63,FF
2019-05-07T22:06:11.202Z,1557266771.202 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63002D2,187,80,80,63,FF
2019-05-07T22:06:11.203Z,1557266771.203 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T22:06:11.603Z,1557266771.603 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:11.603Z,1557266771.603 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:11.604Z,1557266771.604 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:11.605Z,1557266771.605 [DUSBL_Hydroid](INFO): 4 bytes available.****
2019-05-07T22:06:12.007Z,1557266772.007 [DUSBL_Hydroid](INFO): 10 bytes available.****
2019-05-07T22:06:12.008Z,1557266772.008 [DUSBL_Hydroid](INFO): USBL response received:,F4
!U1,P
0,63002D2,187,80,80,63,FF
2019-05-07T22:06:12.008Z,1557266772.008 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:12.008Z,1557266772.008 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:12.009Z,1557266772.009 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:12.412Z,1557266772.412 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:12.413Z,1557266772.413 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T22:06:12.420Z,1557266772.420 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507220610.567576,06,682,16,0112,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,198,0.00,-999,9760,4000*55

2019-05-07T22:06:12.812Z,1557266772.812 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:12.812Z,1557266772.812 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E7,000,00000,186,80,81,0C,FF
2019-05-07T22:06:12.812Z,1557266772.812 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:12.812Z,1557266772.812 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:13.216Z,1557266773.216 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:13.216Z,1557266773.216 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:13.217Z,1557266773.217 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:13.218Z,1557266773.218 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:13.620Z,1557266773.620 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:13.620Z,1557266773.620 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E7,000,00000,186,80,81,0C,FF
2019-05-07T22:06:13.620Z,1557266773.620 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:13.620Z,1557266773.620 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:13.621Z,1557266773.621 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:14.024Z,1557266774.024 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:14.434Z,1557266774.434 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:14.435Z,1557266774.435 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1D5,000,00000,187,80,81,0E,FF
2019-05-07T22:06:14.435Z,1557266774.435 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:14.435Z,1557266774.435 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:14.831Z,1557266774.831 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:14.832Z,1557266774.832 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:14.832Z,1557266774.832 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:14.835Z,1557266774.835 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:15.239Z,1557266775.239 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:15.240Z,1557266775.240 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1D5,000,00000,187,80,81,0E,FF
2019-05-07T22:06:15.240Z,1557266775.240 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:15.240Z,1557266775.240 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:15.241Z,1557266775.241 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:15.640Z,1557266775.640 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:16.044Z,1557266776.044 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:16.044Z,1557266776.044 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F7,000,00000,186,80,81,10,FF
2019-05-07T22:06:16.044Z,1557266776.044 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:16.045Z,1557266776.045 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:16.073Z,1557266776.073 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:06:16.073Z,1557266776.073 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:06:16.073Z,1557266776.073 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:06:16.074Z,1557266776.074 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:06:16.075Z,1557266776.075 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:06:16.076Z,1557266776.076 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:06:16.076Z,1557266776.076 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:06:16.076Z,1557266776.076 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:06:16.447Z,1557266776.447 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:16.448Z,1557266776.448 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:16.448Z,1557266776.448 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:16.450Z,1557266776.450 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:16.852Z,1557266776.852 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:16.852Z,1557266776.852 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F7,000,00000,186,80,81,10,FF
2019-05-07T22:06:16.852Z,1557266776.852 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:16.852Z,1557266776.852 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:16.853Z,1557266776.853 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:17.256Z,1557266777.256 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:17.660Z,1557266777.660 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:17.660Z,1557266777.660 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1B4,000,0027B,186,80,80,0F,FF
2019-05-07T22:06:17.660Z,1557266777.660 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:17.660Z,1557266777.660 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:06:17.704Z,1557266777.704 [Reporter](INFO): acoustic_contact_range 0.599999 m
2019-05-07T22:06:20.087Z,1557266780.087 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:20.087Z,1557266780.087 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:20.088Z,1557266780.088 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:20.091Z,1557266780.091 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:20.488Z,1557266780.488 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:20.488Z,1557266780.488 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1B4,000,0027B,186,80,80,0F,FF
2019-05-07T22:06:20.488Z,1557266780.488 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:20.488Z,1557266780.488 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:20.493Z,1557266780.493 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:20.892Z,1557266780.892 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:21.303Z,1557266781.303 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:21.304Z,1557266781.304 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1DC,000,00000,186,80,81,0C,FF
2019-05-07T22:06:21.304Z,1557266781.304 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:21.304Z,1557266781.304 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:21.703Z,1557266781.703 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:21.703Z,1557266781.703 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:21.704Z,1557266781.704 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:21.705Z,1557266781.705 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:22.104Z,1557266782.104 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:22.104Z,1557266782.104 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1DC,000,00000,186,80,81,0C,FF
2019-05-07T22:06:22.104Z,1557266782.104 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:22.104Z,1557266782.104 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:22.105Z,1557266782.105 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:22.511Z,1557266782.511 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:22.911Z,1557266782.911 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:22.912Z,1557266782.912 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F6,000,00000,186,80,81,12,FF
2019-05-07T22:06:22.912Z,1557266782.912 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:22.912Z,1557266782.912 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:23.315Z,1557266783.315 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:23.315Z,1557266783.315 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:23.316Z,1557266783.316 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:23.316Z,1557266783.316 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:23.720Z,1557266783.720 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:23.720Z,1557266783.720 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F6,000,00000,186,80,81,12,FF
2019-05-07T22:06:23.720Z,1557266783.720 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:23.720Z,1557266783.720 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:23.721Z,1557266783.721 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:24.124Z,1557266784.124 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:24.528Z,1557266784.528 [DUSBL_Hydroid](INFO): 16 bytes available.****
2019-05-07T22:06:24.528Z,1557266784.528 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E1,000,00000,186,80,81,12,FF
2019-05-07T22:06:24.528Z,1557266784.528 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:24.529Z,1557266784.529 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:24.935Z,1557266784.935 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:24.935Z,1557266784.935 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:24.936Z,1557266784.936 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:24.936Z,1557266784.936 [DUSBL_Hydroid](INFO): 20 bytes available.****
2019-05-07T22:06:25.340Z,1557266785.340 [DUSBL_Hydroid](INFO): 26 bytes available.****
2019-05-07T22:06:25.340Z,1557266785.340 [DUSBL_Hydroid](INFO): USBL response received:000,187,80,81,0D,FF
!U1,P
,81,12,FF
2019-05-07T22:06:25.340Z,1557266785.340 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:25.340Z,1557266785.340 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:25.341Z,1557266785.341 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:25.739Z,1557266785.739 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:26.144Z,1557266786.144 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:26.144Z,1557266786.144 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E7,000,00000,186,80,81,0E,FF
2019-05-07T22:06:26.144Z,1557266786.144 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:26.144Z,1557266786.144 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:26.547Z,1557266786.547 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:26.547Z,1557266786.547 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:26.548Z,1557266786.548 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:26.549Z,1557266786.549 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:26.664Z,1557266786.664 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:06:26.664Z,1557266786.664 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:06:26.664Z,1557266786.664 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:06:26.665Z,1557266786.665 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:06:26.666Z,1557266786.666 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:06:26.666Z,1557266786.666 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:06:26.951Z,1557266786.951 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:26.952Z,1557266786.952 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E7,000,00000,186,80,81,0E,FF
2019-05-07T22:06:26.952Z,1557266786.952 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:26.952Z,1557266786.952 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:26.953Z,1557266786.953 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:27.378Z,1557266787.378 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:27.763Z,1557266787.763 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:28.170Z,1557266788.170 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:28.571Z,1557266788.571 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:28.969Z,1557266788.969 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:29.393Z,1557266789.393 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:29.780Z,1557266789.780 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:30.188Z,1557266790.188 [DUSBL_Hydroid](INFO): 16 bytes available.****
2019-05-07T22:06:30.188Z,1557266790.188 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,63,F000,186,80,81,0E,FF
2019-05-07T22:06:30.195Z,1557266790.195 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,F000,186,80,81,0E,FF
2019-05-07T22:06:30.195Z,1557266790.195 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T22:06:30.594Z,1557266790.594 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:30.594Z,1557266790.594 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:30.595Z,1557266790.595 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:30.596Z,1557266790.596 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T22:06:30.996Z,1557266790.996 [DUSBL_Hydroid](INFO): 8 bytes available.****
2019-05-07T22:06:30.996Z,1557266790.996 [DUSBL_Hydroid](INFO): USBL response received:4
!U1,P
,80,63,F000,186,80,81,0E,FF
2019-05-07T22:06:30.996Z,1557266790.996 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:30.996Z,1557266790.996 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:30.997Z,1557266790.997 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:31.407Z,1557266791.407 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:31.814Z,1557266791.814 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:31.814Z,1557266791.814 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1AC,000,0027C,186,80,80,11,FF
2019-05-07T22:06:31.815Z,1557266791.815 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:31.815Z,1557266791.815 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:06:31.850Z,1557266791.850 [Reporter](INFO): acoustic_contact_range 0.659999 m
2019-05-07T22:06:34.227Z,1557266794.227 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:34.227Z,1557266794.227 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:34.228Z,1557266794.228 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:34.229Z,1557266794.229 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:34.635Z,1557266794.635 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:34.636Z,1557266794.636 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1AC,000,0027C,186,80,80,11,FF
2019-05-07T22:06:34.636Z,1557266794.636 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:34.636Z,1557266794.636 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:34.637Z,1557266794.637 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:35.031Z,1557266795.031 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:35.440Z,1557266795.440 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T22:06:35.843Z,1557266795.843 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:36.248Z,1557266796.248 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:36.648Z,1557266796.648 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:37.055Z,1557266797.055 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:37.079Z,1557266797.079 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:06:37.079Z,1557266797.079 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:06:37.079Z,1557266797.079 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:06:37.080Z,1557266797.080 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:06:37.080Z,1557266797.080 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:06:37.080Z,1557266797.080 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:06:37.080Z,1557266797.080 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:06:37.080Z,1557266797.080 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:06:37.081Z,1557266797.081 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T22:06:37.081Z,1557266797.081 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T22:06:37.081Z,1557266797.081 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:06:37.081Z,1557266797.081 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:06:37.081Z,1557266797.081 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:06:37.081Z,1557266797.081 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:06:37.081Z,1557266797.081 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:06:37.456Z,1557266797.456 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:37.864Z,1557266797.864 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:38.267Z,1557266798.267 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:38.668Z,1557266798.668 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:39.076Z,1557266799.076 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:39.479Z,1557266799.479 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:39.883Z,1557266799.883 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:40.287Z,1557266800.287 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,184,80,81,08,FF
6,80,80,11,FF
2019-05-07T22:06:40.298Z,1557266800.298 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070340
2019-05-07T22:06:40.299Z,1557266800.299 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:40.299Z,1557266800.299 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:40.300Z,1557266800.300 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:40.302Z,1557266800.302 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:40.688Z,1557266800.688 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:40.688Z,1557266800.688 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
184,80,81,08,FF
6,80,80,11,FF
2019-05-07T22:06:40.688Z,1557266800.688 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:40.688Z,1557266800.688 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:40.689Z,1557266800.689 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:41.095Z,1557266801.095 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:41.500Z,1557266801.500 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:41.500Z,1557266801.500 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F2,000,00000,186,80,81,0F,FF
2019-05-07T22:06:41.500Z,1557266801.500 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:41.500Z,1557266801.500 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:41.903Z,1557266801.903 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:41.903Z,1557266801.903 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:41.904Z,1557266801.904 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:41.905Z,1557266801.905 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:42.307Z,1557266802.307 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:42.308Z,1557266802.308 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F2,000,00000,186,80,81,0F,FF
2019-05-07T22:06:42.308Z,1557266802.308 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:42.308Z,1557266802.308 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:42.309Z,1557266802.309 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:42.712Z,1557266802.712 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:43.115Z,1557266803.115 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T22:06:43.519Z,1557266803.519 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:43.924Z,1557266803.924 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:44.324Z,1557266804.324 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:44.731Z,1557266804.731 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:45.136Z,1557266805.136 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:45.539Z,1557266805.539 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:45.943Z,1557266805.943 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:46.355Z,1557266806.355 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:46.751Z,1557266806.751 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:47.155Z,1557266807.155 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:47.563Z,1557266807.563 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:06:47.596Z,1557266807.596 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:06:47.596Z,1557266807.596 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:06:47.596Z,1557266807.596 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:06:47.597Z,1557266807.597 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:06:47.598Z,1557266807.598 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:06:47.598Z,1557266807.598 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:06:47.960Z,1557266807.960 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,186,80,81,0D,FF
6,80,81,0F,FF
2019-05-07T22:06:47.974Z,1557266807.974 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070267
2019-05-07T22:06:47.975Z,1557266807.975 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:47.975Z,1557266807.975 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:47.976Z,1557266807.976 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:47.977Z,1557266807.977 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:48.388Z,1557266808.388 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:48.388Z,1557266808.388 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0D,FF
6,80,81,0F,FF
2019-05-07T22:06:48.388Z,1557266808.388 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:48.389Z,1557266808.389 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:48.390Z,1557266808.390 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:48.768Z,1557266808.768 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:49.175Z,1557266809.175 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:49.176Z,1557266809.176 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1A2,000,0026D,186,80,80,13,FF
2019-05-07T22:06:49.176Z,1557266809.176 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:49.176Z,1557266809.176 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:06:49.576Z,1557266809.576 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:49.576Z,1557266809.576 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:49.576Z,1557266809.576 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:49.578Z,1557266809.578 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:49.980Z,1557266809.980 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:50.397Z,1557266810.397 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:50.787Z,1557266810.787 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:51.196Z,1557266811.196 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:51.599Z,1557266811.599 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:52.002Z,1557266812.002 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:52.412Z,1557266812.412 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:52.811Z,1557266812.811 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:53.215Z,1557266813.215 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:53.620Z,1557266813.620 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:54.027Z,1557266814.027 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:54.427Z,1557266814.427 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:54.832Z,1557266814.832 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:54.834Z,1557266814.834 [NAL9602](INFO): SBD MO Status=2, MOMSN=3875, MT Status=2, MTMSN=0
2019-05-07T22:06:54.834Z,1557266814.834 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T22:06:55.235Z,1557266815.235 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:55.639Z,1557266815.639 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T22:06:55.650Z,1557266815.650 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.073987
2019-05-07T22:06:55.651Z,1557266815.651 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:55.651Z,1557266815.651 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:55.651Z,1557266815.651 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:55.653Z,1557266815.653 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:56.044Z,1557266816.044 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:56.044Z,1557266816.044 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1A2,000,0026D,186,80,80,13,FF
2019-05-07T22:06:56.044Z,1557266816.044 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:56.044Z,1557266816.044 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:56.045Z,1557266816.045 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:06:56.447Z,1557266816.447 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:56.851Z,1557266816.851 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:06:56.852Z,1557266816.852 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,11B,000,002E7,186,80,80,0C,FF
2019-05-07T22:06:56.852Z,1557266816.852 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:06:56.852Z,1557266816.852 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:06:56.891Z,1557266816.891 [Reporter](INFO): acoustic_contact_range 7.080001 m
2019-05-07T22:06:58.097Z,1557266818.097 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:06:58.098Z,1557266818.098 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:06:58.098Z,1557266818.098 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:06:58.102Z,1557266818.102 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:06:58.103Z,1557266818.103 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:06:58.104Z,1557266818.104 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:06:59.275Z,1557266819.275 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:06:59.275Z,1557266819.275 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:06:59.276Z,1557266819.276 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:06:59.276Z,1557266819.276 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:06:59.676Z,1557266819.676 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:06:59.676Z,1557266819.676 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
11B,000,002E7,186,80,80,0C,FF
2019-05-07T22:06:59.676Z,1557266819.676 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:06:59.676Z,1557266819.676 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:06:59.677Z,1557266819.677 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:00.079Z,1557266820.079 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:00.484Z,1557266820.484 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T22:07:00.887Z,1557266820.887 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:01.292Z,1557266821.292 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:01.696Z,1557266821.696 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:02.103Z,1557266822.103 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:02.503Z,1557266822.503 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:02.908Z,1557266822.908 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:03.315Z,1557266823.315 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:03.715Z,1557266823.715 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:04.124Z,1557266824.124 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:04.527Z,1557266824.527 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:04.931Z,1557266824.931 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T22:07:05.348Z,1557266825.348 [DUSBL_Hydroid](INFO): IN QUEUE:!U000,186,80,81,0D,FF
6,80,80,0C,FF
2019-05-07T22:07:05.363Z,1557266825.363 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.086731
2019-05-07T22:07:05.364Z,1557266825.364 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:05.364Z,1557266825.364 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:05.365Z,1557266825.365 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:05.399Z,1557266825.399 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:05.399Z,1557266825.399 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0D,FF
6,80,80,0C,FF
2019-05-07T22:07:05.399Z,1557266825.399 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:05.399Z,1557266825.399 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:05.401Z,1557266825.401 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:05.736Z,1557266825.736 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:05.752Z,1557266825.752 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507220703.766385,06,413,14,0094,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,190,-0.05,-999,9760,4000*78

2019-05-07T22:07:06.139Z,1557266826.139 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:06.140Z,1557266826.140 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,0FA,000,00000,187,80,81,0D,FF
2019-05-07T22:07:06.141Z,1557266826.141 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:06.141Z,1557266826.141 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:07:06.553Z,1557266826.553 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:06.553Z,1557266826.553 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:06.554Z,1557266826.554 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:06.556Z,1557266826.556 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:06.952Z,1557266826.952 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:06.952Z,1557266826.952 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
0FA,000,00000,187,80,81,0D,FF
2019-05-07T22:07:06.952Z,1557266826.952 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:06.953Z,1557266826.953 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:06.953Z,1557266826.953 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:07.387Z,1557266827.387 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:07.764Z,1557266827.764 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:07.764Z,1557266827.764 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,0D4,000,00000,187,80,81,09,FF
2019-05-07T22:07:07.764Z,1557266827.764 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:07.764Z,1557266827.764 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:07:08.163Z,1557266828.163 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:08.163Z,1557266828.163 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:08.164Z,1557266828.164 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:08.165Z,1557266828.165 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:08.567Z,1557266828.567 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:08.568Z,1557266828.568 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
0D4,000,00000,187,80,81,09,FF
2019-05-07T22:07:08.568Z,1557266828.568 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:08.568Z,1557266828.568 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:08.569Z,1557266828.569 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:08.670Z,1557266828.670 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:07:08.670Z,1557266828.670 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:07:08.671Z,1557266828.671 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:07:08.671Z,1557266828.671 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:07:08.671Z,1557266828.671 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:07:08.671Z,1557266828.671 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:07:08.671Z,1557266828.671 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:07:08.671Z,1557266828.671 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:07:08.672Z,1557266828.672 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T22:07:08.672Z,1557266828.672 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T22:07:08.672Z,1557266828.672 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:07:08.672Z,1557266828.672 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:07:08.672Z,1557266828.672 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:07:08.672Z,1557266828.672 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:07:08.672Z,1557266828.672 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:07:08.968Z,1557266828.968 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:09.394Z,1557266829.394 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:09.394Z,1557266829.394 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1D0,000,002CB,186,80,80,63,FF
2019-05-07T22:07:09.394Z,1557266829.394 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:09.395Z,1557266829.395 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:09.440Z,1557266829.440 [Reporter](INFO): acoustic_contact_range 5.399999 m
2019-05-07T22:07:11.795Z,1557266831.795 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:11.796Z,1557266831.796 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:11.796Z,1557266831.796 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:11.799Z,1557266831.799 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:12.208Z,1557266832.208 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:12.208Z,1557266832.208 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1D0,000,002CB,186,80,80,63,FF
2019-05-07T22:07:12.208Z,1557266832.208 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:12.209Z,1557266832.209 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:12.210Z,1557266832.210 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:12.604Z,1557266832.604 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:12.605Z,1557266832.605 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T22:07:12.611Z,1557266832.611 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAST,6,1,20905072271.4405,0,0114,0093,150,246,00,00,01,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,192,0.05,-999,9760,4000*5A

2019-05-07T22:07:13.015Z,1557266833.015 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:13.015Z,1557266833.015 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1B3,000,002CB,186,80,80,5B,FF
2019-05-07T22:07:13.015Z,1557266833.015 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:13.015Z,1557266833.015 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:13.059Z,1557266833.059 [Reporter](INFO): acoustic_contact_range 5.399999 m
2019-05-07T22:07:15.431Z,1557266835.431 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:15.432Z,1557266835.432 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:15.432Z,1557266835.432 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:15.434Z,1557266835.434 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:15.835Z,1557266835.835 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:16.240Z,1557266836.240 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:16.656Z,1557266836.656 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:17.047Z,1557266837.047 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:17.452Z,1557266837.452 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:17.856Z,1557266837.856 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:18.263Z,1557266838.263 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:18.663Z,1557266838.663 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:19.073Z,1557266839.073 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:19.130Z,1557266839.130 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:07:19.130Z,1557266839.130 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:07:19.130Z,1557266839.130 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:07:19.135Z,1557266839.135 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:07:19.135Z,1557266839.135 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:07:19.135Z,1557266839.135 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:07:19.135Z,1557266839.135 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:07:19.135Z,1557266839.135 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:07:19.135Z,1557266839.135 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T22:07:19.136Z,1557266839.136 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T22:07:19.136Z,1557266839.136 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:07:19.136Z,1557266839.136 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:07:19.136Z,1557266839.136 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:07:19.136Z,1557266839.136 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:07:19.136Z,1557266839.136 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:07:19.472Z,1557266839.472 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:19.875Z,1557266839.875 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:20.280Z,1557266840.280 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:20.684Z,1557266840.684 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:20.686Z,1557266840.686 [NAL9602](INFO): SBD MO Status=2, MOMSN=3875, MT Status=2, MTMSN=0
2019-05-07T22:07:20.686Z,1557266840.686 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T22:07:21.088Z,1557266841.088 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:21.491Z,1557266841.491 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T22:07:21.502Z,1557266841.502 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070059
2019-05-07T22:07:21.503Z,1557266841.503 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:21.503Z,1557266841.503 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:21.503Z,1557266841.503 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:21.505Z,1557266841.505 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:21.899Z,1557266841.899 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:21.900Z,1557266841.900 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1B3,000,002CB,186,80,80,5B,FF
2019-05-07T22:07:21.900Z,1557266841.900 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:21.900Z,1557266841.900 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:21.901Z,1557266841.901 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:22.300Z,1557266842.300 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:22.323Z,1557266842.323 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T22:07:22.720Z,1557266842.720 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:22.720Z,1557266842.720 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1DD,000,002CC,186,80,80,66,FF
2019-05-07T22:07:22.721Z,1557266842.721 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:22.721Z,1557266842.721 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:22.812Z,1557266842.812 [Reporter](INFO): acoustic_contact_range 5.460000 m
2019-05-07T22:07:25.131Z,1557266845.131 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:25.132Z,1557266845.132 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:25.132Z,1557266845.132 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:25.135Z,1557266845.135 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:25.532Z,1557266845.532 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:25.532Z,1557266845.532 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1DD,000,002CC,186,80,80,66,FF
2019-05-07T22:07:25.532Z,1557266845.532 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:25.532Z,1557266845.532 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:25.533Z,1557266845.533 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:25.936Z,1557266845.936 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:26.341Z,1557266846.341 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:26.341Z,1557266846.341 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,12B,000,002E5,186,80,80,0E,FF
2019-05-07T22:07:26.342Z,1557266846.342 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:26.342Z,1557266846.342 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:26.440Z,1557266846.440 [Reporter](INFO): acoustic_contact_range 6.960000 m
2019-05-07T22:07:28.771Z,1557266848.771 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:28.771Z,1557266848.771 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:28.772Z,1557266848.772 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:28.773Z,1557266848.773 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:29.171Z,1557266849.171 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:29.172Z,1557266849.172 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
12B,000,002E5,186,80,80,0E,FF
2019-05-07T22:07:29.172Z,1557266849.172 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:29.172Z,1557266849.172 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:29.173Z,1557266849.173 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:29.569Z,1557266849.569 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:29.618Z,1557266849.618 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:07:29.619Z,1557266849.619 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:07:29.619Z,1557266849.619 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:07:29.619Z,1557266849.619 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:07:29.620Z,1557266849.620 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:07:29.973Z,1557266849.973 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:29.973Z,1557266849.973 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,0CE,000,00000,187,80,81,16,FF
2019-05-07T22:07:29.973Z,1557266849.973 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:29.974Z,1557266849.974 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:07:30.396Z,1557266850.396 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:30.396Z,1557266850.396 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:30.396Z,1557266850.396 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:30.398Z,1557266850.398 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:30.781Z,1557266850.781 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:30.781Z,1557266850.781 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
0CE,000,00000,187,80,81,16,FF
2019-05-07T22:07:30.781Z,1557266850.781 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:30.781Z,1557266850.781 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:30.783Z,1557266850.783 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:31.185Z,1557266851.185 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:31.591Z,1557266851.591 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:31.592Z,1557266851.592 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C0,000,00000,187,80,81,08,FF
2019-05-07T22:07:31.592Z,1557266851.592 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:31.592Z,1557266851.592 [DUSBL_Hydroid](ERROR): RANGE IS NAN!!!!!
2019-05-07T22:07:31.999Z,1557266851.999 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:31.999Z,1557266851.999 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:32.000Z,1557266852.000 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:32.003Z,1557266852.003 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:32.404Z,1557266852.404 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:32.404Z,1557266852.404 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C0,000,00000,187,80,81,08,FF
2019-05-07T22:07:32.404Z,1557266852.404 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:32.404Z,1557266852.404 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:32.405Z,1557266852.405 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:32.804Z,1557266852.804 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:33.208Z,1557266853.208 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:33.208Z,1557266853.208 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E4,000,002CB,186,80,80,5F,FF
2019-05-07T22:07:33.208Z,1557266853.208 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:33.208Z,1557266853.208 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:33.268Z,1557266853.268 [Reporter](INFO): acoustic_contact_range 5.399999 m
2019-05-07T22:07:35.631Z,1557266855.631 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:35.631Z,1557266855.631 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:35.632Z,1557266855.632 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:35.633Z,1557266855.633 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:36.033Z,1557266856.033 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:36.033Z,1557266856.033 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E4,000,002CB,186,80,80,5F,FF
2019-05-07T22:07:36.033Z,1557266856.033 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:36.033Z,1557266856.033 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:36.034Z,1557266856.034 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:36.437Z,1557266856.437 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:36.844Z,1557266856.844 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:36.844Z,1557266856.844 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1DF,000,002CA,187,80,80,59,FF
2019-05-07T22:07:36.844Z,1557266856.844 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:36.844Z,1557266856.844 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:36.884Z,1557266856.884 [Reporter](INFO): acoustic_contact_range 5.339999 m
2019-05-07T22:07:39.264Z,1557266859.264 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:39.265Z,1557266859.265 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:39.265Z,1557266859.265 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:39.268Z,1557266859.268 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:39.669Z,1557266859.669 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:39.669Z,1557266859.669 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1DF,000,002CA,187,80,80,59,FF
2019-05-07T22:07:39.669Z,1557266859.669 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:39.669Z,1557266859.669 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:39.702Z,1557266859.702 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:40.091Z,1557266860.091 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:40.137Z,1557266860.137 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:07:40.137Z,1557266860.137 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:07:40.138Z,1557266860.138 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:07:40.139Z,1557266860.139 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:07:40.139Z,1557266860.139 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:07:40.139Z,1557266860.139 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:07:40.139Z,1557266860.139 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:07:40.139Z,1557266860.139 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:07:40.140Z,1557266860.140 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-07T22:07:40.140Z,1557266860.140 [DUSBL:RequestRepeater] Running Loop=10
2019-05-07T22:07:40.140Z,1557266860.140 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T22:07:40.140Z,1557266860.140 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T22:07:40.140Z,1557266860.140 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T22:07:40.140Z,1557266860.140 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T22:07:40.140Z,1557266860.140 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:07:40.477Z,1557266860.477 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:40.477Z,1557266860.477 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1DD,000,002CB,186,80,80,60,FF
2019-05-07T22:07:40.478Z,1557266860.478 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:40.478Z,1557266860.478 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:40.527Z,1557266860.527 [Reporter](INFO): acoustic_contact_range 5.399999 m
2019-05-07T22:07:42.905Z,1557266862.905 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:42.905Z,1557266862.905 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:42.906Z,1557266862.906 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:42.907Z,1557266862.907 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:43.308Z,1557266863.308 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:43.709Z,1557266863.709 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:44.113Z,1557266864.113 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:44.524Z,1557266864.524 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:44.922Z,1557266864.922 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:45.325Z,1557266865.325 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:45.729Z,1557266865.729 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:46.133Z,1557266866.133 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:46.537Z,1557266866.537 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:46.941Z,1557266866.941 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:47.353Z,1557266867.353 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:47.749Z,1557266867.749 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:48.155Z,1557266868.155 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:48.564Z,1557266868.564 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:48.967Z,1557266868.967 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T22:07:48.978Z,1557266868.978 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.072485
2019-05-07T22:07:48.979Z,1557266868.979 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T22:07:48.979Z,1557266868.979 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T22:07:48.980Z,1557266868.980 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T22:07:48.981Z,1557266868.981 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:49.403Z,1557266869.403 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T22:07:49.404Z,1557266869.404 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1DD,000,002CB,186,80,80,60,FF
2019-05-07T22:07:49.404Z,1557266869.404 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T22:07:49.404Z,1557266869.404 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T22:07:49.405Z,1557266869.405 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T22:07:49.771Z,1557266869.771 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T22:07:49.778Z,1557266869.778 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507220747.837979,06,338,13,0094,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,205,0.00,-999,9760,4000*54

2019-05-07T22:07:50.176Z,1557266870.176 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T22:07:50.176Z,1557266870.176 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,16C,000,002E6,186,80,80,12,FF
2019-05-07T22:07:50.176Z,1557266870.176 [DUSBL_Hydroid](INFO): GOT RANGE AND DIRECTION
2019-05-07T22:07:50.176Z,1557266870.176 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T22:07:50.256Z,1557266870.256 [Reporter](INFO): acoustic_contact_range 7.020000 m
2019-05-07T22:07:50.661Z,1557266870.661 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T22:07:50.662Z,1557266870.662 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T22:07:50.662Z,1557266870.662 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:07:50.667Z,1557266870.667 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T22:07:50.667Z,1557266870.667 [DUSBL:RequestRepeater] Stopped
2019-05-07T22:07:50.667Z,1557266870.667 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T22:07:50.667Z,1557266870.667 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T22:07:50.667Z,1557266870.667 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T22:07:50.668Z,1557266870.668 [DUSBL](INFO): Completed DUSBL
2019-05-07T22:07:50.668Z,1557266870.668 [MissionManager](INFO): DUSBL is completed.
2019-05-07T22:07:50.668Z,1557266870.668 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T22:07:50.668Z,1557266870.668 [DUSBL] Stopped
2019-05-07T22:07:50.668Z,1557266870.668 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T22:07:50.668Z,1557266870.668 [DUSBL:A.Pitch] Stopped
2019-05-07T22:07:50.668Z,1557266870.668 [DUSBL:B.SetSpeed] Stopped
2019-05-07T22:07:50.668Z,1557266870.668 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T22:07:50.668Z,1557266870.668 [DUSBL:C] Stopped
2019-05-07T22:07:51.010Z,1557266871.010 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T22:07:51.010Z,1557266871.010 [Default] Running Loop=1
2019-05-07T22:07:51.010Z,1557266871.010 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T22:07:51.011Z,1557266871.011 [Default:B.GoToSurface] Running Loop=1
2019-05-07T22:07:51.011Z,1557266871.011 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T22:07:51.011Z,1557266871.011 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T22:07:51.011Z,1557266871.011 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T22:07:51.011Z,1557266871.011 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T22:07:51.012Z,1557266871.012 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T22:07:51.012Z,1557266871.012 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T22:07:51.012Z,1557266871.012 [Default:A.Wait] Running Loop=1
2019-05-07T22:07:51.013Z,1557266871.013 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:07:53.008Z,1557266873.008 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T22:08:04.357Z,1557266884.357 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T22:08:04.357Z,1557266884.357 [Default:A.Wait] Stopped
2019-05-07T22:08:04.357Z,1557266884.357 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:08:04.765Z,1557266884.765 [Default:CheckIn] Running Loop=1
2019-05-07T22:08:04.765Z,1557266884.765 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T22:08:04.765Z,1557266884.765 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T22:08:06.351Z,1557266886.351 [NAL9602](DEBUG): Fix Requested
2019-05-07T22:08:06.746Z,1557266886.746 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220631.00,A,3648.16753,N,12147.28591,W,0.253,164.53,070519,,,A*7A
2019-05-07T22:08:06.748Z,1557266886.748 [NAL9602](INFO): GPS fix at 20190507T220631: (36.802792, -121.788099)
2019-05-07T22:08:06.781Z,1557266886.781 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T22:08:06.781Z,1557266886.781 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T22:08:12.357Z,1557266892.357 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190507T215531/Courier0010.lzma
2019-05-07T22:08:13.156Z,1557266893.156 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Courier0010.lzma.bak
2019-05-07T22:08:13.156Z,1557266893.156 [DataOverHttps](INFO): SBD MOMSN=10959904
2019-05-07T22:08:27.392Z,1557266907.392 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T22:08:27.393Z,1557266907.393 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,    +0,   -2,A
2019-05-07T22:08:31.700Z,1557266911.700 [DataOverHttps](INFO): Sending 999 bytes from file Logs/20190507T215531/Express0011.lzma
2019-05-07T22:08:32.504Z,1557266912.504 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Express0011.lzma.bak
2019-05-07T22:08:32.504Z,1557266912.504 [DataOverHttps](INFO): SBD MOMSN=10959911
2019-05-07T22:08:33.445Z,1557266913.445 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T22:08:33.446Z,1557266913.446 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T22:08:33.446Z,1557266913.446 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:08:37.445Z,1557266917.445 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T22:08:37.518Z,1557266917.518 [NAL9602](FAULT): received: 
+SBDI: 2, 3875, 2, 0, 0, 0

OK
2019-05-07T22:08:37.519Z,1557266917.519 [NAL9602] Data Fault, FailCount= 1
2019-05-07T22:08:37.519Z,1557266917.519 [NAL9602](ERROR): Data Fault
2019-05-07T22:08:37.613Z,1557266917.613 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T22:08:37.848Z,1557266917.848 [NAL9602](INFO): Powering down
2019-05-07T22:08:38.710Z,1557266918.710 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T22:08:38.711Z,1557266918.711 [NAL9602] No Fault, FailCount= 1
2019-05-07T22:09:08.152Z,1557266948.152 [NAL9602](INFO): Powering up NAL9602
2019-05-07T22:09:19.056Z,1557266959.056 [NAL9602](INFO): NAL9602 initialized
2019-05-07T22:09:50.165Z,1557266990.165 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T22:12:08.761Z,1557267128.761 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T22:13:34.005Z,1557267214.005 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T22:13:34.005Z,1557267214.005 [Default:CheckIn:C.Wait] Stopped
2019-05-07T22:13:34.006Z,1557267214.006 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:13:34.006Z,1557267214.006 [Default:CheckIn:D] Running Loop=1
2019-05-07T22:13:34.457Z,1557267214.457 [Default:CheckIn:D] Stopped
2019-05-07T22:13:34.458Z,1557267214.458 [Default:CheckIn:E] Running Loop=1
2019-05-07T22:13:34.833Z,1557267214.833 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.724120 min 
2019-05-07T22:13:34.834Z,1557267214.834 [Default:CheckIn:E] Stopped
2019-05-07T22:13:34.834Z,1557267214.834 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T22:13:34.834Z,1557267214.834 [Default:CheckIn] Stopped
2019-05-07T22:13:34.834Z,1557267214.834 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T22:13:34.834Z,1557267214.834 [Default:CheckIn](INFO): Running loop #2
2019-05-07T22:13:34.834Z,1557267214.834 [Default:CheckIn] Running Loop=2
2019-05-07T22:13:34.835Z,1557267214.835 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T22:13:34.835Z,1557267214.835 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T22:13:36.431Z,1557267216.431 [NAL9602](DEBUG): Fix Requested
2019-05-07T22:13:36.815Z,1557267216.815 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221202.00,A,3648.17122,N,12147.28796,W,0.156,0.00,070519,,,A*78
2019-05-07T22:13:36.817Z,1557267216.817 [NAL9602](INFO): GPS fix at 20190507T221202: (36.802854, -121.788133)
2019-05-07T22:13:36.889Z,1557267216.889 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T22:13:36.889Z,1557267216.889 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T22:13:39.243Z,1557267219.243 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T22:13:42.722Z,1557267222.722 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190507T215531/Courier0013.lzma
2019-05-07T22:13:43.528Z,1557267223.528 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Courier0013.lzma.bak
2019-05-07T22:13:43.528Z,1557267223.528 [DataOverHttps](INFO): SBD MOMSN=10959921
2019-05-07T22:13:54.924Z,1557267234.924 [DataOverHttps](INFO): Sending 873 bytes from file Logs/20190507T215531/Express0014.lzma
2019-05-07T22:13:55.728Z,1557267235.728 [DataOverHttps](INFO): Moved sent file to Logs/20190507T215531/Express0014.lzma.bak
2019-05-07T22:13:55.728Z,1557267235.728 [DataOverHttps](INFO): SBD MOMSN=10959927
2019-05-07T22:13:56.633Z,1557267236.633 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T22:13:56.633Z,1557267236.633 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T22:13:56.633Z,1557267236.633 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T22:14:09.952Z,1557267249.952 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T22:15:49.399Z,1557267349.399 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T22:15:49.399Z,1557267349.399 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  92.93,  87.94,   0.00
2019-05-07T22:16:52.402Z,1557267412.402 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T22:16:52.402Z,1557267412.402 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   +23,    +3,   BE,   +23,    +3,   -11,A
2019-05-07T22:17:37.171Z,1557267457.171 [CommandLine](IMPORTANT): got command restart application
2019-05-07T22:17:38.174Z,1557267458.174 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-07T22:17:38.175Z,1557267458.175 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:38.175Z,1557267458.175 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:38.347Z,1557267458.347 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-07T22:17:38.347Z,1557267458.347 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:38.349Z,1557267458.349 [CommandLine](INFO): Join timeout helper Thread ID is 1352
2019-05-07T22:17:38.352Z,1557267458.352 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-07T22:17:38.352Z,1557267458.352 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:38.354Z,1557267458.354 [NavChartDb](INFO): Join timeout helper Thread ID is 1353
2019-05-07T22:17:38.587Z,1557267458.587 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:38.587Z,1557267458.587 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:38.590Z,1557267458.590 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-07T22:17:38.591Z,1557267458.591 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:38.591Z,1557267458.591 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1354
2019-05-07T22:17:38.963Z,1557267458.963 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:38.963Z,1557267458.963 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T22:17:38.963Z,1557267458.963 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:38.974Z,1557267458.974 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-07T22:17:38.975Z,1557267458.975 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:38.975Z,1557267458.975 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1355
2019-05-07T22:17:39.163Z,1557267459.163 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:39.163Z,1557267459.163 [CTD_NeilBrown](INFO): Powering down
2019-05-07T22:17:39.174Z,1557267459.174 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.182Z,1557267459.182 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-07T22:17:39.182Z,1557267459.182 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.183Z,1557267459.183 [Radio_Surface](INFO): Join timeout helper Thread ID is 1356
2019-05-07T22:17:39.367Z,1557267459.367 [Radio_Surface](INFO): Powering down
2019-05-07T22:17:39.369Z,1557267459.369 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:39.370Z,1557267459.370 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.384Z,1557267459.384 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-07T22:17:39.384Z,1557267459.384 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.385Z,1557267459.385 [DataOverHttps](INFO): Join timeout helper Thread ID is 1357
2019-05-07T22:17:39.550Z,1557267459.550 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:39.554Z,1557267459.554 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.571Z,1557267459.571 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-07T22:17:39.571Z,1557267459.571 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.572Z,1557267459.572 [logger](INFO): Join timeout helper Thread ID is 1358
2019-05-07T22:17:39.646Z,1557267459.646 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:39.647Z,1557267459.647 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.651Z,1557267459.651 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-07T22:17:39.651Z,1557267459.651 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.651Z,1557267459.651 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-07T22:17:39.651Z,1557267459.651 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:39.652Z,1557267459.652 [controlThread](INFO): Join timeout helper Thread ID is 1359
2019-05-07T22:17:39.670Z,1557267459.670 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T22:17:39.670Z,1557267459.670 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-07T22:17:39.670Z,1557267459.670 [AHRS_M2](INFO): Powering down
2019-05-07T22:17:39.743Z,1557267459.743 [DUSBL_Hydroid](INFO): Powering down
2019-05-07T22:17:39.815Z,1557267459.815 [Micromodem](INFO): Powering down
2019-05-07T22:17:39.911Z,1557267459.911 [NAL9602](INFO): Powering down
2019-05-07T22:17:39.982Z,1557267459.982 [RDI_Pathfinder](INFO): Powering down
2019-05-07T22:17:39.984Z,1557267459.984 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-07T22:17:39.985Z,1557267459.985 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-07T22:17:39.985Z,1557267459.985 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-07T22:17:39.986Z,1557267459.986 [MissionManager](INFO): Uninitializing Mission Default
2019-05-07T22:17:39.986Z,1557267459.986 [Default] Stopped
2019-05-07T22:17:39.986Z,1557267459.986 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T22:17:39.986Z,1557267459.986 [Default:B.GoToSurface] Stopped
2019-05-07T22:17:39.986Z,1557267459.986 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T22:17:39.986Z,1557267459.986 [Default:CheckIn] Stopped
2019-05-07T22:17:39.986Z,1557267459.986 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T22:17:39.986Z,1557267459.986 [Default:CheckIn:C.Wait] Stopped
2019-05-07T22:17:39.986Z,1557267459.986 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T22:17:39.989Z,1557267459.989 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-07T22:17:39.989Z,1557267459.989 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-07T22:17:39.989Z,1557267459.989 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-07T22:17:39.989Z,1557267459.989 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-07T22:17:39.990Z,1557267459.990 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-07T22:17:39.990Z,1557267459.990 [BuoyancyServo](INFO): Powering down
2019-05-07T22:17:40.002Z,1557267460.002 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-07T22:17:40.003Z,1557267460.003 [ElevatorServo](INFO): Powering down
2019-05-07T22:17:40.003Z,1557267460.003 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-07T22:17:40.003Z,1557267460.003 [MassServo](INFO): Powering down
2019-05-07T22:17:40.004Z,1557267460.004 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T22:17:40.004Z,1557267460.004 [RudderServo](INFO): Powering down
2019-05-07T22:17:40.005Z,1557267460.005 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-07T22:17:40.005Z,1557267460.005 [ThrusterServo](INFO): Powering down
2019-05-07T22:17:40.006Z,1557267460.006 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-07T22:17:40.006Z,1557267460.006 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-07T22:17:40.007Z,1557267460.007 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-07T22:17:40.007Z,1557267460.007 [CBIT](DEBUG): Powering off loads.
2019-05-07T22:17:40.018Z,1557267460.018 [CBIT](DEBUG): Disabling WDT.
2019-05-07T22:17:40.030Z,1557267460.030 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-07T22:17:40.031Z,1557267460.031 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:40.079Z,1557267460.079 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:40.088Z,1557267460.088 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:40.131Z,1557267460.131 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:40.133Z,1557267460.133 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:40.188Z,1557267460.188 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T22:17:40.256Z,1557267460.256 [logger ThreadHandler](INFO): Thread cancelled.