2019-05-07T21:34:04.976Z,1557264844.976 [Supervisor](DEBUG): Initializing supervisor.
2019-05-07T21:34:04.979Z,1557264844.979 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-07T21:34:04.980Z,1557264844.980 [SyncHandler](INFO): Protected caller Thread ID is 934
2019-05-07T21:34:04.981Z,1557264844.981 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-07T21:34:04.982Z,1557264844.982 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-07T21:34:04.982Z,1557264844.982 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 935
2019-05-07T21:34:04.985Z,1557264844.985 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-07T21:34:04.997Z,1557264844.997 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-07T21:34:04.998Z,1557264844.998 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-07T21:34:04.999Z,1557264844.999 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 936
2019-05-07T21:34:04.000Z,1557264845.000 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-07T21:34:05.000Z,1557264845.000 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-07T21:34:05.001Z,1557264845.001 [logger ThreadHandler](INFO): Protected caller Thread ID is 937
2019-05-07T21:34:05.003Z,1557264845.003 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-07T21:34:05.003Z,1557264845.003 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-07T21:34:05.005Z,1557264845.005 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-07T21:34:05.437Z,1557264845.437 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-07T21:34:05.438Z,1557264845.438 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-07T21:34:05.536Z,1557264845.536 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-07T21:34:05.536Z,1557264845.536 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-07T21:34:05.897Z,1557264845.897 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-07T21:34:05.897Z,1557264845.897 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-07T21:34:06.178Z,1557264846.178 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-07T21:34:06.179Z,1557264846.179 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-07T21:34:06.370Z,1557264846.370 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-07T21:34:06.371Z,1557264846.371 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-07T21:34:06.826Z,1557264846.826 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-07T21:34:06.827Z,1557264846.827 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-07T21:34:07.038Z,1557264847.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-07T21:34:07.039Z,1557264847.039 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-07T21:34:07.184Z,1557264847.184 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-07T21:34:07.185Z,1557264847.185 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-07T21:34:07.623Z,1557264847.623 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-07T21:34:07.624Z,1557264847.624 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-07T21:34:07.719Z,1557264847.719 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-07T21:34:07.720Z,1557264847.720 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-07T21:34:08.044Z,1557264848.044 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-07T21:34:08.045Z,1557264848.045 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-07T21:34:08.125Z,1557264848.125 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-07T21:34:08.228Z,1557264848.228 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-07T21:34:08.229Z,1557264848.229 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-07T21:34:08.805Z,1557264848.805 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-07T21:34:08.805Z,1557264848.805 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-07T21:34:09.198Z,1557264849.198 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-07T21:34:09.200Z,1557264849.200 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-07T21:34:09.201Z,1557264849.201 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-07T21:34:09.409Z,1557264849.409 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-07T21:34:09.509Z,1557264849.509 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-07T21:34:09.607Z,1557264849.607 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-07T21:34:09.834Z,1557264849.834 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-07T21:34:09.834Z,1557264849.834 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-07T21:34:09.919Z,1557264849.919 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-07T21:34:10.012Z,1557264850.012 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-07T21:34:10.109Z,1557264850.109 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-07T21:34:10.191Z,1557264850.191 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-07T21:34:10.299Z,1557264850.299 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-07T21:34:10.470Z,1557264850.470 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-07T21:34:10.602Z,1557264850.602 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-07T21:34:10.602Z,1557264850.602 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-07T21:34:10.615Z,1557264850.615 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-07T21:34:11.039Z,1557264851.039 [AHRS_M2] Loaded
2019-05-07T21:34:11.039Z,1557264851.039 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-07T21:34:11.239Z,1557264851.239 [DataOverHttps] Loaded
2019-05-07T21:34:11.239Z,1557264851.239 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-07T21:34:11.246Z,1557264851.246 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-07T21:34:11.282Z,1557264851.282 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1016
2019-05-07T21:34:11.296Z,1557264851.296 [Depth_Keller] Loaded
2019-05-07T21:34:11.296Z,1557264851.296 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-07T21:34:11.301Z,1557264851.301 [DropWeight] Loaded
2019-05-07T21:34:11.301Z,1557264851.301 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-07T21:34:11.505Z,1557264851.505 [DUSBL_Hydroid] Loaded
2019-05-07T21:34:11.505Z,1557264851.505 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-07T21:34:11.745Z,1557264851.745 [Micromodem] Loaded
2019-05-07T21:34:11.746Z,1557264851.746 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-07T21:34:11.844Z,1557264851.844 [NAL9602] Loaded
2019-05-07T21:34:11.844Z,1557264851.844 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-07T21:34:11.864Z,1557264851.864 [Onboard] Loaded
2019-05-07T21:34:11.864Z,1557264851.864 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-07T21:34:11.870Z,1557264851.870 [PowerOnly] Loaded
2019-05-07T21:34:11.871Z,1557264851.871 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-07T21:34:11.877Z,1557264851.877 [Radio_Surface] Loaded
2019-05-07T21:34:11.877Z,1557264851.877 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-07T21:34:11.878Z,1557264851.878 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-07T21:34:11.879Z,1557264851.879 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1017
2019-05-07T21:34:11.922Z,1557264851.922 [RDI_Pathfinder] Loaded
2019-05-07T21:34:11.923Z,1557264851.923 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-07T21:34:13.407Z,1557264853.407 [BPC1] Loaded
2019-05-07T21:34:13.407Z,1557264853.407 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-07T21:34:13.408Z,1557264853.408 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-07T21:34:13.408Z,1557264853.408 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-07T21:34:13.421Z,1557264853.421 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-07T21:34:13.422Z,1557264853.422 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-07T21:34:13.528Z,1557264853.528 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-07T21:34:13.528Z,1557264853.528 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-07T21:34:13.549Z,1557264853.549 [NavChart] Loaded
2019-05-07T21:34:13.549Z,1557264853.549 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-07T21:34:13.553Z,1557264853.553 [UniversalFixResidualReporter] Loaded
2019-05-07T21:34:13.553Z,1557264853.553 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-07T21:34:13.554Z,1557264853.554 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-07T21:34:13.554Z,1557264853.554 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-07T21:34:13.662Z,1557264853.662 [BuoyancyServo] Loaded
2019-05-07T21:34:13.663Z,1557264853.663 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-07T21:34:13.678Z,1557264853.678 [ElevatorServo] Loaded
2019-05-07T21:34:13.678Z,1557264853.678 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-07T21:34:13.693Z,1557264853.693 [MassServo] Loaded
2019-05-07T21:34:13.693Z,1557264853.693 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-07T21:34:13.708Z,1557264853.708 [RudderServo] Loaded
2019-05-07T21:34:13.708Z,1557264853.708 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-07T21:34:13.723Z,1557264853.723 [ThrusterServo] Loaded
2019-05-07T21:34:13.723Z,1557264853.723 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-07T21:34:13.724Z,1557264853.724 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-07T21:34:13.724Z,1557264853.724 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-07T21:34:13.970Z,1557264853.970 [CTD_NeilBrown] Loaded
2019-05-07T21:34:13.970Z,1557264853.970 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-07T21:34:13.971Z,1557264853.971 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-07T21:34:13.971Z,1557264853.971 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1018
2019-05-07T21:34:14.015Z,1557264854.015 [WetLabsSeaOWL_UV_A] Loaded
2019-05-07T21:34:14.016Z,1557264854.016 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-07T21:34:14.017Z,1557264854.017 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-07T21:34:14.017Z,1557264854.017 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1019
2019-05-07T21:34:14.018Z,1557264854.018 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-07T21:34:14.018Z,1557264854.018 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-07T21:34:14.308Z,1557264854.308 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-07T21:34:14.308Z,1557264854.308 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-07T21:34:14.348Z,1557264854.348 [DepthRateCalculator] Loaded
2019-05-07T21:34:14.348Z,1557264854.348 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-07T21:34:14.354Z,1557264854.354 [PitchRateCalculator] Loaded
2019-05-07T21:34:14.354Z,1557264854.354 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-07T21:34:14.366Z,1557264854.366 [SpeedCalculator] Loaded
2019-05-07T21:34:14.367Z,1557264854.367 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-07T21:34:14.387Z,1557264854.387 [TempGradientCalculator] Loaded
2019-05-07T21:34:14.388Z,1557264854.388 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-07T21:34:14.393Z,1557264854.393 [YawRateCalculator] Loaded
2019-05-07T21:34:14.393Z,1557264854.393 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-07T21:34:14.434Z,1557264854.434 [ElevatorOffsetCalculator] Loaded
2019-05-07T21:34:14.434Z,1557264854.434 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-07T21:34:14.434Z,1557264854.434 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-07T21:34:14.435Z,1557264854.435 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-07T21:34:14.571Z,1557264854.571 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-07T21:34:14.592Z,1557264854.592 [SBIT] Loaded
2019-05-07T21:34:14.593Z,1557264854.593 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-07T21:34:14.593Z,1557264854.593 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-07T21:34:14.605Z,1557264854.605 [IBIT] Loaded
2019-05-07T21:34:14.605Z,1557264854.605 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-07T21:34:14.608Z,1557264854.608 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-07T21:34:14.746Z,1557264854.746 [CBIT] Loaded
2019-05-07T21:34:14.746Z,1557264854.746 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-07T21:34:14.747Z,1557264854.747 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-07T21:34:14.747Z,1557264854.747 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-07T21:34:14.817Z,1557264854.817 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-07T21:34:14.817Z,1557264854.817 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-07T21:34:14.915Z,1557264854.915 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-07T21:34:14.916Z,1557264854.916 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-07T21:34:14.982Z,1557264854.982 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-07T21:34:15.066Z,1557264855.066 [VerticalControl] Loaded
2019-05-07T21:34:15.066Z,1557264855.066 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-07T21:34:15.067Z,1557264855.067 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-07T21:34:15.125Z,1557264855.125 [HorizontalControl] Loaded
2019-05-07T21:34:15.125Z,1557264855.125 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-07T21:34:15.126Z,1557264855.126 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-07T21:34:15.127Z,1557264855.127 [SpeedControl] Loaded
2019-05-07T21:34:15.128Z,1557264855.128 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-07T21:34:15.128Z,1557264855.128 [LoopControl](DEBUG): Construct LoopControl.
2019-05-07T21:34:15.129Z,1557264855.129 [LoopControl] Loaded
2019-05-07T21:34:15.129Z,1557264855.129 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-07T21:34:15.130Z,1557264855.130 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-07T21:34:15.130Z,1557264855.130 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-07T21:34:15.156Z,1557264855.156 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-07T21:34:15.160Z,1557264855.160 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-07T21:34:15.161Z,1557264855.161 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-07T21:34:15.168Z,1557264855.168 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-07T21:34:15.169Z,1557264855.169 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-07T21:34:15.169Z,1557264855.169 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1020
2019-05-07T21:34:15.174Z,1557264855.174 [Supervisor](INFO): Main Thread ID is 805
2019-05-07T21:34:15.174Z,1557264855.174 [Supervisor](DEBUG): Running supervisor.
2019-05-07T21:34:15.174Z,1557264855.174 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1021
2019-05-07T21:34:15.177Z,1557264855.177 [controlThread ThreadHandler](INFO): Handler Thread ID is 1022
2019-05-07T21:34:15.177Z,1557264855.177 [controlThread](DEBUG): Initializing ControlThread
2019-05-07T21:34:15.186Z,1557264855.186 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-07T21:34:15.187Z,1557264855.187 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-07T21:34:15.188Z,1557264855.188 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-07T21:34:15.188Z,1557264855.188 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-07T21:34:15.188Z,1557264855.188 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-07T21:34:15.188Z,1557264855.188 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-07T21:34:15.189Z,1557264855.189 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-07T21:34:15.189Z,1557264855.189 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-07T21:34:15.190Z,1557264855.190 [SBIT](INFO): Initialize SBIT Component.
2019-05-07T21:34:15.190Z,1557264855.190 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-07T21:34:15.190Z,1557264855.190 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-07T21:34:15.191Z,1557264855.191 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-07T21:34:15.192Z,1557264855.192 [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:34:15.193Z,1557264855.193 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-07T21:34:15.194Z,1557264855.194 [IBIT](INFO): Initialize IBIT Component.
2019-05-07T21:34:15.195Z,1557264855.195 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-07T21:34:15.196Z,1557264855.196 [logger ThreadHandler](INFO): Handler Thread ID is 1023
2019-05-07T21:34:15.206Z,1557264855.206 [CBIT](DEBUG): Initialized mux pins.
2019-05-07T21:34:15.206Z,1557264855.206 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-07T21:34:15.215Z,1557264855.215 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1024
2019-05-07T21:34:15.216Z,1557264855.216 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-07T21:34:15.227Z,1557264855.227 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1025
2019-05-07T21:34:15.230Z,1557264855.230 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-07T21:34:15.230Z,1557264855.230 [CBIT](DEBUG): Initializing heartbeat.
2019-05-07T21:34:15.239Z,1557264855.239 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1026
2019-05-07T21:34:15.240Z,1557264855.240 [CTD_NeilBrown](INFO): Powering down
2019-05-07T21:34:15.267Z,1557264855.267 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1027
2019-05-07T21:34:15.268Z,1557264855.268 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T21:34:15.302Z,1557264855.302 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-07T21:34:15.302Z,1557264855.302 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-07T21:34:15.303Z,1557264855.303 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1028
2019-05-07T21:34:15.306Z,1557264855.306 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-07T21:34:15.306Z,1557264855.306 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-07T21:34:15.307Z,1557264855.307 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-07T21:34:15.307Z,1557264855.307 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-07T21:34:15.307Z,1557264855.307 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-07T21:34:15.307Z,1557264855.307 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-07T21:34:15.307Z,1557264855.307 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-07T21:34:15.308Z,1557264855.308 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-07T21:34:15.308Z,1557264855.308 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-07T21:34:15.308Z,1557264855.308 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-07T21:34:15.308Z,1557264855.308 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-07T21:34:15.308Z,1557264855.308 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-07T21:34:15.308Z,1557264855.308 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-07T21:34:15.309Z,1557264855.309 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-07T21:34:15.309Z,1557264855.309 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-07T21:34:15.309Z,1557264855.309 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-07T21:34:15.338Z,1557264855.338 [CBIT](DEBUG): Backplane powered.
2019-05-07T21:34:15.339Z,1557264855.339 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-07T21:34:15.340Z,1557264855.340 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-07T21:34:15.341Z,1557264855.341 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-07T21:34:15.341Z,1557264855.341 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-07T21:34:15.342Z,1557264855.342 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-07T21:34:15.352Z,1557264855.352 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T21:34:15.383Z,1557264855.383 [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:34:15.383Z,1557264855.383 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-07T21:34:15.450Z,1557264855.450 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-07T21:34:15.451Z,1557264855.451 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-07T21:34:15.453Z,1557264855.453 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T21:34:15.472Z,1557264855.472 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-07T21:34:15.499Z,1557264855.499 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-07T21:34:15.504Z,1557264855.504 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-07T21:34:15.523Z,1557264855.523 [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:34:15.528Z,1557264855.528 [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:34:15.538Z,1557264855.538 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-07T21:34:15.576Z,1557264855.576 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-07T21:34:15.577Z,1557264855.577 [DUSBL_Hydroid](INFO): Powering up
2019-05-07T21:34:15.577Z,1557264855.577 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-07T21:34:15.630Z,1557264855.630 [Radio_Surface](INFO): Powering up
2019-05-07T21:34:15.651Z,1557264855.651 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T21:34:15.671Z,1557264855.671 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:34:15.679Z,1557264855.679 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-07T21:34:15.680Z,1557264855.680 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:34:15.691Z,1557264855.691 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-07T21:34:15.692Z,1557264855.692 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:34:15.699Z,1557264855.699 [MassServo](DEBUG): Initializing MassServo.
2019-05-07T21:34:15.699Z,1557264855.699 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:34:15.715Z,1557264855.715 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T21:34:15.715Z,1557264855.715 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-07T21:34:15.723Z,1557264855.723 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-07T21:34:15.952Z,1557264855.952 [Micromodem](INFO): Powering up
2019-05-07T21:34:15.953Z,1557264855.953 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-07T21:34:15.991Z,1557264855.991 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T21:34:28.987Z,1557264868.987 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T21:34:32.193Z,1557264872.193 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-05-07T21:34:33.404Z,1557264873.404 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-07T21:34:41.884Z,1557264881.884 [NAL9602](INFO): Powering up NAL9602
2019-05-07T21:34:52.810Z,1557264892.810 [NAL9602](INFO): NAL9602 initialized
2019-05-07T21:34:53.614Z,1557264893.614 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:34:59.705Z,1557264899.705 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-07T21:34:59.709Z,1557264899.709 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-07T21:35:10.903Z,1557264910.903 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.023549
CHAN A1 (24V): -0.026450
CHAN A2 (12V): -0.006464
CHAN A3 (5V): -0.002296
CHAN B0 (3.3V): 0.000308
CHAN B1 (3.15aV): 0.000358
CHAN B2 (3.15bV): 0.000267
CHAN B3 (GND): 0.001641
OPEN: 0.006215
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-07T21:35:15.811Z,1557264915.811 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T21:35:53.560Z,1557264953.560 [SBIT](IMPORTANT): SBIT PASSED
2019-05-07T21:35:53.607Z,1557264953.607 [CommandLine](IMPORTANT): got command configSet list
2019-05-07T21:35:53.607Z,1557264953.607 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-07T21:35:53.608Z,1557264953.608 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-07T21:35:53.608Z,1557264953.608 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-07T21:35:53.608Z,1557264953.608 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-07T21:35:53.608Z,1557264953.608 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-07T21:35:53.608Z,1557264953.608 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-07T21:35:53.608Z,1557264953.608 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-07T21:35:53.609Z,1557264953.609 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-07T21:35:53.609Z,1557264953.609 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-07T21:35:53.609Z,1557264953.609 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-07T21:35:53.609Z,1557264953.609 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-07T21:35:53.609Z,1557264953.609 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-07T21:35:53.609Z,1557264953.609 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-07T21:35:53.609Z,1557264953.609 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-07T21:35:53.949Z,1557264953.949 [MissionManager](IMPORTANT): Started mission Startup
2019-05-07T21:35:53.949Z,1557264953.949 [Startup] Running Loop=1
2019-05-07T21:35:53.949Z,1557264953.949 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-07T21:35:53.949Z,1557264953.949 [Startup:A.GoToSurface] Running Loop=1
2019-05-07T21:35:53.949Z,1557264953.949 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:35:53.950Z,1557264953.950 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:35:53.951Z,1557264953.951 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:35:53.951Z,1557264953.951 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:35:53.951Z,1557264953.951 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:35:53.952Z,1557264953.952 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:35:53.953Z,1557264953.953 [Startup:StartupSatComms] Running Loop=1
2019-05-07T21:35:53.953Z,1557264953.953 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-07T21:35:53.953Z,1557264953.953 [Startup:StartupSatComms:A] Running Loop=1
2019-05-07T21:35:54.340Z,1557264954.340 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-07T21:36:42.737Z,1557265002.737 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.009342
2019-05-07T21:36:54.154Z,1557265014.154 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-07T21:35:53.0Z
2019-05-07T21:36:54.154Z,1557265014.154 [Startup:StartupSatComms:A] Stopped
2019-05-07T21:36:54.155Z,1557265014.155 [Startup:StartupSatComms:B] Running Loop=1
2019-05-07T21:36:54.552Z,1557265014.552 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T21:36:59.824Z,1557265019.824 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-07T21:36:59.824Z,1557265019.824 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +1.14,        +1    +0.74,   0.00,  7.00
2019-05-07T21:37:00.282Z,1557265020.282 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190507T211026/Courier0013.lzma
2019-05-07T21:37:01.088Z,1557265021.088 [DataOverHttps](INFO): Moved sent file to Logs/20190507T211026/Courier0013.lzma.bak
2019-05-07T21:37:01.088Z,1557265021.088 [DataOverHttps](INFO): SBD MOMSN=10959332
2019-05-07T21:37:12.990Z,1557265032.990 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190507T211026/Express0014.lzma
2019-05-07T21:37:13.799Z,1557265033.799 [DataOverHttps](INFO): Moved sent file to Logs/20190507T211026/Express0014.lzma.bak
2019-05-07T21:37:13.800Z,1557265033.800 [DataOverHttps](INFO): SBD MOMSN=10959334
2019-05-07T21:37:15.578Z,1557265035.578 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-07T21:37:15.578Z,1557265035.578 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T21:37:15.589Z,1557265035.589 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T21:37:16.045Z,1557265036.045 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T21:37:16.045Z,1557265036.045 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-07T21:37:18.827Z,1557265038.827 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T21:37:18.827Z,1557265038.827 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050714445509,35.0, -0.1,   0.0,1448.9A,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T21:37:32.239Z,1557265052.239 [DataOverHttps](INFO): Sending 882 bytes from file Logs/20190507T213223/Express0001.lzma
2019-05-07T21:37:33.044Z,1557265053.044 [DataOverHttps](INFO): Moved sent file to Logs/20190507T213223/Express0001.lzma.bak
2019-05-07T21:37:33.044Z,1557265053.044 [DataOverHttps](INFO): SBD MOMSN=10959336
2019-05-07T21:37:44.860Z,1557265064.860 [DataOverHttps](INFO): Sending 1359 bytes from file Logs/20190507T213404/Express0001.lzma
2019-05-07T21:37:45.664Z,1557265065.664 [DataOverHttps](INFO): Moved sent file to Logs/20190507T213404/Express0001.lzma.bak
2019-05-07T21:37:45.664Z,1557265065.664 [DataOverHttps](INFO): SBD MOMSN=10959346
2019-05-07T21:37:46.687Z,1557265066.687 [Startup:StartupSatComms:B] Stopped
2019-05-07T21:37:46.687Z,1557265066.687 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-07T21:37:46.687Z,1557265066.687 [Startup:StartupSatComms] Stopped
2019-05-07T21:37:46.687Z,1557265066.687 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-07T21:37:46.688Z,1557265066.688 [Startup](INFO): Completed Startup
2019-05-07T21:37:46.688Z,1557265066.688 [MissionManager](INFO): Startup is completed.
2019-05-07T21:37:46.688Z,1557265066.688 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-07T21:37:46.688Z,1557265066.688 [Startup] Stopped
2019-05-07T21:37:46.688Z,1557265066.688 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-07T21:37:46.688Z,1557265066.688 [Startup:A.GoToSurface] Stopped
2019-05-07T21:37:46.689Z,1557265066.689 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T21:37:47.079Z,1557265067.079 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T21:37:47.079Z,1557265067.079 [Default] Running Loop=1
2019-05-07T21:37:47.079Z,1557265067.079 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T21:37:47.079Z,1557265067.079 [Default:B.GoToSurface] Running Loop=1
2019-05-07T21:37:47.079Z,1557265067.079 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:37:47.079Z,1557265067.079 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:37:47.080Z,1557265067.080 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:37:47.080Z,1557265067.080 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:37:47.080Z,1557265067.080 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:37:47.081Z,1557265067.081 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:37:47.081Z,1557265067.081 [Default:A.Wait] Running Loop=1
2019-05-07T21:37:47.081Z,1557265067.081 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:38:00.404Z,1557265080.404 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T21:38:00.404Z,1557265080.404 [Default:A.Wait] Stopped
2019-05-07T21:38:00.404Z,1557265080.404 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:38:00.852Z,1557265080.852 [Default:CheckIn] Running Loop=1
2019-05-07T21:38:00.852Z,1557265080.852 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T21:38:00.852Z,1557265080.852 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T21:38:01.212Z,1557265081.212 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-07T21:38:01.591Z,1557265081.591 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:38:01.591Z,1557265081.591 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:39:14.710Z,1557265154.710 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:39:14.711Z,1557265154.711 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:39:30.872Z,1557265170.872 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:39:30.872Z,1557265170.872 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:39:58.749Z,1557265198.749 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:39:58.750Z,1557265198.750 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:39:59.151Z,1557265199.151 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T21:39:59.970Z,1557265199.970 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:02.402Z,1557265202.402 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:05.630Z,1557265205.630 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:08.470Z,1557265208.470 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:11.702Z,1557265211.702 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:14.519Z,1557265214.519 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:16.562Z,1557265216.562 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-05-07T21:40:16.563Z,1557265216.563 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T21:40:16.601Z,1557265216.601 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T21:40:17.012Z,1557265217.012 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T21:40:17.012Z,1557265217.012 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-05-07T21:40:17.750Z,1557265217.750 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:18.179Z,1557265218.179 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T21:40:18.180Z,1557265218.180 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050714475409,35.0, -0.1,448.9,  0
2019-05-07T21:40:19.821Z,1557265219.821 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T21:40:19.821Z,1557265219.821 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,
2019-05-07T21:40:20.574Z,1557265220.574 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:40:20.967Z,1557265220.967 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213845.00,A,3648.16487,N,12147.28080,W,1.302,344.43,070519,,,A*7D
2019-05-07T21:40:20.970Z,1557265220.970 [NAL9602](INFO): GPS fix at 20190507T213845: (36.802748, -121.788013)
2019-05-07T21:40:21.004Z,1557265221.004 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T21:40:21.005Z,1557265221.005 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T21:40:21.421Z,1557265221.421 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T21:40:29.876Z,1557265229.876 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190507T213404/Courier0004.lzma
2019-05-07T21:40:30.680Z,1557265230.680 [DataOverHttps](INFO): Moved sent file to Logs/20190507T213404/Courier0004.lzma.bak
2019-05-07T21:40:30.680Z,1557265230.680 [DataOverHttps](INFO): SBD MOMSN=10959378
2019-05-07T21:40:44.027Z,1557265244.027 [DataOverHttps](INFO): Sending 785 bytes from file Logs/20190507T213404/Express0005.lzma
2019-05-07T21:40:44.836Z,1557265244.836 [DataOverHttps](INFO): Moved sent file to Logs/20190507T213404/Express0005.lzma.bak
2019-05-07T21:40:44.837Z,1557265244.837 [DataOverHttps](INFO): SBD MOMSN=10959381
2019-05-07T21:40:46.180Z,1557265246.180 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T21:40:46.180Z,1557265246.180 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T21:40:46.180Z,1557265246.180 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:40:53.409Z,1557265253.409 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T21:41:20.963Z,1557265280.963 [CommandLine](IMPORTANT): got command show variable range
2019-05-07T21:41:20.966Z,1557265280.966 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-07T21:41:21.075Z,1557265281.075 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-07T21:41:21.075Z,1557265281.075 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-07T21:41:21.093Z,1557265281.093 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-07T21:41:21.094Z,1557265281.094 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-07T21:41:21.095Z,1557265281.095 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-07T21:41:21.098Z,1557265281.098 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-07T21:41:21.098Z,1557265281.098 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-07T21:41:21.099Z,1557265281.099 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-07T21:41:21.099Z,1557265281.099 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-07T21:41:31.317Z,1557265291.317 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-07T21:41:35.240Z,1557265295.240 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:41:35.240Z,1557265295.240 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:41:35.291Z,1557265295.291 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T21:41:35.294Z,1557265295.294 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T21:41:35.298Z,1557265295.298 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T21:41:35.302Z,1557265295.302 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T21:41:35.305Z,1557265295.305 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T21:41:35.307Z,1557265295.307 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T21:41:35.313Z,1557265295.313 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T21:41:35.321Z,1557265295.321 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T21:41:35.325Z,1557265295.325 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

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

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-05-07T21:41:35.328Z,1557265295.328 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T21:41:35.441Z,1557265295.441 [Default] Stopped
2019-05-07T21:41:35.441Z,1557265295.441 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T21:41:35.441Z,1557265295.441 [Default:B.GoToSurface] Stopped
2019-05-07T21:41:35.441Z,1557265295.441 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T21:41:35.442Z,1557265295.442 [Default:CheckIn] Stopped
2019-05-07T21:41:35.442Z,1557265295.442 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T21:41:35.442Z,1557265295.442 [Default:CheckIn:C.Wait] Stopped
2019-05-07T21:41:35.442Z,1557265295.442 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:41:35.442Z,1557265295.442 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T21:41:35.442Z,1557265295.442 [DUSBL] Running Loop=1
2019-05-07T21:41:35.443Z,1557265295.443 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T21:41:35.443Z,1557265295.443 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T21:41:35.443Z,1557265295.443 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T21:41:35.443Z,1557265295.443 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T21:41:35.443Z,1557265295.443 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T21:41:35.443Z,1557265295.443 [DUSBL:C] Running Loop=1
2019-05-07T21:41:35.443Z,1557265295.443 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T21:41:35.444Z,1557265295.444 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:41:35.444Z,1557265295.444 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:41:35.444Z,1557265295.444 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:41:35.444Z,1557265295.444 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:41:35.444Z,1557265295.444 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:41:35.444Z,1557265295.444 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:41:35.444Z,1557265295.444 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:41:35.445Z,1557265295.445 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T21:41:35.446Z,1557265295.446 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T21:41:35.446Z,1557265295.446 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T21:41:35.450Z,1557265295.450 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T21:41:37.036Z,1557265297.036 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:41:37.036Z,1557265297.036 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:41:37.036Z,1557265297.036 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:41:37.037Z,1557265297.037 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:37.433Z,1557265297.433 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:41:37.433Z,1557265297.433 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
O
2019-05-07T21:41:37.433Z,1557265297.433 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:41:37.434Z,1557265297.434 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:41:37.435Z,1557265297.435 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:41:37.853Z,1557265297.853 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:38.247Z,1557265298.247 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:41:38.248Z,1557265298.248 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,197,000,00A6C,186,80,80,06,FF
2019-05-07T21:41:38.249Z,1557265298.249 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T21:41:38.332Z,1557265298.332 [Reporter](INFO): acoustic_contact_range 122.580002 m
2019-05-07T21:41:40.671Z,1557265300.671 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:41:40.671Z,1557265300.671 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:41:40.672Z,1557265300.672 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:41:40.721Z,1557265300.721 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:41:40.722Z,1557265300.722 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
197,000,00A6C,186,80,80,06,FF
2019-05-07T21:41:40.726Z,1557265300.726 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:41:40.726Z,1557265300.726 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:41:40.735Z,1557265300.735 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:41:41.072Z,1557265301.072 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:41.479Z,1557265301.479 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:41:41.480Z,1557265301.480 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1E4,000,00000,187,80,81,0A,FF
2019-05-07T21:41:41.883Z,1557265301.883 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:41:41.883Z,1557265301.883 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:41:41.884Z,1557265301.884 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:41:41.887Z,1557265301.887 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:42.281Z,1557265302.281 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:41:42.281Z,1557265302.281 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1E4,000,00000,187,80,81,0A,FF
2019-05-07T21:41:42.281Z,1557265302.281 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:41:42.281Z,1557265302.281 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:41:42.314Z,1557265302.314 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:41:42.703Z,1557265302.703 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:43.096Z,1557265303.096 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:43.495Z,1557265303.495 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:43.900Z,1557265303.900 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:44.304Z,1557265304.304 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:44.723Z,1557265304.723 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:45.109Z,1557265305.109 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:45.519Z,1557265305.519 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:45.553Z,1557265305.553 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:41:45.553Z,1557265305.553 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:41:45.553Z,1557265305.553 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:41:45.578Z,1557265305.578 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:41:45.578Z,1557265305.578 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:41:45.579Z,1557265305.579 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:41:45.924Z,1557265305.924 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:46.332Z,1557265306.332 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:46.731Z,1557265306.731 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:47.132Z,1557265307.132 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:47.540Z,1557265307.540 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:41:47.943Z,1557265307.943 [DUSBL_Hydroid](INFO): IN QUEUE:00000,187,80,81,0D,FF
7,80,81,0A,FF
2019-05-07T21:41:47.954Z,1557265307.954 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070243
2019-05-07T21:41:47.955Z,1557265307.955 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:41:47.955Z,1557265307.955 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:41:47.955Z,1557265307.955 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:41:47.958Z,1557265307.958 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:48.347Z,1557265308.347 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:41:48.348Z,1557265308.348 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,0D,FF
7,80,81,0A,FF
2019-05-07T21:41:48.348Z,1557265308.348 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:41:48.348Z,1557265308.348 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:41:48.349Z,1557265308.349 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:41:48.751Z,1557265308.751 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:49.152Z,1557265309.152 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:41:49.152Z,1557265309.152 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,225,000,00000,187,80,81,0B,FF
2019-05-07T21:41:49.555Z,1557265309.555 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:41:49.555Z,1557265309.555 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:41:49.556Z,1557265309.556 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:41:49.556Z,1557265309.556 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:49.957Z,1557265309.957 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:41:49.957Z,1557265309.957 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
225,000,00000,187,80,81,0B,FF
2019-05-07T21:41:49.957Z,1557265309.957 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:41:49.958Z,1557265309.958 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:41:49.959Z,1557265309.959 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:41:50.364Z,1557265310.364 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:50.778Z,1557265310.778 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:51.169Z,1557265311.169 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:51.573Z,1557265311.573 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:51.983Z,1557265311.983 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:52.381Z,1557265312.381 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:52.808Z,1557265312.808 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:41:53.191Z,1557265313.191 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T21:41:53.191Z,1557265313.191 [DUSBL_Hydroid](INFO): USBL response received:!U1,N,80,80,0,00000,187,80,81,0B,FF
2019-05-07T21:42:09.134Z,1557265329.134 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,0,00000,187,80,81,0B,FF
2019-05-07T21:42:09.134Z,1557265329.134 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-07T21:42:09.153Z,1557265329.153 [RDI_Pathfinder](ERROR): No DVL communication! Re-initializing
2019-05-07T21:42:09.153Z,1557265329.153 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-05-07T21:42:09.153Z,1557265329.153 [RDI_Pathfinder](ERROR): Communications Fault
2019-05-07T21:42:09.402Z,1557265329.402 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:42:09.402Z,1557265329.402 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:42:09.402Z,1557265329.402 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:42:09.415Z,1557265329.415 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:42:09.415Z,1557265329.415 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:42:09.415Z,1557265329.415 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:42:09.415Z,1557265329.415 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:42:09.415Z,1557265329.415 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:42:09.415Z,1557265329.415 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T21:42:09.416Z,1557265329.416 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T21:42:09.416Z,1557265329.416 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:42:09.416Z,1557265329.416 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:42:09.416Z,1557265329.416 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:42:09.416Z,1557265329.416 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:42:09.416Z,1557265329.416 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:42:09.433Z,1557265329.433 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-05-07T21:42:09.506Z,1557265329.506 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:09.506Z,1557265329.506 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:09.514Z,1557265329.514 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:09.515Z,1557265329.515 [DUSBL_Hydroid](INFO): 7 bytes available.****
2019-05-07T21:42:09.643Z,1557265329.643 [RDI_Pathfinder](INFO): Powering down
2019-05-07T21:42:09.644Z,1557265329.644 [BPC1](ERROR): BPC1A buffer size (966 bytes) exceeded the max device response limit.
2019-05-07T21:42:09.644Z,1557265329.644 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-05-07T21:42:09.868Z,1557265329.868 [DUSBL_Hydroid](INFO): 12 bytes available.****
2019-05-07T21:42:09.868Z,1557265329.868 [DUSBL_Hydroid](INFO): USBL response received:63,E4
!U1,P
0,00000,187,80,81,0B,FF
2019-05-07T21:42:09.868Z,1557265329.868 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:09.868Z,1557265329.868 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:09.871Z,1557265329.871 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:10.271Z,1557265330.271 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:10.273Z,1557265330.273 [Micromodem](ERROR): Response from modem unexpected: $CADQF,194,1*5C

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

2019-05-07T21:42:10.339Z,1557265330.339 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-05-07T21:42:10.339Z,1557265330.339 [RDI_Pathfinder] No Fault, FailCount= 1
2019-05-07T21:42:10.692Z,1557265330.692 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:42:10.692Z,1557265330.692 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C6,000,00000,186,80,81,0E,FF
2019-05-07T21:42:10.712Z,1557265330.712 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507214202.768522,06,266,12,0100,0150,246,00,00,02,00,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,194,-0.05,-999,9760,4000*75

2019-05-07T21:42:11.088Z,1557265331.088 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:11.088Z,1557265331.088 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:11.089Z,1557265331.089 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:11.090Z,1557265331.090 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:11.507Z,1557265331.507 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:11.508Z,1557265331.508 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C6,000,00000,186,80,81,0E,FF
2019-05-07T21:42:11.508Z,1557265331.508 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:11.508Z,1557265331.508 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:11.509Z,1557265331.509 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:11.904Z,1557265331.904 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:12.296Z,1557265332.296 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:12.699Z,1557265332.699 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:13.107Z,1557265333.107 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:13.513Z,1557265333.513 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:13.903Z,1557265333.903 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:14.312Z,1557265334.312 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:14.715Z,1557265334.715 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:15.120Z,1557265335.120 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:15.524Z,1557265335.524 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:15.927Z,1557265335.927 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:16.327Z,1557265336.327 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:16.736Z,1557265336.736 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:17.139Z,1557265337.139 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,07,FF
6,80,81,0E,FF
2019-05-07T21:42:17.150Z,1557265337.150 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.061718
2019-05-07T21:42:17.151Z,1557265337.151 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:17.151Z,1557265337.151 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:17.151Z,1557265337.151 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:17.153Z,1557265337.153 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:17.543Z,1557265337.543 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:17.544Z,1557265337.544 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,07,FF
6,80,81,0E,FF
2019-05-07T21:42:17.544Z,1557265337.544 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:17.544Z,1557265337.544 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:17.545Z,1557265337.545 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:17.952Z,1557265337.952 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:18.348Z,1557265338.348 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:42:18.348Z,1557265338.348 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,DAC,000,0026B,18A,80,80,03,FF
2019-05-07T21:42:18.751Z,1557265338.751 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:18.751Z,1557265338.751 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:18.752Z,1557265338.752 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:18.754Z,1557265338.754 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:19.188Z,1557265339.188 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:19.563Z,1557265339.563 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:19.967Z,1557265339.967 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:20.008Z,1557265340.008 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:42:20.008Z,1557265340.008 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:42:20.008Z,1557265340.008 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:42:20.008Z,1557265340.008 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:42:20.008Z,1557265340.008 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:42:20.009Z,1557265340.009 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:42:20.368Z,1557265340.368 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:20.775Z,1557265340.775 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:21.175Z,1557265341.175 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:21.584Z,1557265341.584 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:21.994Z,1557265341.994 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:22.392Z,1557265342.392 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:22.792Z,1557265342.792 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:23.204Z,1557265343.204 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:23.256Z,1557265343.256 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-07T21:42:23.259Z,1557265343.259 [BPC1](INFO): Received data from all battery sticks.
2019-05-07T21:42:23.604Z,1557265343.604 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:24.008Z,1557265344.008 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:24.024Z,1557265344.024 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T21:42:24.412Z,1557265344.412 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:24.812Z,1557265344.812 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T21:42:24.822Z,1557265344.822 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.070142
2019-05-07T21:42:24.823Z,1557265344.823 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:24.823Z,1557265344.823 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:24.823Z,1557265344.823 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:24.825Z,1557265344.825 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:25.213Z,1557265345.213 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:25.214Z,1557265345.214 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
DAC,000,0026B,18A,80,80,03,FF
2019-05-07T21:42:25.214Z,1557265345.214 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:25.214Z,1557265345.214 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:25.215Z,1557265345.215 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:25.639Z,1557265345.639 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:26.023Z,1557265346.023 [DUSBL_Hydroid](INFO): 1 bytes available.****
2019-05-07T21:42:26.428Z,1557265346.428 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:26.832Z,1557265346.832 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:27.242Z,1557265347.242 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:27.648Z,1557265347.648 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:28.047Z,1557265348.047 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:28.451Z,1557265348.451 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:28.856Z,1557265348.856 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:29.260Z,1557265349.260 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:29.670Z,1557265349.670 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:30.068Z,1557265350.068 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:30.475Z,1557265350.475 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:30.499Z,1557265350.499 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:42:30.499Z,1557265350.499 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:42:30.499Z,1557265350.499 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T21:42:30.500Z,1557265350.500 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:42:30.501Z,1557265350.501 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:42:30.501Z,1557265350.501 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:42:30.501Z,1557265350.501 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:42:30.501Z,1557265350.501 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:42:30.872Z,1557265350.872 [DUSBL_Hydroid](INFO): IN QUEUE:!0000,186,80,81,0A,FF
A,80,80,03,FF
2019-05-07T21:42:30.883Z,1557265350.883 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059105
2019-05-07T21:42:30.883Z,1557265350.883 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:30.883Z,1557265350.883 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:30.883Z,1557265350.883 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:30.883Z,1557265350.883 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:31.276Z,1557265351.276 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:31.276Z,1557265351.276 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0A,FF
A,80,80,03,FF
2019-05-07T21:42:31.276Z,1557265351.276 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:31.276Z,1557265351.276 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:31.278Z,1557265351.278 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:31.680Z,1557265351.680 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:31.681Z,1557265351.681 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T21:42:31.688Z,1557265351.688 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507214231.305921,06,175,16,0096,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,190,-0.10,-999,9760,4000*7F

2019-05-07T21:42:32.087Z,1557265352.087 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:32.492Z,1557265352.492 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:32.889Z,1557265352.889 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:33.300Z,1557265353.300 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:33.700Z,1557265353.700 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:34.104Z,1557265354.104 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:34.514Z,1557265354.514 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:34.912Z,1557265354.912 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:35.319Z,1557265355.319 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:35.736Z,1557265355.736 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:36.128Z,1557265356.128 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:36.531Z,1557265356.531 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:36.932Z,1557265356.932 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,0A,FF
A,80,80,03,FF
2019-05-07T21:42:36.942Z,1557265356.942 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059082
2019-05-07T21:42:36.943Z,1557265356.943 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:36.943Z,1557265356.943 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:36.943Z,1557265356.943 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:36.945Z,1557265356.945 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:37.336Z,1557265357.336 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:37.336Z,1557265357.336 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,0A,FF
A,80,80,03,FF
2019-05-07T21:42:37.336Z,1557265357.336 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:37.336Z,1557265357.336 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:37.337Z,1557265357.337 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:37.744Z,1557265357.744 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:38.144Z,1557265358.144 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:42:38.144Z,1557265358.144 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,133,000,00275,186,80,80,07,FF
2019-05-07T21:42:38.144Z,1557265358.144 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T21:42:38.200Z,1557265358.200 [Reporter](INFO): acoustic_contact_range 0.239999 m
2019-05-07T21:42:40.574Z,1557265360.574 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:40.574Z,1557265360.574 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:40.586Z,1557265360.586 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:40.587Z,1557265360.587 [DUSBL_Hydroid](INFO): 3 bytes available.****
2019-05-07T21:42:40.972Z,1557265360.972 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:40.972Z,1557265360.972 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
133,000,00275,186,80,80,07,FF
2019-05-07T21:42:40.972Z,1557265360.972 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:40.972Z,1557265360.972 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:40.973Z,1557265360.973 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:41.068Z,1557265361.068 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:42:41.069Z,1557265361.069 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:42:41.069Z,1557265361.069 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:42:41.069Z,1557265361.069 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:42:41.069Z,1557265361.069 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:42:41.069Z,1557265361.069 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:42:41.069Z,1557265361.069 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:42:41.070Z,1557265361.070 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:42:41.070Z,1557265361.070 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T21:42:41.070Z,1557265361.070 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T21:42:41.070Z,1557265361.070 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:42:41.070Z,1557265361.070 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:42:41.074Z,1557265361.074 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:42:41.074Z,1557265361.074 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:42:41.074Z,1557265361.074 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:42:41.375Z,1557265361.375 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:41.780Z,1557265361.780 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:42:41.780Z,1557265361.780 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,210,000,00000,187,80,81,0A,FF
2019-05-07T21:42:42.183Z,1557265362.183 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:42.183Z,1557265362.183 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:42.184Z,1557265362.184 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:42.184Z,1557265362.184 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:42.587Z,1557265362.587 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:42.588Z,1557265362.588 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
210,000,00000,187,80,81,0A,FF
2019-05-07T21:42:42.588Z,1557265362.588 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:42.588Z,1557265362.588 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:42.589Z,1557265362.589 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:42.996Z,1557265362.996 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:43.393Z,1557265363.393 [DUSBL_Hydroid](INFO): 2 bytes available.****
2019-05-07T21:42:43.797Z,1557265363.797 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:44.208Z,1557265364.208 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:44.609Z,1557265364.609 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:45.009Z,1557265365.009 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:45.420Z,1557265365.420 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:45.836Z,1557265365.836 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:46.221Z,1557265366.221 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:46.636Z,1557265366.636 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:47.032Z,1557265367.032 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:47.438Z,1557265367.438 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:47.848Z,1557265367.848 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:42:48.245Z,1557265368.245 [DUSBL_Hydroid](INFO): IN QUEUE:!U000,187,80,81,0B,FF
7,80,81,0A,FF
2019-05-07T21:42:48.258Z,1557265368.258 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.074366
2019-05-07T21:42:48.259Z,1557265368.259 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:48.259Z,1557265368.259 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:48.259Z,1557265368.259 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:48.261Z,1557265368.261 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:48.663Z,1557265368.663 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:48.663Z,1557265368.663 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
187,80,81,0B,FF
7,80,81,0A,FF
2019-05-07T21:42:48.663Z,1557265368.663 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:48.663Z,1557265368.663 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:48.665Z,1557265368.665 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:49.056Z,1557265369.056 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:49.453Z,1557265369.453 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:42:49.453Z,1557265369.453 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1F6,000,00000,187,80,81,04,FF
2019-05-07T21:42:49.857Z,1557265369.857 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:49.857Z,1557265369.857 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:49.858Z,1557265369.858 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:49.859Z,1557265369.859 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:50.268Z,1557265370.268 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:50.268Z,1557265370.268 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1F6,000,00000,187,80,81,04,FF
2019-05-07T21:42:50.268Z,1557265370.268 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:50.268Z,1557265370.268 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:50.269Z,1557265370.269 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:50.679Z,1557265370.679 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:51.075Z,1557265371.075 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:42:51.076Z,1557265371.076 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,217,000,00000,187,80,81,0D,FF
2019-05-07T21:42:51.479Z,1557265371.479 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:51.479Z,1557265371.479 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:51.480Z,1557265371.480 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:51.483Z,1557265371.483 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:51.513Z,1557265371.513 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:42:51.513Z,1557265371.513 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:42:51.514Z,1557265371.514 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T21:42:51.515Z,1557265371.515 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:42:51.516Z,1557265371.516 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:42:51.516Z,1557265371.516 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:42:51.516Z,1557265371.516 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:42:51.516Z,1557265371.516 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:42:51.883Z,1557265371.883 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:51.884Z,1557265371.884 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
217,000,00000,187,80,81,0D,FF
2019-05-07T21:42:51.884Z,1557265371.884 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:51.884Z,1557265371.884 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:51.885Z,1557265371.885 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:52.342Z,1557265372.342 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:52.688Z,1557265372.688 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:42:52.688Z,1557265372.688 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,DAA,000,0026B,18A,80,80,03,FF
2019-05-07T21:42:53.090Z,1557265373.090 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:53.090Z,1557265373.090 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:53.091Z,1557265373.091 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:53.092Z,1557265373.092 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:53.499Z,1557265373.499 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:53.904Z,1557265373.904 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:54.307Z,1557265374.307 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:54.705Z,1557265374.705 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:55.116Z,1557265375.116 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:55.516Z,1557265375.516 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:55.917Z,1557265375.917 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:56.328Z,1557265376.328 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:56.725Z,1557265376.725 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:57.133Z,1557265377.133 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:57.540Z,1557265377.540 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:57.937Z,1557265377.937 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:58.341Z,1557265378.341 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:58.752Z,1557265378.752 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:59.149Z,1557265379.149 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T21:42:59.162Z,1557265379.162 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.071725
2019-05-07T21:42:59.163Z,1557265379.163 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:42:59.163Z,1557265379.163 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:42:59.164Z,1557265379.164 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:42:59.165Z,1557265379.165 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:42:59.553Z,1557265379.553 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:42:59.553Z,1557265379.553 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
DAA,000,0026B,18A,80,80,03,FF
2019-05-07T21:42:59.553Z,1557265379.553 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:42:59.553Z,1557265379.553 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:42:59.555Z,1557265379.555 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:42:59.964Z,1557265379.964 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:00.361Z,1557265380.361 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:43:00.362Z,1557265380.362 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1C8,000,0024B,186,80,80,08,FF
2019-05-07T21:43:00.765Z,1557265380.765 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:43:00.765Z,1557265380.765 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:43:00.766Z,1557265380.766 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:43:00.767Z,1557265380.767 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:01.176Z,1557265381.176 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:01.573Z,1557265381.573 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:01.977Z,1557265381.977 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:02.011Z,1557265382.011 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:43:02.012Z,1557265382.012 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:43:02.012Z,1557265382.012 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:43:02.012Z,1557265382.012 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:43:02.012Z,1557265382.012 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:43:02.012Z,1557265382.012 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:43:02.012Z,1557265382.012 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:43:02.013Z,1557265382.013 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:43:02.388Z,1557265382.388 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:02.785Z,1557265382.785 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:03.189Z,1557265383.189 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:03.600Z,1557265383.600 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:03.997Z,1557265383.997 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:04.401Z,1557265384.401 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:04.812Z,1557265384.812 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:05.209Z,1557265385.209 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:05.613Z,1557265385.613 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:06.024Z,1557265386.024 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:06.421Z,1557265386.421 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:06.827Z,1557265386.827 [DUSBL_Hydroid](INFO): IN QUEUE:
2019-05-07T21:43:06.838Z,1557265386.838 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.072802
2019-05-07T21:43:06.839Z,1557265386.839 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:43:06.839Z,1557265386.839 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:43:06.839Z,1557265386.839 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:43:06.841Z,1557265386.841 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:07.236Z,1557265387.236 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:43:07.236Z,1557265387.236 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1C8,000,0024B,186,80,80,08,FF
2019-05-07T21:43:07.236Z,1557265387.236 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:43:07.236Z,1557265387.236 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:43:07.237Z,1557265387.237 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:43:07.663Z,1557265387.663 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:08.037Z,1557265388.037 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:43:08.037Z,1557265388.037 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1EC,000,00000,187,80,81,07,FF
2019-05-07T21:43:08.447Z,1557265388.447 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:43:08.447Z,1557265388.447 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:43:08.448Z,1557265388.448 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:43:08.451Z,1557265388.451 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:08.845Z,1557265388.845 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:43:08.846Z,1557265388.846 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1EC,000,00000,187,80,81,07,FF
2019-05-07T21:43:08.846Z,1557265388.846 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:43:08.846Z,1557265388.846 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:43:08.847Z,1557265388.847 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:43:09.249Z,1557265389.249 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:09.669Z,1557265389.669 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:10.057Z,1557265390.057 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:10.464Z,1557265390.464 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:10.868Z,1557265390.868 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:11.269Z,1557265391.269 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:11.680Z,1557265391.680 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:12.084Z,1557265392.084 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:12.487Z,1557265392.487 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:12.511Z,1557265392.511 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:43:12.512Z,1557265392.512 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:43:12.512Z,1557265392.512 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:43:12.512Z,1557265392.512 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:43:12.512Z,1557265392.512 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:43:12.512Z,1557265392.512 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:43:12.512Z,1557265392.512 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:43:12.512Z,1557265392.512 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:43:12.513Z,1557265392.513 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T21:43:12.513Z,1557265392.513 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T21:43:12.513Z,1557265392.513 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:43:12.513Z,1557265392.513 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:43:12.513Z,1557265392.513 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:43:12.513Z,1557265392.513 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:43:12.513Z,1557265392.513 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:43:12.886Z,1557265392.886 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:13.292Z,1557265393.292 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:13.694Z,1557265393.694 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:14.100Z,1557265394.100 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:14.503Z,1557265394.503 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,07,FF
7,80,81,07,FF
2019-05-07T21:43:14.515Z,1557265394.515 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.066846
2019-05-07T21:43:14.515Z,1557265394.515 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:43:14.515Z,1557265394.515 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:43:14.515Z,1557265394.515 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:43:14.516Z,1557265394.516 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:14.908Z,1557265394.908 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:43:14.908Z,1557265394.908 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
186,80,81,07,FF
7,80,81,07,FF
2019-05-07T21:43:14.908Z,1557265394.908 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:43:14.908Z,1557265394.908 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:43:14.910Z,1557265394.910 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:43:15.311Z,1557265395.311 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:15.313Z,1557265395.313 [Micromodem](ERROR): Response from modem unexpected: $CADQF,204,1*56

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

2019-05-07T21:43:15.716Z,1557265395.716 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:43:15.716Z,1557265395.716 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,212,000,00000,187,80,81,0F,FF
2019-05-07T21:43:15.723Z,1557265395.723 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507214314.555768,06,112,14,0099,0150,246,00,00,01,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,204,0.00,-999,9760,4000*54

2019-05-07T21:43:16.119Z,1557265396.119 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:43:16.120Z,1557265396.120 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:43:16.120Z,1557265396.120 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:43:16.120Z,1557265396.120 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:16.524Z,1557265396.524 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:43:16.524Z,1557265396.524 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
212,000,00000,187,80,81,0F,FF
2019-05-07T21:43:16.524Z,1557265396.524 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:43:16.524Z,1557265396.524 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:43:16.525Z,1557265396.525 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:43:16.928Z,1557265396.928 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:17.332Z,1557265397.332 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:43:17.332Z,1557265397.332 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,1D0,000,002C4,186,80,80,15,FF
2019-05-07T21:43:17.332Z,1557265397.332 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-05-07T21:43:17.376Z,1557265397.376 [Reporter](INFO): acoustic_contact_range 4.979999 m
2019-05-07T21:43:19.755Z,1557265399.755 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:43:19.756Z,1557265399.756 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:43:19.756Z,1557265399.756 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:43:19.756Z,1557265399.756 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:20.160Z,1557265400.160 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:43:20.160Z,1557265400.160 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
1D0,000,002C4,186,80,80,15,FF
2019-05-07T21:43:20.160Z,1557265400.160 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:43:20.160Z,1557265400.160 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:43:20.161Z,1557265400.161 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:43:20.571Z,1557265400.571 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:20.968Z,1557265400.968 [DUSBL_Hydroid](INFO): 36 bytes available.****
2019-05-07T21:43:20.968Z,1557265400.968 [DUSBL_Hydroid](INFO): USBL response received:!U1,R,22F,000,00000,188,80,81,0C,FF
2019-05-07T21:43:21.388Z,1557265401.388 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T21:43:21.388Z,1557265401.388 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T21:43:21.388Z,1557265401.388 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T21:43:21.389Z,1557265401.389 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:21.803Z,1557265401.803 [DUSBL_Hydroid](INFO): 6 bytes available.****
2019-05-07T21:43:21.803Z,1557265401.803 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
22F,000,00000,188,80,81,0C,FF
2019-05-07T21:43:21.803Z,1557265401.803 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T21:43:21.804Z,1557265401.804 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T21:43:21.805Z,1557265401.805 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T21:43:22.192Z,1557265402.192 [DUSBL_Hydroid](INFO): 0 bytes available.****
2019-05-07T21:43:22.586Z,1557265402.586 [DUSBL_Hydroid](INFO): 3 bytes available.****
2019-05-07T21:43:22.992Z,1557265402.992 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:23.035Z,1557265403.035 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T21:43:23.035Z,1557265403.035 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:43:23.035Z,1557265403.035 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:43:23.036Z,1557265403.036 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T21:43:23.036Z,1557265403.036 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:43:23.036Z,1557265403.036 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:43:23.036Z,1557265403.036 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater] Running Loop=10
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T21:43:23.037Z,1557265403.037 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:43:23.411Z,1557265403.411 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:23.820Z,1557265403.820 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:24.200Z,1557265404.200 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:24.605Z,1557265404.605 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:25.007Z,1557265405.007 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:25.413Z,1557265405.413 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:25.629Z,1557265405.629 [CommandLine](IMPORTANT): got command stop
2019-05-07T21:43:25.629Z,1557265405.629 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-07T21:43:25.630Z,1557265405.630 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-07T21:43:25.816Z,1557265405.816 [DUSBL_Hydroid](INFO): 22 bytes available.****
2019-05-07T21:43:25.862Z,1557265405.862 [MissionManager](INFO): MissionManager is completed.
2019-05-07T21:43:25.863Z,1557265405.863 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:A.Pitch] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:B.SetSpeed] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:C] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:RequestRepeater] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T21:43:25.863Z,1557265405.863 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:43:26.247Z,1557265406.247 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T21:43:26.247Z,1557265406.247 [Default] Running Loop=1
2019-05-07T21:43:26.247Z,1557265406.247 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T21:43:26.247Z,1557265406.247 [Default:B.GoToSurface] Running Loop=1
2019-05-07T21:43:26.247Z,1557265406.247 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T21:43:26.247Z,1557265406.247 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T21:43:26.248Z,1557265406.248 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T21:43:26.248Z,1557265406.248 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T21:43:26.249Z,1557265406.249 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T21:43:26.249Z,1557265406.249 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T21:43:26.249Z,1557265406.249 [Default:A.Wait] Running Loop=1
2019-05-07T21:43:26.249Z,1557265406.249 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:43:39.576Z,1557265419.576 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T21:43:39.576Z,1557265419.576 [Default:A.Wait] Stopped
2019-05-07T21:43:39.576Z,1557265419.576 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:43:39.988Z,1557265419.988 [Default:CheckIn] Running Loop=1
2019-05-07T21:43:39.988Z,1557265419.988 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T21:43:39.988Z,1557265419.988 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T21:43:41.586Z,1557265421.586 [NAL9602](DEBUG): Fix Requested
2019-05-07T21:43:41.992Z,1557265421.992 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214206.00,A,3648.17032,N,12147.27913,W,0.311,301.86,070519,,,A*7B
2019-05-07T21:43:41.994Z,1557265421.994 [NAL9602](INFO): GPS fix at 20190507T214206: (36.802839, -121.787986)
2019-05-07T21:43:42.026Z,1557265422.026 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T21:43:42.026Z,1557265422.026 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T21:43:47.674Z,1557265427.674 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190507T213404/Courier0007.lzma
2019-05-07T21:43:48.481Z,1557265428.481 [DataOverHttps](INFO): Moved sent file to Logs/20190507T213404/Courier0007.lzma.bak
2019-05-07T21:43:48.481Z,1557265428.481 [DataOverHttps](INFO): SBD MOMSN=10959390
2019-05-07T21:43:55.449Z,1557265435.449 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:43:55.449Z,1557265435.449 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:44:00.144Z,1557265440.144 [DataOverHttps](INFO): Sending 979 bytes from file Logs/20190507T213404/Express0008.lzma
2019-05-07T21:44:00.948Z,1557265440.948 [DataOverHttps](INFO): Moved sent file to Logs/20190507T213404/Express0008.lzma.bak
2019-05-07T21:44:00.948Z,1557265440.948 [DataOverHttps](INFO): SBD MOMSN=10959479
2019-05-07T21:44:01.956Z,1557265441.956 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T21:44:01.956Z,1557265441.956 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T21:44:01.956Z,1557265441.956 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T21:44:11.198Z,1557265451.198 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:44:11.198Z,1557265451.198 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:44:50.390Z,1557265490.390 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:44:50.391Z,1557265490.391 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:47:15.041Z,1557265635.041 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T21:47:15.041Z,1557265635.041 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  92.93,  96.92,   0.00
2019-05-07T21:47:34.427Z,1557265654.427 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:47:34.428Z,1557265654.428 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:47:53.022Z,1557265673.022 [NAL9602](INFO): SBD MO Status=2, MOMSN=3873, MT Status=2, MTMSN=0
2019-05-07T21:47:53.023Z,1557265673.023 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T21:47:58.148Z,1557265678.148 [CommandLine](IMPORTANT): got command restart application
2019-05-07T21:47:59.154Z,1557265679.154 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:47:59.155Z,1557265679.155 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:47:59.174Z,1557265679.174 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-07T21:47:59.174Z,1557265679.174 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:47:59.175Z,1557265679.175 [CommandLine](INFO): Join timeout helper Thread ID is 1078
2019-05-07T21:47:59.176Z,1557265679.176 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-07T21:47:59.176Z,1557265679.176 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:47:59.176Z,1557265679.176 [NavChartDb](INFO): Join timeout helper Thread ID is 1079
2019-05-07T21:47:59.547Z,1557265679.547 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:47:59.547Z,1557265679.547 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:47:59.566Z,1557265679.566 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-07T21:47:59.566Z,1557265679.566 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:47:59.567Z,1557265679.567 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1080
2019-05-07T21:47:59.891Z,1557265679.891 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:47:59.891Z,1557265679.891 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T21:47:59.892Z,1557265679.892 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:47:59.906Z,1557265679.906 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-07T21:47:59.907Z,1557265679.907 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:47:59.907Z,1557265679.907 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1081
2019-05-07T21:48:00.071Z,1557265680.071 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:48:00.071Z,1557265680.071 [CTD_NeilBrown](INFO): Powering down
2019-05-07T21:48:00.082Z,1557265680.082 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.094Z,1557265680.094 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-07T21:48:00.094Z,1557265680.094 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.095Z,1557265680.095 [Radio_Surface](INFO): Join timeout helper Thread ID is 1082
2019-05-07T21:48:00.298Z,1557265680.298 [Radio_Surface](INFO): Powering down
2019-05-07T21:48:00.299Z,1557265680.299 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:48:00.300Z,1557265680.300 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.315Z,1557265680.315 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-07T21:48:00.315Z,1557265680.315 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.316Z,1557265680.316 [DataOverHttps](INFO): Join timeout helper Thread ID is 1083
2019-05-07T21:48:00.350Z,1557265680.350 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:48:00.351Z,1557265680.351 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.352Z,1557265680.352 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-07T21:48:00.352Z,1557265680.352 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.352Z,1557265680.352 [logger](INFO): Join timeout helper Thread ID is 1084
2019-05-07T21:48:00.388Z,1557265680.388 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:48:00.388Z,1557265680.388 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.391Z,1557265680.391 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-07T21:48:00.391Z,1557265680.391 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.391Z,1557265680.391 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-07T21:48:00.391Z,1557265680.391 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:00.392Z,1557265680.392 [controlThread](INFO): Join timeout helper Thread ID is 1085
2019-05-07T21:48:00.674Z,1557265680.674 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T21:48:00.675Z,1557265680.675 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-07T21:48:00.675Z,1557265680.675 [AHRS_M2](INFO): Powering down
2019-05-07T21:48:00.747Z,1557265680.747 [DUSBL_Hydroid](INFO): Powering down
2019-05-07T21:48:00.819Z,1557265680.819 [Micromodem](INFO): Powering down
2019-05-07T21:48:00.915Z,1557265680.915 [NAL9602](INFO): Powering down
2019-05-07T21:48:00.986Z,1557265680.986 [RDI_Pathfinder](INFO): Powering down
2019-05-07T21:48:00.988Z,1557265680.988 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-07T21:48:00.989Z,1557265680.989 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-07T21:48:00.989Z,1557265680.989 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-07T21:48:00.989Z,1557265680.989 [MissionManager](INFO): Uninitializing Mission Default
2019-05-07T21:48:00.990Z,1557265680.990 [Default] Stopped
2019-05-07T21:48:00.990Z,1557265680.990 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T21:48:00.990Z,1557265680.990 [Default:B.GoToSurface] Stopped
2019-05-07T21:48:00.990Z,1557265680.990 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T21:48:00.990Z,1557265680.990 [Default:CheckIn] Stopped
2019-05-07T21:48:00.990Z,1557265680.990 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T21:48:00.990Z,1557265680.990 [Default:CheckIn:C.Wait] Stopped
2019-05-07T21:48:00.990Z,1557265680.990 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T21:48:00.993Z,1557265680.993 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-07T21:48:00.993Z,1557265680.993 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-07T21:48:00.993Z,1557265680.993 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-07T21:48:00.994Z,1557265680.994 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-07T21:48:00.994Z,1557265680.994 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-07T21:48:00.994Z,1557265680.994 [BuoyancyServo](INFO): Powering down
2019-05-07T21:48:01.006Z,1557265681.006 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-07T21:48:01.007Z,1557265681.007 [ElevatorServo](INFO): Powering down
2019-05-07T21:48:01.007Z,1557265681.007 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-07T21:48:01.007Z,1557265681.007 [MassServo](INFO): Powering down
2019-05-07T21:48:01.008Z,1557265681.008 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T21:48:01.008Z,1557265681.008 [RudderServo](INFO): Powering down
2019-05-07T21:48:01.009Z,1557265681.009 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-07T21:48:01.009Z,1557265681.009 [ThrusterServo](INFO): Powering down
2019-05-07T21:48:01.010Z,1557265681.010 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-07T21:48:01.011Z,1557265681.011 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-07T21:48:01.011Z,1557265681.011 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-07T21:48:01.011Z,1557265681.011 [CBIT](DEBUG): Powering off loads.
2019-05-07T21:48:01.022Z,1557265681.022 [CBIT](DEBUG): Disabling WDT.
2019-05-07T21:48:01.034Z,1557265681.034 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-07T21:48:01.035Z,1557265681.035 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:01.087Z,1557265681.087 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:01.096Z,1557265681.096 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:01.138Z,1557265681.138 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:01.140Z,1557265681.140 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:01.194Z,1557265681.194 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T21:48:01.259Z,1557265681.259 [logger ThreadHandler](INFO): Thread cancelled.