2019-05-07T04:47:52.488Z,1557204472.488 [Supervisor](DEBUG): Initializing supervisor.
2019-05-07T04:47:52.491Z,1557204472.491 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-07T04:47:52.491Z,1557204472.491 [SyncHandler](INFO): Protected caller Thread ID is 1982
2019-05-07T04:47:52.492Z,1557204472.492 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-07T04:47:52.493Z,1557204472.493 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-07T04:47:52.493Z,1557204472.493 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1983
2019-05-07T04:47:52.496Z,1557204472.496 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-07T04:47:52.508Z,1557204472.508 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-07T04:47:52.509Z,1557204472.509 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-07T04:47:52.509Z,1557204472.509 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1984
2019-05-07T04:47:52.510Z,1557204472.510 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-07T04:47:52.511Z,1557204472.511 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-07T04:47:52.512Z,1557204472.512 [logger ThreadHandler](INFO): Protected caller Thread ID is 1985
2019-05-07T04:47:52.514Z,1557204472.514 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-07T04:47:52.514Z,1557204472.514 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-07T04:47:52.516Z,1557204472.516 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-07T04:47:52.939Z,1557204472.939 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-07T04:47:52.939Z,1557204472.939 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-07T04:47:53.037Z,1557204473.037 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-07T04:47:53.037Z,1557204473.037 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-07T04:47:53.363Z,1557204473.363 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-07T04:47:53.364Z,1557204473.364 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-07T04:47:53.505Z,1557204473.505 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-07T04:47:53.506Z,1557204473.506 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-07T04:47:53.697Z,1557204473.697 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-07T04:47:53.698Z,1557204473.698 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-07T04:47:54.153Z,1557204474.153 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-07T04:47:54.154Z,1557204474.154 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-07T04:47:54.364Z,1557204474.364 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-07T04:47:54.365Z,1557204474.365 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-07T04:47:54.510Z,1557204474.510 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-07T04:47:54.511Z,1557204474.511 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-07T04:47:54.705Z,1557204474.705 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-07T04:47:54.705Z,1557204474.705 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-07T04:47:54.801Z,1557204474.801 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-07T04:47:54.802Z,1557204474.802 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-07T04:47:55.124Z,1557204475.124 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-07T04:47:55.125Z,1557204475.125 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-07T04:47:55.205Z,1557204475.205 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-07T04:47:55.308Z,1557204475.308 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-07T04:47:55.309Z,1557204475.309 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-07T04:47:55.886Z,1557204475.886 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-07T04:47:55.886Z,1557204475.886 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-07T04:47:56.280Z,1557204476.280 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-07T04:47:56.281Z,1557204476.281 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-07T04:47:56.282Z,1557204476.282 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-07T04:47:56.544Z,1557204476.544 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-07T04:47:56.811Z,1557204476.811 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-07T04:47:56.913Z,1557204476.913 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-07T04:47:57.260Z,1557204477.260 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-07T04:47:57.261Z,1557204477.261 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-07T04:47:57.345Z,1557204477.345 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-07T04:47:57.439Z,1557204477.439 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-07T04:47:57.535Z,1557204477.535 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-07T04:47:57.617Z,1557204477.617 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-07T04:47:57.725Z,1557204477.725 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-07T04:47:57.896Z,1557204477.896 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-07T04:47:58.028Z,1557204478.028 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-07T04:47:58.028Z,1557204478.028 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-07T04:47:58.041Z,1557204478.041 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-07T04:47:58.417Z,1557204478.417 [AHRS_M2] Loaded
2019-05-07T04:47:58.417Z,1557204478.417 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-07T04:47:58.490Z,1557204478.490 [DataOverHttps] Loaded
2019-05-07T04:47:58.490Z,1557204478.490 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-07T04:47:58.491Z,1557204478.491 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-07T04:47:58.492Z,1557204478.492 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2064
2019-05-07T04:47:58.505Z,1557204478.505 [Depth_Keller] Loaded
2019-05-07T04:47:58.505Z,1557204478.505 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-07T04:47:58.510Z,1557204478.510 [DropWeight] Loaded
2019-05-07T04:47:58.510Z,1557204478.510 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-07T04:47:58.565Z,1557204478.565 [DUSBL_Hydroid] Loaded
2019-05-07T04:47:58.566Z,1557204478.566 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-07T04:47:58.605Z,1557204478.605 [Micromodem] Loaded
2019-05-07T04:47:58.605Z,1557204478.605 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-07T04:47:58.701Z,1557204478.701 [NAL9602] Loaded
2019-05-07T04:47:58.702Z,1557204478.702 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-07T04:47:58.717Z,1557204478.717 [Onboard] Loaded
2019-05-07T04:47:58.717Z,1557204478.717 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-07T04:47:58.723Z,1557204478.723 [PowerOnly] Loaded
2019-05-07T04:47:58.723Z,1557204478.723 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-07T04:47:58.730Z,1557204478.730 [Radio_Surface] Loaded
2019-05-07T04:47:58.730Z,1557204478.730 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-07T04:47:58.731Z,1557204478.731 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-07T04:47:58.731Z,1557204478.731 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2065
2019-05-07T04:47:58.775Z,1557204478.775 [RDI_Pathfinder] Loaded
2019-05-07T04:47:58.775Z,1557204478.775 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-07T04:48:00.247Z,1557204480.247 [BPC1] Loaded
2019-05-07T04:48:00.247Z,1557204480.247 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-07T04:48:00.248Z,1557204480.248 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-07T04:48:00.248Z,1557204480.248 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-07T04:48:00.261Z,1557204480.261 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-07T04:48:00.261Z,1557204480.261 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-07T04:48:00.365Z,1557204480.365 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-07T04:48:00.365Z,1557204480.365 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-07T04:48:00.385Z,1557204480.385 [NavChart] Loaded
2019-05-07T04:48:00.386Z,1557204480.386 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-07T04:48:00.390Z,1557204480.390 [UniversalFixResidualReporter] Loaded
2019-05-07T04:48:00.390Z,1557204480.390 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-07T04:48:00.390Z,1557204480.390 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-07T04:48:00.391Z,1557204480.391 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-07T04:48:00.497Z,1557204480.497 [BuoyancyServo] Loaded
2019-05-07T04:48:00.498Z,1557204480.498 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-07T04:48:00.513Z,1557204480.513 [ElevatorServo] Loaded
2019-05-07T04:48:00.513Z,1557204480.513 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-07T04:48:00.528Z,1557204480.528 [MassServo] Loaded
2019-05-07T04:48:00.528Z,1557204480.528 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-07T04:48:00.543Z,1557204480.543 [RudderServo] Loaded
2019-05-07T04:48:00.543Z,1557204480.543 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-07T04:48:00.557Z,1557204480.557 [ThrusterServo] Loaded
2019-05-07T04:48:00.558Z,1557204480.558 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-07T04:48:00.558Z,1557204480.558 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-07T04:48:00.559Z,1557204480.559 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-07T04:48:00.801Z,1557204480.801 [CTD_NeilBrown] Loaded
2019-05-07T04:48:00.801Z,1557204480.801 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-07T04:48:00.802Z,1557204480.802 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-07T04:48:00.803Z,1557204480.803 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2066
2019-05-07T04:48:00.846Z,1557204480.846 [WetLabsSeaOWL_UV_A] Loaded
2019-05-07T04:48:00.847Z,1557204480.847 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-07T04:48:00.848Z,1557204480.848 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-07T04:48:00.848Z,1557204480.848 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 2067
2019-05-07T04:48:00.849Z,1557204480.849 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-07T04:48:00.849Z,1557204480.849 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-07T04:48:01.134Z,1557204481.134 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-07T04:48:01.134Z,1557204481.134 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-07T04:48:01.174Z,1557204481.174 [DepthRateCalculator] Loaded
2019-05-07T04:48:01.174Z,1557204481.174 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-07T04:48:01.179Z,1557204481.179 [PitchRateCalculator] Loaded
2019-05-07T04:48:01.180Z,1557204481.180 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-07T04:48:01.192Z,1557204481.192 [SpeedCalculator] Loaded
2019-05-07T04:48:01.192Z,1557204481.192 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-07T04:48:01.212Z,1557204481.212 [TempGradientCalculator] Loaded
2019-05-07T04:48:01.213Z,1557204481.213 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-07T04:48:01.218Z,1557204481.218 [YawRateCalculator] Loaded
2019-05-07T04:48:01.219Z,1557204481.219 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-07T04:48:01.258Z,1557204481.258 [ElevatorOffsetCalculator] Loaded
2019-05-07T04:48:01.259Z,1557204481.259 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-07T04:48:01.259Z,1557204481.259 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-07T04:48:01.260Z,1557204481.260 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-07T04:48:01.393Z,1557204481.393 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-07T04:48:01.415Z,1557204481.415 [SBIT] Loaded
2019-05-07T04:48:01.415Z,1557204481.415 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-07T04:48:01.416Z,1557204481.416 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-07T04:48:01.427Z,1557204481.427 [IBIT] Loaded
2019-05-07T04:48:01.428Z,1557204481.428 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-07T04:48:01.431Z,1557204481.431 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-07T04:48:01.567Z,1557204481.567 [CBIT] Loaded
2019-05-07T04:48:01.567Z,1557204481.567 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-07T04:48:01.567Z,1557204481.567 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-07T04:48:01.568Z,1557204481.568 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-07T04:48:01.804Z,1557204481.804 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-07T04:48:01.804Z,1557204481.804 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-07T04:48:01.947Z,1557204481.947 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-07T04:48:01.948Z,1557204481.948 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-07T04:48:02.015Z,1557204482.015 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-07T04:48:02.099Z,1557204482.099 [VerticalControl] Loaded
2019-05-07T04:48:02.100Z,1557204482.100 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-07T04:48:02.100Z,1557204482.100 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-07T04:48:02.158Z,1557204482.158 [HorizontalControl] Loaded
2019-05-07T04:48:02.158Z,1557204482.158 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-07T04:48:02.159Z,1557204482.159 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-07T04:48:02.161Z,1557204482.161 [SpeedControl] Loaded
2019-05-07T04:48:02.161Z,1557204482.161 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-07T04:48:02.161Z,1557204482.161 [LoopControl](DEBUG): Construct LoopControl.
2019-05-07T04:48:02.162Z,1557204482.162 [LoopControl] Loaded
2019-05-07T04:48:02.162Z,1557204482.162 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-07T04:48:02.163Z,1557204482.163 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-07T04:48:02.163Z,1557204482.163 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-07T04:48:02.189Z,1557204482.189 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-07T04:48:02.193Z,1557204482.193 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-07T04:48:02.194Z,1557204482.194 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-07T04:48:02.200Z,1557204482.200 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-07T04:48:02.201Z,1557204482.201 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-07T04:48:02.202Z,1557204482.202 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2068
2019-05-07T04:48:02.206Z,1557204482.206 [Supervisor](INFO): Main Thread ID is 802
2019-05-07T04:48:02.206Z,1557204482.206 [Supervisor](DEBUG): Running supervisor.
2019-05-07T04:48:02.207Z,1557204482.207 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2069
2019-05-07T04:48:02.209Z,1557204482.209 [controlThread ThreadHandler](INFO): Handler Thread ID is 2070
2019-05-07T04:48:02.210Z,1557204482.210 [controlThread](DEBUG): Initializing ControlThread
2019-05-07T04:48:02.217Z,1557204482.217 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-07T04:48:02.218Z,1557204482.218 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-07T04:48:02.219Z,1557204482.219 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-07T04:48:02.219Z,1557204482.219 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-07T04:48:02.220Z,1557204482.220 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-07T04:48:02.220Z,1557204482.220 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-07T04:48:02.220Z,1557204482.220 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-07T04:48:02.221Z,1557204482.221 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-07T04:48:02.221Z,1557204482.221 [SBIT](INFO): Initialize SBIT Component.
2019-05-07T04:48:02.222Z,1557204482.222 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-07T04:48:02.222Z,1557204482.222 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-07T04:48:02.222Z,1557204482.222 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-07T04:48:02.223Z,1557204482.223 [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-07T04:48:02.225Z,1557204482.225 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-07T04:48:02.225Z,1557204482.225 [IBIT](INFO): Initialize IBIT Component.
2019-05-07T04:48:02.226Z,1557204482.226 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-07T04:48:02.227Z,1557204482.227 [logger ThreadHandler](INFO): Handler Thread ID is 2071
2019-05-07T04:48:02.238Z,1557204482.238 [CBIT](DEBUG): Initialized mux pins.
2019-05-07T04:48:02.238Z,1557204482.238 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-07T04:48:02.247Z,1557204482.247 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2072
2019-05-07T04:48:02.248Z,1557204482.248 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-07T04:48:02.259Z,1557204482.259 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2073
2019-05-07T04:48:02.262Z,1557204482.262 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-07T04:48:02.262Z,1557204482.262 [CBIT](DEBUG): Initializing heartbeat.
2019-05-07T04:48:02.279Z,1557204482.279 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2074
2019-05-07T04:48:02.279Z,1557204482.279 [CTD_NeilBrown](INFO): Powering down
2019-05-07T04:48:02.301Z,1557204482.301 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 2075
2019-05-07T04:48:02.307Z,1557204482.307 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T04:48:02.334Z,1557204482.334 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-07T04:48:02.334Z,1557204482.334 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-07T04:48:02.335Z,1557204482.335 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2076
2019-05-07T04:48:02.338Z,1557204482.338 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-07T04:48:02.338Z,1557204482.338 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-07T04:48:02.339Z,1557204482.339 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-07T04:48:02.339Z,1557204482.339 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-07T04:48:02.339Z,1557204482.339 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-07T04:48:02.339Z,1557204482.339 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-07T04:48:02.339Z,1557204482.339 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-07T04:48:02.340Z,1557204482.340 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-07T04:48:02.340Z,1557204482.340 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-07T04:48:02.340Z,1557204482.340 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-07T04:48:02.340Z,1557204482.340 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-07T04:48:02.340Z,1557204482.340 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-07T04:48:02.340Z,1557204482.340 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-07T04:48:02.341Z,1557204482.341 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-07T04:48:02.341Z,1557204482.341 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-07T04:48:02.341Z,1557204482.341 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-07T04:48:02.370Z,1557204482.370 [CBIT](DEBUG): Backplane powered.
2019-05-07T04:48:02.371Z,1557204482.371 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-07T04:48:02.372Z,1557204482.372 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-07T04:48:02.373Z,1557204482.373 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-07T04:48:02.373Z,1557204482.373 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-07T04:48:02.374Z,1557204482.374 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-07T04:48:02.384Z,1557204482.384 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T04:48:02.407Z,1557204482.407 [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-07T04:48:02.407Z,1557204482.407 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-07T04:48:02.465Z,1557204482.465 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-07T04:48:02.483Z,1557204482.483 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-07T04:48:02.485Z,1557204482.485 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T04:48:02.504Z,1557204482.504 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-07T04:48:02.526Z,1557204482.526 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-07T04:48:02.532Z,1557204482.532 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-07T04:48:02.551Z,1557204482.551 [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-07T04:48:02.555Z,1557204482.555 [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-07T04:48:02.574Z,1557204482.574 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-07T04:48:02.618Z,1557204482.618 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-07T04:48:02.627Z,1557204482.627 [DUSBL_Hydroid](INFO): Powering up
2019-05-07T04:48:02.627Z,1557204482.627 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-07T04:48:02.662Z,1557204482.662 [Radio_Surface](INFO): Powering up
2019-05-07T04:48:02.707Z,1557204482.707 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T04:48:02.724Z,1557204482.724 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:48:02.739Z,1557204482.739 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-07T04:48:02.740Z,1557204482.740 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:48:02.747Z,1557204482.747 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-07T04:48:02.748Z,1557204482.748 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:48:02.759Z,1557204482.759 [MassServo](DEBUG): Initializing MassServo.
2019-05-07T04:48:02.759Z,1557204482.759 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:48:02.771Z,1557204482.771 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T04:48:02.771Z,1557204482.771 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:48:02.779Z,1557204482.779 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-07T04:48:02.980Z,1557204482.980 [Micromodem](INFO): Powering up
2019-05-07T04:48:02.981Z,1557204482.981 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-07T04:48:03.015Z,1557204483.015 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T04:48:03.698Z,1557204483.698 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-07T04:48:03.698Z,1557204483.698 [RudderServo](FAULT): Rudder failed to initialize
2019-05-07T04:48:03.699Z,1557204483.699 [RudderServo] Communications Fault, FailCount= 1
2019-05-07T04:48:03.699Z,1557204483.699 [RudderServo](ERROR): Communications Fault
2019-05-07T04:48:03.810Z,1557204483.810 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-07T04:48:03.983Z,1557204483.983 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T04:48:03.983Z,1557204483.983 [RudderServo](INFO): Powering down
2019-05-07T04:48:04.654Z,1557204484.654 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:48:04.775Z,1557204484.775 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T04:48:04.779Z,1557204484.779 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-07T04:48:04.780Z,1557204484.780 [RudderServo] No Fault, FailCount= 1
2019-05-07T04:48:16.003Z,1557204496.003 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T04:48:20.841Z,1557204500.841 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-07T04:48:28.905Z,1557204508.905 [NAL9602](INFO): Powering up NAL9602
2019-05-07T04:48:33.367Z,1557204513.367 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T04:48:33.367Z,1557204513.367 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050621561701,35.0, -0.1,   0.0,1448.RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T04:48:35.368Z,1557204515.368 [Micromodem](ERROR): Response from modem unexpected: $CADQF,192,1*5A

2019-05-07T04:48:35.773Z,1557204515.773 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T04:48:36.180Z,1557204516.180 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507044834.254316,05,179,16,0110,0150,246,00,00,01,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,192,0.05,-999,9760,4000*54

2019-05-07T04:48:39.825Z,1557204519.825 [NAL9602](INFO): NAL9602 initialized
2019-05-07T04:48:40.638Z,1557204520.638 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:48:46.747Z,1557204526.747 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-07T04:48:46.755Z,1557204526.755 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-07T04:48:57.459Z,1557204537.459 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.022355
CHAN A1 (24V): -0.026554
CHAN A2 (12V): -0.006652
CHAN A3 (5V): -0.001915
CHAN B0 (3.3V): -0.000154
CHAN B1 (3.15aV): 0.000387
CHAN B2 (3.15bV): 0.000108
CHAN B3 (GND): 0.002113
OPEN: 0.006669
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-07T04:49:00.615Z,1557204540.615 [NAL9602](INFO): SBD MO Status=2, MOMSN=3828, MT Status=2, MTMSN=0
2019-05-07T04:49:00.615Z,1557204540.615 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T04:49:16.608Z,1557204556.608 [NAL9602](INFO): SBD MO Status=2, MOMSN=3828, MT Status=2, MTMSN=0
2019-05-07T04:49:16.608Z,1557204556.608 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T04:49:36.890Z,1557204576.890 [NAL9602](INFO): SBD MO Status=2, MOMSN=3828, MT Status=2, MTMSN=0
2019-05-07T04:49:36.890Z,1557204576.890 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T04:49:40.564Z,1557204580.564 [SBIT](IMPORTANT): SBIT PASSED
2019-05-07T04:49:40.664Z,1557204580.664 [CommandLine](IMPORTANT): got command configSet list
2019-05-07T04:49:40.664Z,1557204580.664 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-07T04:49:40.665Z,1557204580.665 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-07T04:49:40.665Z,1557204580.665 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-07T04:49:40.665Z,1557204580.665 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-07T04:49:40.665Z,1557204580.665 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-07T04:49:40.665Z,1557204580.665 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-07T04:49:40.665Z,1557204580.665 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-07T04:49:40.666Z,1557204580.666 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-07T04:49:40.666Z,1557204580.666 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-07T04:49:40.666Z,1557204580.666 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-07T04:49:40.666Z,1557204580.666 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-07T04:49:40.666Z,1557204580.666 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-07T04:49:40.666Z,1557204580.666 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-07T04:49:40.666Z,1557204580.666 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-07T04:49:40.955Z,1557204580.955 [MissionManager](IMPORTANT): Started mission Startup
2019-05-07T04:49:40.956Z,1557204580.956 [Startup] Running Loop=1
2019-05-07T04:49:40.956Z,1557204580.956 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-07T04:49:40.956Z,1557204580.956 [Startup:A.GoToSurface] Running Loop=1
2019-05-07T04:49:40.956Z,1557204580.956 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T04:49:40.957Z,1557204580.957 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T04:49:40.957Z,1557204580.957 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T04:49:40.957Z,1557204580.957 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T04:49:40.958Z,1557204580.958 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T04:49:40.958Z,1557204580.958 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T04:49:40.972Z,1557204580.972 [Startup:StartupSatComms] Running Loop=1
2019-05-07T04:49:40.972Z,1557204580.972 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-07T04:49:40.972Z,1557204580.972 [Startup:StartupSatComms:A] Running Loop=1
2019-05-07T04:49:41.372Z,1557204581.372 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-07T04:49:44.162Z,1557204584.162 [NAL9602](INFO): SBD MO Status=0, MOMSN=3828, MT Status=0, MTMSN=0
2019-05-07T04:49:44.162Z,1557204584.162 [NAL9602](INFO): No messages in MT queue
2019-05-07T04:49:44.982Z,1557204584.982 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:49:47.807Z,1557204587.807 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:49:51.042Z,1557204591.042 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:49:53.878Z,1557204593.878 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:49:57.102Z,1557204597.102 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:49:59.942Z,1557204599.942 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:03.158Z,1557204603.158 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:05.986Z,1557204605.986 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:09.222Z,1557204609.222 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:12.046Z,1557204612.046 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:15.278Z,1557204615.278 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:18.106Z,1557204618.106 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:20.938Z,1557204620.938 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:24.166Z,1557204624.166 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:26.998Z,1557204626.998 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:29.592Z,1557204629.592 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004434
2019-05-07T04:50:30.234Z,1557204630.234 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:50:30.623Z,1557204630.623 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,044903.00,A,3648.16207,N,12147.28374,W,0.156,0.00,070519,,,A*7E
2019-05-07T04:50:30.627Z,1557204630.627 [NAL9602](INFO): GPS fix at 20190507T044903: (36.802701, -121.788062)
2019-05-07T04:50:30.667Z,1557204630.667 [Startup:StartupSatComms:A] Stopped
2019-05-07T04:50:30.667Z,1557204630.667 [Startup:StartupSatComms:B] Running Loop=1
2019-05-07T04:50:31.087Z,1557204631.087 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T04:50:40.318Z,1557204640.318 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20190507T043926/Courier0007.lzma
2019-05-07T04:50:41.124Z,1557204641.124 [DataOverHttps](INFO): Moved sent file to Logs/20190507T043926/Courier0007.lzma.bak
2019-05-07T04:50:41.124Z,1557204641.124 [DataOverHttps](INFO): SBD MOMSN=10950035
2019-05-07T04:50:53.231Z,1557204653.231 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-05-07T04:50:53.434Z,1557204653.434 [Startup:StartupSatComms:B] Stopped
2019-05-07T04:50:53.434Z,1557204653.434 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-07T04:50:53.434Z,1557204653.434 [Startup:StartupSatComms] Stopped
2019-05-07T04:50:53.442Z,1557204653.442 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-07T04:50:53.443Z,1557204653.443 [Startup](INFO): Completed Startup
2019-05-07T04:50:53.443Z,1557204653.443 [MissionManager](INFO): Startup is completed.
2019-05-07T04:50:53.443Z,1557204653.443 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-07T04:50:53.443Z,1557204653.443 [Startup] Stopped
2019-05-07T04:50:53.444Z,1557204653.444 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-07T04:50:53.444Z,1557204653.444 [Startup:A.GoToSurface] Stopped
2019-05-07T04:50:53.444Z,1557204653.444 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T04:50:53.806Z,1557204653.806 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T04:50:53.810Z,1557204653.810 [Default] Running Loop=1
2019-05-07T04:50:53.810Z,1557204653.810 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T04:50:53.811Z,1557204653.811 [Default:B.GoToSurface] Running Loop=1
2019-05-07T04:50:53.811Z,1557204653.811 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T04:50:53.811Z,1557204653.811 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T04:50:53.811Z,1557204653.811 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T04:50:53.812Z,1557204653.812 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T04:50:53.812Z,1557204653.812 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T04:50:53.812Z,1557204653.812 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T04:50:53.812Z,1557204653.812 [Default:A.Wait] Running Loop=1
2019-05-07T04:50:53.813Z,1557204653.813 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:50:55.462Z,1557204655.462 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190507T044752/Courier0000.lzma
2019-05-07T04:50:56.268Z,1557204656.268 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Courier0000.lzma.bak
2019-05-07T04:50:56.268Z,1557204656.268 [DataOverHttps](INFO): SBD MOMSN=10950037
2019-05-07T04:51:03.060Z,1557204663.060 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T04:51:07.182Z,1557204667.182 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T04:51:07.182Z,1557204667.182 [Default:A.Wait] Stopped
2019-05-07T04:51:07.186Z,1557204667.186 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:51:07.603Z,1557204667.603 [Default:CheckIn] Running Loop=1
2019-05-07T04:51:07.603Z,1557204667.603 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T04:51:07.603Z,1557204667.603 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T04:51:08.014Z,1557204668.014 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-07T04:51:09.130Z,1557204669.130 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:51:09.526Z,1557204669.526 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,044942.00,A,3648.16058,N,12147.28437,W,0.428,0.00,070519,,,A*7F
2019-05-07T04:51:09.528Z,1557204669.528 [NAL9602](INFO): GPS fix at 20190507T044942: (36.802676, -121.788073)
2019-05-07T04:51:09.552Z,1557204669.552 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T04:51:09.552Z,1557204669.552 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T04:51:09.975Z,1557204669.975 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T04:51:10.072Z,1557204670.072 [CommandLine](IMPORTANT): got command show variable range
2019-05-07T04:51:10.075Z,1557204670.075 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-07T04:51:10.299Z,1557204670.299 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-07T04:51:10.299Z,1557204670.299 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-07T04:51:10.383Z,1557204670.383 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-07T04:51:10.384Z,1557204670.384 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-07T04:51:10.384Z,1557204670.384 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-07T04:51:10.387Z,1557204670.387 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-07T04:51:10.388Z,1557204670.388 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-07T04:51:10.388Z,1557204670.388 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-07T04:51:10.388Z,1557204670.388 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-07T04:51:15.890Z,1557204675.890 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190507T044752/Courier0004.lzma
2019-05-07T04:51:16.696Z,1557204676.696 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Courier0004.lzma.bak
2019-05-07T04:51:16.696Z,1557204676.696 [DataOverHttps](INFO): SBD MOMSN=10950042
2019-05-07T04:51:23.544Z,1557204683.544 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-07T04:51:29.216Z,1557204689.216 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T04:51:29.216Z,1557204689.216 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T04:51:29.786Z,1557204689.786 [DataOverHttps](INFO): Sending 395 bytes from file Logs/20190507T043926/Express0008.lzma
2019-05-07T04:51:30.592Z,1557204690.592 [DataOverHttps](INFO): Moved sent file to Logs/20190507T043926/Express0008.lzma.bak
2019-05-07T04:51:30.592Z,1557204690.592 [DataOverHttps](INFO): SBD MOMSN=10950045
2019-05-07T04:51:32.907Z,1557204692.907 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:51:32.907Z,1557204692.907 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:51:32.999Z,1557204692.999 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T04:51:33.019Z,1557204693.019 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T04:51:33.056Z,1557204693.056 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T04:51:33.084Z,1557204693.084 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T04:51:33.096Z,1557204693.096 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T04:51:33.106Z,1557204693.106 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T04:51:33.133Z,1557204693.133 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T04:51:33.165Z,1557204693.165 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T04:51:33.252Z,1557204693.252 [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-07T04:51:33.266Z,1557204693.266 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:51:33.307Z,1557204693.307 [Default] Stopped
2019-05-07T04:51:33.307Z,1557204693.307 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T04:51:33.307Z,1557204693.307 [Default:B.GoToSurface] Stopped
2019-05-07T04:51:33.307Z,1557204693.307 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T04:51:33.307Z,1557204693.307 [Default:CheckIn] Stopped
2019-05-07T04:51:33.307Z,1557204693.307 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:51:33.307Z,1557204693.307 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T04:51:33.307Z,1557204693.307 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T04:51:33.308Z,1557204693.308 [DUSBL] Running Loop=1
2019-05-07T04:51:33.308Z,1557204693.308 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T04:51:33.308Z,1557204693.308 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:51:33.308Z,1557204693.308 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T04:51:33.308Z,1557204693.308 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:51:33.308Z,1557204693.308 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T04:51:33.308Z,1557204693.308 [DUSBL:C] Running Loop=1
2019-05-07T04:51:33.309Z,1557204693.309 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T04:51:33.309Z,1557204693.309 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:51:33.309Z,1557204693.309 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:51:33.309Z,1557204693.309 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:51:33.309Z,1557204693.309 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:51:33.309Z,1557204693.309 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:51:33.309Z,1557204693.309 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:51:33.310Z,1557204693.310 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:51:33.319Z,1557204693.319 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T04:51:33.319Z,1557204693.319 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T04:51:33.319Z,1557204693.319 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:51:33.320Z,1557204693.320 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:51:34.883Z,1557204694.883 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:51:34.883Z,1557204694.883 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:51:34.884Z,1557204694.884 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:51:35.264Z,1557204695.264 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:51:35.265Z,1557204695.265 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:51:36.062Z,1557204696.062 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:51:36.063Z,1557204696.063 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:51:40.923Z,1557204700.923 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.038696
2019-05-07T04:51:40.923Z,1557204700.923 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:51:40.923Z,1557204700.923 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:51:40.923Z,1557204700.923 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:51:41.315Z,1557204701.315 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:51:41.316Z,1557204701.316 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:51:42.120Z,1557204702.120 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:51:42.120Z,1557204702.120 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:51:43.368Z,1557204703.368 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:51:43.368Z,1557204703.368 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:51:43.368Z,1557204703.368 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:51:43.369Z,1557204703.369 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:51:43.369Z,1557204703.369 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:51:43.369Z,1557204703.369 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:51:43.369Z,1557204703.369 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:51:43.369Z,1557204703.369 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:51:43.370Z,1557204703.370 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T04:51:43.370Z,1557204703.370 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T04:51:43.370Z,1557204703.370 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:51:43.370Z,1557204703.370 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:51:43.370Z,1557204703.370 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:51:43.370Z,1557204703.370 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:51:43.374Z,1557204703.374 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:51:44.057Z,1557204704.057 [DataOverHttps](INFO): Sending 1383 bytes from file Logs/20190507T044752/Express0001.lzma
2019-05-07T04:51:44.860Z,1557204704.860 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Express0001.lzma.bak
2019-05-07T04:51:44.860Z,1557204704.860 [DataOverHttps](INFO): SBD MOMSN=10950048
2019-05-07T04:51:46.982Z,1557204706.982 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058872
2019-05-07T04:51:46.983Z,1557204706.983 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:51:46.983Z,1557204706.983 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:51:46.984Z,1557204706.984 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:51:47.375Z,1557204707.375 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:51:47.376Z,1557204707.376 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:51:48.587Z,1557204708.587 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:51:48.588Z,1557204708.588 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:51:53.043Z,1557204713.043 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059001
2019-05-07T04:51:53.043Z,1557204713.043 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:51:53.043Z,1557204713.043 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:51:53.044Z,1557204713.044 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:51:53.435Z,1557204713.435 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:51:53.437Z,1557204713.437 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:51:53.925Z,1557204713.925 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:51:53.925Z,1557204713.925 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:51:53.925Z,1557204713.925 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:51:53.926Z,1557204713.926 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:51:53.926Z,1557204713.926 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:51:53.926Z,1557204713.926 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:51:53.926Z,1557204713.926 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:51:53.926Z,1557204713.926 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:51:53.934Z,1557204713.934 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T04:51:53.935Z,1557204713.935 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T04:51:53.935Z,1557204713.935 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:51:53.935Z,1557204713.935 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:51:53.935Z,1557204713.935 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:51:53.935Z,1557204713.935 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:51:53.935Z,1557204713.935 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:51:54.240Z,1557204714.240 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:51:54.240Z,1557204714.240 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:51:59.102Z,1557204719.102 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058539
2019-05-07T04:51:59.103Z,1557204719.103 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:51:59.103Z,1557204719.103 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:51:59.104Z,1557204719.104 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:51:59.495Z,1557204719.495 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:51:59.496Z,1557204719.496 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:00.300Z,1557204720.300 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:00.300Z,1557204720.300 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:04.369Z,1557204724.369 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:52:04.370Z,1557204724.370 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:52:04.370Z,1557204724.370 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:52:04.374Z,1557204724.374 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:52:04.374Z,1557204724.374 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:52:04.375Z,1557204724.375 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:52:05.158Z,1557204725.158 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054921
2019-05-07T04:52:05.159Z,1557204725.159 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:05.159Z,1557204725.159 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:05.160Z,1557204725.160 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:05.552Z,1557204725.552 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:05.553Z,1557204725.553 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:06.360Z,1557204726.360 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:06.360Z,1557204726.360 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:11.218Z,1557204731.218 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058678
2019-05-07T04:52:11.218Z,1557204731.218 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:11.219Z,1557204731.219 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:11.219Z,1557204731.219 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:11.615Z,1557204731.615 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:11.616Z,1557204731.616 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:12.428Z,1557204732.428 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:12.428Z,1557204732.428 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:15.099Z,1557204735.099 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:52:15.099Z,1557204735.099 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:52:15.099Z,1557204735.099 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:52:15.100Z,1557204735.100 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:52:15.100Z,1557204735.100 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:52:15.100Z,1557204735.100 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:52:15.101Z,1557204735.101 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:52:17.278Z,1557204737.278 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059030
2019-05-07T04:52:17.279Z,1557204737.279 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:17.279Z,1557204737.279 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:17.279Z,1557204737.279 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:17.671Z,1557204737.671 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:17.673Z,1557204737.673 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:18.077Z,1557204738.077 [Micromodem](ERROR): Response from modem unexpected: $CADQF,190,1*58

2019-05-07T04:52:18.078Z,1557204738.078 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T04:52:18.479Z,1557204738.479 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:18.480Z,1557204738.480 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:18.496Z,1557204738.496 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507045215.908411,06,421,14,0106,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,190,-0.05,-999,9760,4000*7F

2019-05-07T04:52:23.338Z,1557204743.338 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058936
2019-05-07T04:52:23.338Z,1557204743.338 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:23.339Z,1557204743.339 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:23.340Z,1557204743.340 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:23.739Z,1557204743.739 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:23.740Z,1557204743.740 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:24.540Z,1557204744.540 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:24.540Z,1557204744.540 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:25.381Z,1557204745.381 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:52:25.381Z,1557204745.381 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:52:25.381Z,1557204745.381 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:52:25.382Z,1557204745.382 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:52:25.382Z,1557204745.382 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:52:25.382Z,1557204745.382 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:52:25.382Z,1557204745.382 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:52:25.382Z,1557204745.382 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:52:25.383Z,1557204745.383 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T04:52:25.383Z,1557204745.383 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T04:52:25.383Z,1557204745.383 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:52:25.383Z,1557204745.383 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:52:25.383Z,1557204745.383 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:52:25.383Z,1557204745.383 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:52:25.383Z,1557204745.383 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:52:29.402Z,1557204749.402 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062861
2019-05-07T04:52:29.402Z,1557204749.402 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:29.403Z,1557204749.403 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:29.403Z,1557204749.403 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:29.795Z,1557204749.795 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:29.796Z,1557204749.796 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:30.600Z,1557204750.600 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:30.600Z,1557204750.600 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:35.458Z,1557204755.458 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.055146
2019-05-07T04:52:35.459Z,1557204755.459 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:35.459Z,1557204755.459 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:35.460Z,1557204755.460 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:35.855Z,1557204755.855 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:35.858Z,1557204755.858 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:35.989Z,1557204755.989 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:52:35.989Z,1557204755.989 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:52:35.989Z,1557204755.989 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:52:35.990Z,1557204755.990 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:52:35.990Z,1557204755.990 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:52:35.990Z,1557204755.990 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:52:35.995Z,1557204755.995 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:52:35.995Z,1557204755.995 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:52:35.995Z,1557204755.995 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T04:52:35.995Z,1557204755.995 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T04:52:35.995Z,1557204755.995 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:52:35.996Z,1557204755.996 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:52:35.996Z,1557204755.996 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:52:35.996Z,1557204755.996 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:52:35.996Z,1557204755.996 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:52:36.668Z,1557204756.668 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:36.668Z,1557204756.668 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:41.521Z,1557204761.521 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058761
2019-05-07T04:52:41.521Z,1557204761.521 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:41.521Z,1557204761.521 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:41.522Z,1557204761.522 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:41.924Z,1557204761.924 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:41.925Z,1557204761.925 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:42.723Z,1557204762.723 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:42.724Z,1557204762.724 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:46.406Z,1557204766.406 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:52:46.406Z,1557204766.406 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:52:46.406Z,1557204766.406 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:52:46.407Z,1557204766.407 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:52:46.407Z,1557204766.407 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:52:46.407Z,1557204766.407 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:52:46.407Z,1557204766.407 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:52:46.407Z,1557204766.407 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:52:46.407Z,1557204766.407 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T04:52:46.407Z,1557204766.407 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T04:52:46.408Z,1557204766.408 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:52:46.408Z,1557204766.408 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:52:46.408Z,1557204766.408 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:52:46.408Z,1557204766.408 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:52:46.408Z,1557204766.408 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:52:47.582Z,1557204767.582 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.060266
2019-05-07T04:52:47.582Z,1557204767.582 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:47.583Z,1557204767.583 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:47.583Z,1557204767.583 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:47.979Z,1557204767.979 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:47.980Z,1557204767.980 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:48.784Z,1557204768.784 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:48.785Z,1557204768.785 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:53.639Z,1557204773.639 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.055292
2019-05-07T04:52:53.639Z,1557204773.639 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:53.639Z,1557204773.639 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:53.640Z,1557204773.640 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:52:54.031Z,1557204774.031 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:52:54.032Z,1557204774.032 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:52:54.852Z,1557204774.852 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:52:54.852Z,1557204774.852 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:52:56.912Z,1557204776.912 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:52:56.912Z,1557204776.912 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:52:56.912Z,1557204776.912 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:52:56.912Z,1557204776.912 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:52:56.912Z,1557204776.912 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:52:56.913Z,1557204776.913 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:52:59.706Z,1557204779.706 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.066657
2019-05-07T04:52:59.706Z,1557204779.706 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:52:59.707Z,1557204779.707 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:52:59.713Z,1557204779.713 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:05.762Z,1557204785.762 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.049554
2019-05-07T04:53:05.763Z,1557204785.763 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:05.763Z,1557204785.763 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:05.768Z,1557204785.768 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:07.506Z,1557204787.506 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:53:07.506Z,1557204787.506 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:53:07.506Z,1557204787.506 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:53:07.507Z,1557204787.507 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:53:07.507Z,1557204787.507 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:53:07.507Z,1557204787.507 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:53:07.507Z,1557204787.507 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:53:07.507Z,1557204787.507 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:53:07.508Z,1557204787.508 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-07T04:53:07.508Z,1557204787.508 [DUSBL:RequestRepeater] Running Loop=10
2019-05-07T04:53:07.508Z,1557204787.508 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:53:07.508Z,1557204787.508 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:53:07.508Z,1557204787.508 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:53:07.508Z,1557204787.508 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:53:07.508Z,1557204787.508 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:53:11.818Z,1557204791.818 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.049827
2019-05-07T04:53:11.818Z,1557204791.818 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:11.819Z,1557204791.819 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:11.819Z,1557204791.819 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:12.215Z,1557204792.215 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:53:12.216Z,1557204792.216 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:53:12.619Z,1557204792.619 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CADQ,24,1*56

2019-05-07T04:53:13.021Z,1557204793.021 [Micromodem](ERROR): Response from modem failed NMEA checksum: CASG,BAD_CRC,0*21

2019-05-07T04:53:17.883Z,1557204797.883 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.063147
2019-05-07T04:53:17.884Z,1557204797.884 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:17.884Z,1557204797.884 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:17.885Z,1557204797.885 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:17.980Z,1557204797.980 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:53:17.980Z,1557204797.980 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:53:17.980Z,1557204797.980 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:53:17.981Z,1557204797.981 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:53:17.981Z,1557204797.981 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:53:17.981Z,1557204797.981 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:53:17.981Z,1557204797.981 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:53:17.981Z,1557204797.981 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:53:17.981Z,1557204797.981 [DUSBL](INFO): Completed DUSBL
2019-05-07T04:53:17.982Z,1557204797.982 [MissionManager](INFO): DUSBL is completed.
2019-05-07T04:53:17.982Z,1557204797.982 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T04:53:17.982Z,1557204797.982 [DUSBL] Stopped
2019-05-07T04:53:17.982Z,1557204797.982 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T04:53:17.986Z,1557204797.986 [DUSBL:A.Pitch] Stopped
2019-05-07T04:53:17.986Z,1557204797.986 [DUSBL:B.SetSpeed] Stopped
2019-05-07T04:53:17.986Z,1557204797.986 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T04:53:17.987Z,1557204797.987 [DUSBL:C] Stopped
2019-05-07T04:53:18.325Z,1557204798.325 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T04:53:18.325Z,1557204798.325 [Default] Running Loop=1
2019-05-07T04:53:18.325Z,1557204798.325 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T04:53:18.325Z,1557204798.325 [Default:B.GoToSurface] Running Loop=1
2019-05-07T04:53:18.325Z,1557204798.325 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T04:53:18.326Z,1557204798.326 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T04:53:18.326Z,1557204798.326 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T04:53:18.327Z,1557204798.327 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T04:53:18.327Z,1557204798.327 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T04:53:18.327Z,1557204798.327 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T04:53:18.328Z,1557204798.328 [Default:A.Wait] Running Loop=1
2019-05-07T04:53:18.328Z,1557204798.328 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:53:30.903Z,1557204810.903 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:53:30.904Z,1557204810.904 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:53:30.949Z,1557204810.949 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T04:53:30.956Z,1557204810.956 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T04:53:30.958Z,1557204810.958 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T04:53:30.964Z,1557204810.964 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T04:53:30.970Z,1557204810.970 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T04:53:30.971Z,1557204810.971 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T04:53:30.980Z,1557204810.980 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T04:53:30.993Z,1557204810.993 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T04:53:31.009Z,1557204811.009 [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-07T04:53:31.011Z,1557204811.011 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:53:31.257Z,1557204811.257 [Default] Stopped
2019-05-07T04:53:31.257Z,1557204811.257 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T04:53:31.257Z,1557204811.257 [Default:A.Wait] Stopped
2019-05-07T04:53:31.257Z,1557204811.257 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:53:31.257Z,1557204811.257 [Default:B.GoToSurface] Stopped
2019-05-07T04:53:31.257Z,1557204811.257 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T04:53:31.257Z,1557204811.257 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T04:53:31.258Z,1557204811.258 [DUSBL] Running Loop=1
2019-05-07T04:53:31.258Z,1557204811.258 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T04:53:31.258Z,1557204811.258 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:53:31.259Z,1557204811.259 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T04:53:31.259Z,1557204811.259 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:53:31.259Z,1557204811.259 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T04:53:31.259Z,1557204811.259 [DUSBL:C] Running Loop=1
2019-05-07T04:53:31.259Z,1557204811.259 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T04:53:31.259Z,1557204811.259 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:53:31.260Z,1557204811.260 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:53:31.260Z,1557204811.260 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:53:31.260Z,1557204811.260 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:53:31.260Z,1557204811.260 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:53:31.260Z,1557204811.260 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:53:31.260Z,1557204811.260 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:53:31.261Z,1557204811.261 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T04:53:31.262Z,1557204811.262 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T04:53:31.262Z,1557204811.262 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:53:31.262Z,1557204811.262 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:53:32.843Z,1557204812.843 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:14.957206
2019-05-07T04:53:32.844Z,1557204812.844 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:32.844Z,1557204812.844 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:32.845Z,1557204812.845 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:33.223Z,1557204813.223 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:53:33.225Z,1557204813.225 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:53:34.032Z,1557204814.032 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:53:34.032Z,1557204814.032 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:53:38.886Z,1557204818.886 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.041077
2019-05-07T04:53:38.886Z,1557204818.886 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:38.887Z,1557204818.887 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:38.887Z,1557204818.887 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:39.285Z,1557204819.285 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:53:39.288Z,1557204819.288 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:53:39.695Z,1557204819.695 [Micromodem](ERROR): Response from modem unexpected: $CADQF,197,1*5F

2019-05-07T04:53:40.088Z,1557204820.088 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:53:40.088Z,1557204820.088 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:53:40.104Z,1557204820.104 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T04:53:40.111Z,1557204820.111 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190507045337.626148,06,465,14,0093,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,197,0.00,-999,70400*56
$CAREV,0538,UV2.0.2769*1C

2019-05-07T04:53:41.334Z,1557204821.334 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:53:41.334Z,1557204821.334 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:53:41.334Z,1557204821.334 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:53:41.335Z,1557204821.335 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:53:41.336Z,1557204821.336 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:53:44.950Z,1557204824.950 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062975
2019-05-07T04:53:44.950Z,1557204824.950 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:44.951Z,1557204824.951 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:44.951Z,1557204824.951 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:45.343Z,1557204825.343 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:53:45.345Z,1557204825.345 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:53:51.006Z,1557204831.006 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054900
2019-05-07T04:53:51.006Z,1557204831.006 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:51.007Z,1557204831.007 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:51.012Z,1557204831.012 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:53:51.894Z,1557204831.894 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:53:51.894Z,1557204831.894 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:53:51.894Z,1557204831.894 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:53:51.895Z,1557204831.895 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:53:51.895Z,1557204831.895 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:53:51.895Z,1557204831.895 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:53:51.895Z,1557204831.895 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:53:51.895Z,1557204831.895 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:53:51.896Z,1557204831.895 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T04:53:51.896Z,1557204831.896 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T04:53:51.896Z,1557204831.896 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:53:51.896Z,1557204831.896 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:53:51.896Z,1557204831.896 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:53:51.896Z,1557204831.896 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:53:51.896Z,1557204831.896 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:53:57.070Z,1557204837.070 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058036
2019-05-07T04:53:57.071Z,1557204837.071 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:53:57.071Z,1557204837.071 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:53:57.077Z,1557204837.077 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:02.396Z,1557204842.396 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:54:02.396Z,1557204842.396 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:54:02.396Z,1557204842.396 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:54:02.397Z,1557204842.397 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:54:02.398Z,1557204842.398 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:54:02.398Z,1557204842.398 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:54:02.398Z,1557204842.398 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:54:03.126Z,1557204843.126 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.049526
2019-05-07T04:54:03.127Z,1557204843.127 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:03.127Z,1557204843.127 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:03.127Z,1557204843.127 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:03.520Z,1557204843.520 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:03.521Z,1557204843.521 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:04.328Z,1557204844.328 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:04.328Z,1557204844.328 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:54:09.190Z,1557204849.190 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.063137
2019-05-07T04:54:09.191Z,1557204849.191 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:09.191Z,1557204849.191 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:09.191Z,1557204849.191 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:09.580Z,1557204849.580 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:09.581Z,1557204849.581 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:10.396Z,1557204850.396 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:10.396Z,1557204850.396 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:54:12.896Z,1557204852.896 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:54:12.896Z,1557204852.896 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:54:12.896Z,1557204852.896 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:54:12.897Z,1557204852.897 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:54:12.897Z,1557204852.897 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:54:12.897Z,1557204852.897 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:54:12.897Z,1557204852.897 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:54:12.897Z,1557204852.897 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:54:12.897Z,1557204852.897 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T04:54:12.898Z,1557204852.898 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T04:54:12.898Z,1557204852.898 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:54:12.898Z,1557204852.898 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:54:12.898Z,1557204852.898 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:54:12.898Z,1557204852.898 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:54:12.902Z,1557204852.902 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:54:15.246Z,1557204855.246 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054925
2019-05-07T04:54:15.246Z,1557204855.246 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:15.247Z,1557204855.247 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:15.247Z,1557204855.247 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:15.643Z,1557204855.643 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:15.645Z,1557204855.645 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:16.451Z,1557204856.451 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:16.452Z,1557204856.452 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:54:21.310Z,1557204861.310 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062942
2019-05-07T04:54:21.310Z,1557204861.310 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:21.311Z,1557204861.311 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:21.311Z,1557204861.311 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:21.703Z,1557204861.703 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:21.705Z,1557204861.705 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:23.343Z,1557204863.343 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:54:23.344Z,1557204863.344 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:54:23.344Z,1557204863.344 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:54:23.344Z,1557204863.344 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:54:23.344Z,1557204863.344 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:54:23.344Z,1557204863.344 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:54:23.344Z,1557204863.344 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:54:23.345Z,1557204863.345 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:54:27.370Z,1557204867.370 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059097
2019-05-07T04:54:27.371Z,1557204867.371 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:27.371Z,1557204867.371 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:27.375Z,1557204867.375 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:27.758Z,1557204867.758 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:27.763Z,1557204867.763 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:33.430Z,1557204873.430 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.055455
2019-05-07T04:54:33.430Z,1557204873.430 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:33.431Z,1557204873.431 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:33.431Z,1557204873.431 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:33.850Z,1557204873.850 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:33.851Z,1557204873.851 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:33.908Z,1557204873.908 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:54:33.908Z,1557204873.908 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:54:33.909Z,1557204873.909 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:54:33.909Z,1557204873.909 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:54:33.909Z,1557204873.909 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:54:33.910Z,1557204873.910 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:54:33.910Z,1557204873.910 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:54:33.910Z,1557204873.910 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:54:33.910Z,1557204873.910 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T04:54:33.911Z,1557204873.911 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T04:54:33.911Z,1557204873.911 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:54:33.911Z,1557204873.911 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:54:33.911Z,1557204873.911 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:54:33.911Z,1557204873.911 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:54:33.911Z,1557204873.911 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:54:34.635Z,1557204874.635 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:34.636Z,1557204874.636 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:54:39.486Z,1557204879.486 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054944
2019-05-07T04:54:39.486Z,1557204879.486 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:39.487Z,1557204879.487 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:39.487Z,1557204879.487 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:39.883Z,1557204879.883 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:39.885Z,1557204879.885 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:40.289Z,1557204880.289 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507045437.678254,06,394,13,0092,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,193,0.05,-999,9760,4000*5A

2019-05-07T04:54:40.695Z,1557204880.695 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:40.696Z,1557204880.696 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:54:44.356Z,1557204884.356 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:54:44.357Z,1557204884.357 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:54:44.357Z,1557204884.357 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:54:44.357Z,1557204884.357 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:54:44.357Z,1557204884.357 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:54:44.357Z,1557204884.357 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:54:44.357Z,1557204884.357 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:54:44.357Z,1557204884.357 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:54:44.358Z,1557204884.358 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T04:54:44.358Z,1557204884.358 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T04:54:44.358Z,1557204884.358 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:54:44.358Z,1557204884.358 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:54:44.358Z,1557204884.358 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:54:44.358Z,1557204884.358 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:54:44.358Z,1557204884.358 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:54:45.550Z,1557204885.550 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062987
2019-05-07T04:54:45.550Z,1557204885.550 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:45.551Z,1557204885.551 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:45.551Z,1557204885.551 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:45.940Z,1557204885.940 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:45.941Z,1557204885.941 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:46.751Z,1557204886.751 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:46.752Z,1557204886.752 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:54:51.606Z,1557204891.606 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.055075
2019-05-07T04:54:51.607Z,1557204891.607 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:51.607Z,1557204891.607 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:51.608Z,1557204891.608 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:52.003Z,1557204892.003 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:52.005Z,1557204892.005 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:52.414Z,1557204892.414 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507045449.730730,06,424,14,0090,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,201,0.00,-999,9760,4000*5D

2019-05-07T04:54:52.809Z,1557204892.809 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:52.809Z,1557204892.809 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:54:54.950Z,1557204894.950 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:54:54.950Z,1557204894.950 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:54:54.950Z,1557204894.950 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:54:54.951Z,1557204894.951 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:54:54.951Z,1557204894.951 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:54:54.951Z,1557204894.951 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:54:54.951Z,1557204894.951 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:54:54.951Z,1557204894.951 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:54:54.951Z,1557204894.951 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T04:54:54.952Z,1557204894.952 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T04:54:54.952Z,1557204894.952 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:54:54.952Z,1557204894.952 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:54:54.952Z,1557204894.952 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:54:54.952Z,1557204894.952 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:54:54.952Z,1557204894.952 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:54:57.671Z,1557204897.671 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062997
2019-05-07T04:54:57.671Z,1557204897.671 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:54:57.671Z,1557204897.671 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:54:57.672Z,1557204897.672 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:54:58.063Z,1557204898.063 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:54:58.064Z,1557204898.064 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:54:58.871Z,1557204898.871 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:54:58.872Z,1557204898.872 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:55:03.726Z,1557204903.726 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054673
2019-05-07T04:55:03.726Z,1557204903.726 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:55:03.727Z,1557204903.727 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:55:03.727Z,1557204903.727 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:55:04.120Z,1557204904.120 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:55:04.121Z,1557204904.121 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:55:04.925Z,1557204904.925 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:55:04.926Z,1557204904.926 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:55:05.765Z,1557204905.765 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:55:05.765Z,1557204905.765 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:55:05.765Z,1557204905.765 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:55:05.766Z,1557204905.766 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:55:05.766Z,1557204905.766 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:55:05.766Z,1557204905.766 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:55:05.766Z,1557204905.766 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:55:05.766Z,1557204905.766 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:55:05.767Z,1557204905.767 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-07T04:55:05.767Z,1557204905.767 [DUSBL:RequestRepeater] Running Loop=10
2019-05-07T04:55:05.767Z,1557204905.767 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:55:05.767Z,1557204905.767 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:55:05.767Z,1557204905.767 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:55:05.767Z,1557204905.767 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:55:05.767Z,1557204905.767 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:55:05.983Z,1557204905.983 [CommandLine](IMPORTANT): got command stop
2019-05-07T04:55:05.983Z,1557204905.983 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-07T04:55:05.983Z,1557204905.983 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-07T04:55:06.196Z,1557204906.196 [MissionManager](INFO): MissionManager is completed.
2019-05-07T04:55:06.197Z,1557204906.197 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:A.Pitch] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:B.SetSpeed] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:C] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:55:06.197Z,1557204906.197 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:55:06.589Z,1557204906.589 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T04:55:06.590Z,1557204906.590 [Default] Running Loop=1
2019-05-07T04:55:06.590Z,1557204906.590 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T04:55:06.590Z,1557204906.590 [Default:B.GoToSurface] Running Loop=1
2019-05-07T04:55:06.590Z,1557204906.590 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T04:55:06.590Z,1557204906.590 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T04:55:06.591Z,1557204906.591 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T04:55:06.591Z,1557204906.591 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T04:55:06.591Z,1557204906.591 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T04:55:06.592Z,1557204906.592 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T04:55:06.592Z,1557204906.592 [Default:A.Wait] Running Loop=1
2019-05-07T04:55:06.592Z,1557204906.592 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:55:19.468Z,1557204919.468 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:55:19.469Z,1557204919.469 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:55:19.559Z,1557204919.559 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T04:55:19.561Z,1557204919.561 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T04:55:19.571Z,1557204919.571 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T04:55:19.573Z,1557204919.573 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T04:55:19.580Z,1557204919.580 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T04:55:19.580Z,1557204919.580 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T04:55:19.590Z,1557204919.590 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T04:55:19.605Z,1557204919.605 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T04:55:19.626Z,1557204919.626 [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-07T04:55:19.640Z,1557204919.640 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:55:19.909Z,1557204919.909 [Default] Stopped
2019-05-07T04:55:19.910Z,1557204919.910 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T04:55:19.910Z,1557204919.910 [Default:A.Wait] Stopped
2019-05-07T04:55:19.910Z,1557204919.910 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:55:19.910Z,1557204919.910 [Default:B.GoToSurface] Stopped
2019-05-07T04:55:19.910Z,1557204919.910 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T04:55:19.910Z,1557204919.910 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T04:55:19.911Z,1557204919.911 [DUSBL] Running Loop=1
2019-05-07T04:55:19.911Z,1557204919.911 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T04:55:19.911Z,1557204919.911 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:55:19.911Z,1557204919.911 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T04:55:19.911Z,1557204919.911 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:55:19.911Z,1557204919.911 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T04:55:19.911Z,1557204919.911 [DUSBL:C] Running Loop=1
2019-05-07T04:55:19.912Z,1557204919.912 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T04:55:19.912Z,1557204919.912 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:55:19.912Z,1557204919.912 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:55:19.912Z,1557204919.912 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:55:19.912Z,1557204919.912 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:55:19.912Z,1557204919.912 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:55:19.912Z,1557204919.912 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:55:19.913Z,1557204919.913 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:55:19.913Z,1557204919.913 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T04:55:19.914Z,1557204919.914 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T04:55:19.914Z,1557204919.914 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:55:19.914Z,1557204919.914 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:55:21.506Z,1557204921.506 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:17.778969
2019-05-07T04:55:21.507Z,1557204921.507 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:55:21.507Z,1557204921.507 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:55:21.508Z,1557204921.508 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:55:21.895Z,1557204921.895 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:55:21.896Z,1557204921.896 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:55:23.108Z,1557204923.108 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:55:23.108Z,1557204923.108 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:55:27.562Z,1557204927.562 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054811
2019-05-07T04:55:27.563Z,1557204927.563 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:55:27.563Z,1557204927.563 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:55:27.563Z,1557204927.563 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:55:27.956Z,1557204927.956 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:55:27.957Z,1557204927.957 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:55:28.370Z,1557204928.370 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507045525.640095,06,351,13,0091,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,192,0.10,-999,9760,4000*53

2019-05-07T04:55:28.768Z,1557204928.768 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:55:28.768Z,1557204928.768 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:55:30.010Z,1557204930.010 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:55:30.010Z,1557204930.010 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:55:30.011Z,1557204930.011 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:55:30.011Z,1557204930.011 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:55:30.011Z,1557204930.011 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:55:30.012Z,1557204930.012 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:55:33.626Z,1557204933.626 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.063201
2019-05-07T04:55:33.627Z,1557204933.627 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:55:33.627Z,1557204933.627 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:55:33.628Z,1557204933.628 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:55:34.023Z,1557204934.023 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:55:34.024Z,1557204934.024 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:55:34.438Z,1557204934.438 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CADQF,19,1*F
$AMG,AD_RC0*1
$CACST,6,1,20190507045532.449328,06,119,14,0095,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,197,0.05,-999,9760,4000*54

2019-05-07T04:55:34.851Z,1557204934.851 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:55:34.851Z,1557204934.851 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:55:39.682Z,1557204939.682 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054925
2019-05-07T04:55:39.683Z,1557204939.683 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:55:39.683Z,1557204939.683 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:55:39.683Z,1557204939.683 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:55:40.080Z,1557204940.080 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:55:40.081Z,1557204940.081 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:55:40.534Z,1557204940.534 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:55:40.535Z,1557204940.535 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:55:40.535Z,1557204940.535 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:55:40.535Z,1557204940.535 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:55:40.535Z,1557204940.535 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:55:40.535Z,1557204940.535 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:55:40.535Z,1557204940.535 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:55:40.536Z,1557204940.536 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:55:40.884Z,1557204940.884 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:55:40.884Z,1557204940.884 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:55:42.913Z,1557204942.913 [CommandLine](IMPORTANT): got command stop
2019-05-07T04:55:42.913Z,1557204942.913 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-07T04:55:42.951Z,1557204942.951 [MissionManager](INFO): MissionManager is completed.
2019-05-07T04:55:42.951Z,1557204942.951 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL] Stopped
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL:A.Pitch] Stopped
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL:B.SetSpeed] Stopped
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL:C] Stopped
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:55:42.951Z,1557204942.951 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:55:42.952Z,1557204942.952 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:55:42.952Z,1557204942.952 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:55:42.952Z,1557204942.952 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:55:43.377Z,1557204943.377 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T04:55:43.378Z,1557204943.378 [Default] Running Loop=1
2019-05-07T04:55:43.378Z,1557204943.378 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T04:55:43.378Z,1557204943.378 [Default:B.GoToSurface] Running Loop=1
2019-05-07T04:55:43.379Z,1557204943.379 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T04:55:43.380Z,1557204943.380 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T04:55:43.380Z,1557204943.380 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T04:55:43.381Z,1557204943.381 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T04:55:43.381Z,1557204943.381 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T04:55:43.381Z,1557204943.381 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T04:55:43.382Z,1557204943.382 [Default:A.Wait] Running Loop=1
2019-05-07T04:55:43.398Z,1557204943.398 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:55:56.678Z,1557204956.678 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T04:55:56.678Z,1557204956.678 [Default:A.Wait] Stopped
2019-05-07T04:55:56.678Z,1557204956.678 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:55:57.076Z,1557204957.076 [Default:CheckIn] Running Loop=1
2019-05-07T04:55:57.077Z,1557204957.077 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T04:55:57.077Z,1557204957.077 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T04:56:11.993Z,1557204971.993 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T04:56:12.834Z,1557204972.834 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:56:17.258Z,1557204977.258 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:56:17.654Z,1557204977.654 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,045451.00,A,3648.16360,N,12147.28335,W,0.058,344.32,070519,,,A*7D
2019-05-07T04:56:17.656Z,1557204977.656 [NAL9602](INFO): GPS fix at 20190507T045451: (36.802727, -121.788056)
2019-05-07T04:56:17.684Z,1557204977.684 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T04:56:17.685Z,1557204977.685 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T04:56:20.844Z,1557204980.844 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:56:20.844Z,1557204980.844 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:56:20.906Z,1557204980.906 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T04:56:20.912Z,1557204980.912 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T04:56:20.918Z,1557204980.918 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T04:56:20.920Z,1557204980.920 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T04:56:20.926Z,1557204980.926 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T04:56:20.927Z,1557204980.927 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T04:56:20.944Z,1557204980.944 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T04:56:21.019Z,1557204981.019 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T04:56:21.035Z,1557204981.035 [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-07T04:56:21.037Z,1557204981.037 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T04:56:21.054Z,1557204981.054 [Default] Stopped
2019-05-07T04:56:21.054Z,1557204981.054 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T04:56:21.062Z,1557204981.062 [Default:B.GoToSurface] Stopped
2019-05-07T04:56:21.062Z,1557204981.062 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T04:56:21.062Z,1557204981.062 [Default:CheckIn] Stopped
2019-05-07T04:56:21.063Z,1557204981.063 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:56:21.063Z,1557204981.063 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T04:56:21.063Z,1557204981.063 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T04:56:21.063Z,1557204981.063 [DUSBL] Running Loop=1
2019-05-07T04:56:21.063Z,1557204981.063 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T04:56:21.063Z,1557204981.063 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:56:21.063Z,1557204981.063 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:C] Running Loop=1
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:56:21.064Z,1557204981.064 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:56:21.065Z,1557204981.065 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:56:21.065Z,1557204981.065 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:56:21.065Z,1557204981.065 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:56:21.066Z,1557204981.066 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T04:56:21.075Z,1557204981.075 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T04:56:21.075Z,1557204981.075 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T04:56:21.075Z,1557204981.075 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T04:56:22.598Z,1557204982.598 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:42.915195
2019-05-07T04:56:22.599Z,1557204982.599 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:56:22.599Z,1557204982.599 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:56:22.599Z,1557204982.599 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:56:22.991Z,1557204982.991 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:56:22.993Z,1557204982.993 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:56:23.758Z,1557204983.758 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T044752/Courier0007.lzma
2019-05-07T04:56:23.804Z,1557204983.804 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:56:23.804Z,1557204983.804 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:56:24.564Z,1557204984.564 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Courier0007.lzma.bak
2019-05-07T04:56:24.564Z,1557204984.564 [DataOverHttps](INFO): SBD MOMSN=10950081
2019-05-07T04:56:28.658Z,1557204988.658 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059213
2019-05-07T04:56:28.659Z,1557204988.659 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:56:28.659Z,1557204988.659 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:56:28.660Z,1557204988.660 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:56:29.051Z,1557204989.051 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:56:29.053Z,1557204989.053 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:56:29.627Z,1557204989.627 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-07T04:56:29.635Z,1557204989.635 [BPC1](INFO): Received data from all battery sticks.
2019-05-07T04:56:29.859Z,1557204989.859 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:56:29.860Z,1557204989.860 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:56:31.105Z,1557204991.105 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:56:31.105Z,1557204991.105 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:56:31.105Z,1557204991.105 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:56:31.106Z,1557204991.106 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:56:31.106Z,1557204991.106 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:56:31.106Z,1557204991.106 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:56:31.106Z,1557204991.106 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:56:31.106Z,1557204991.106 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:56:31.106Z,1557204991.106 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T04:56:31.107Z,1557204991.107 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T04:56:31.107Z,1557204991.107 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:56:31.107Z,1557204991.107 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:56:31.107Z,1557204991.107 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:56:31.107Z,1557204991.107 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:56:31.107Z,1557204991.107 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:56:34.722Z,1557204994.722 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062859
2019-05-07T04:56:34.722Z,1557204994.722 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:56:34.723Z,1557204994.723 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:56:34.723Z,1557204994.723 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:56:35.111Z,1557204995.111 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:56:35.113Z,1557204995.113 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:56:35.920Z,1557204995.920 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:56:35.920Z,1557204995.920 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:56:40.778Z,1557205000.778 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054980
2019-05-07T04:56:40.778Z,1557205000.778 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:56:40.779Z,1557205000.779 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:56:40.779Z,1557205000.779 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:56:41.177Z,1557205001.177 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:56:41.180Z,1557205001.180 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:56:41.577Z,1557205001.577 [Micromodem](ERROR): Response from modem unexpected: $CADQF,189,1*50

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

2019-05-07T04:56:41.605Z,1557205001.605 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:56:41.605Z,1557205001.605 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:56:41.605Z,1557205001.605 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:56:41.606Z,1557205001.606 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:56:41.606Z,1557205001.606 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:56:41.606Z,1557205001.606 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:56:41.606Z,1557205001.606 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:56:41.606Z,1557205001.606 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:56:41.607Z,1557205001.607 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T04:56:41.607Z,1557205001.607 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T04:56:41.607Z,1557205001.607 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:56:41.607Z,1557205001.607 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:56:41.607Z,1557205001.607 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:56:41.607Z,1557205001.607 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:56:41.607Z,1557205001.607 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:56:41.977Z,1557205001.977 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:56:41.977Z,1557205001.977 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:56:41.996Z,1557205001.996 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190507045639.522892,06,518,15,0094,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,19,0.0,-999760400*7REV,04560,U,027690*16

2019-05-07T04:56:44.857Z,1557205004.857 [RDI_Pathfinder](ERROR): Failed to parse:
68,-32768,-32768,V
2019-05-07T04:56:46.855Z,1557205006.855 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.075092
2019-05-07T04:56:46.855Z,1557205006.855 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:56:46.856Z,1557205006.856 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:56:46.857Z,1557205006.857 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:56:47.237Z,1557205007.237 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T04:56:47.239Z,1557205007.239 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T04:56:47.646Z,1557205007.646 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507045645.017754,06,156,15,0105,0150,246,00,00,01,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,192,0.00,-999,9760,4000*56

2019-05-07T04:56:48.046Z,1557205008.046 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T04:56:48.046Z,1557205008.046 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T04:56:50.064Z,1557205010.064 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T04:56:52.123Z,1557205012.123 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T04:56:52.123Z,1557205012.123 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:56:52.123Z,1557205012.123 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:56:52.124Z,1557205012.124 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T04:56:52.124Z,1557205012.124 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:56:52.124Z,1557205012.124 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:56:52.124Z,1557205012.124 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:56:52.124Z,1557205012.124 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:56:52.125Z,1557205012.125 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T04:56:52.125Z,1557205012.125 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T04:56:52.125Z,1557205012.125 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T04:56:52.125Z,1557205012.125 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T04:56:52.125Z,1557205012.125 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T04:56:52.125Z,1557205012.125 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T04:56:52.125Z,1557205012.125 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:56:52.820Z,1557205012.820 [CommandLine](IMPORTANT): got command stop
2019-05-07T04:56:52.821Z,1557205012.821 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-07T04:56:52.898Z,1557205012.898 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.041852
2019-05-07T04:56:52.899Z,1557205012.899 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T04:56:52.899Z,1557205012.899 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T04:56:52.900Z,1557205012.900 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T04:56:52.967Z,1557205012.967 [MissionManager](INFO): MissionManager is completed.
2019-05-07T04:56:52.967Z,1557205012.967 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:A.Pitch] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:B.SetSpeed] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:C] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:RequestRepeater] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T04:56:52.968Z,1557205012.968 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:56:53.321Z,1557205013.321 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T04:56:53.322Z,1557205013.322 [Default] Running Loop=1
2019-05-07T04:56:53.322Z,1557205013.322 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T04:56:53.322Z,1557205013.322 [Default:B.GoToSurface] Running Loop=1
2019-05-07T04:56:53.322Z,1557205013.322 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T04:56:53.323Z,1557205013.323 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T04:56:53.323Z,1557205013.323 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T04:56:53.323Z,1557205013.323 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T04:56:53.323Z,1557205013.323 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T04:56:53.324Z,1557205013.324 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T04:56:53.324Z,1557205013.324 [Default:A.Wait] Running Loop=1
2019-05-07T04:56:53.324Z,1557205013.324 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:57:03.862Z,1557205023.862 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T04:57:03.862Z,1557205023.862 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050622044801,35.0, -0.1,  8.9,  0
2019-05-07T04:57:06.650Z,1557205026.650 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T04:57:06.650Z,1557205026.650 [Default:A.Wait] Stopped
2019-05-07T04:57:06.650Z,1557205026.650 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:57:07.093Z,1557205027.093 [Default:CheckIn] Running Loop=1
2019-05-07T04:57:07.094Z,1557205027.094 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T04:57:07.094Z,1557205027.094 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T04:57:08.662Z,1557205028.662 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:57:09.060Z,1557205029.060 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,045542.00,A,3648.16846,N,12147.28598,W,0.428,344.32,070519,,,A*73
2019-05-07T04:57:09.063Z,1557205029.063 [NAL9602](INFO): GPS fix at 20190507T045542: (36.802808, -121.788100)
2019-05-07T04:57:09.118Z,1557205029.118 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T04:57:09.119Z,1557205029.119 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T04:57:15.462Z,1557205035.462 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190507T044752/Courier0010.lzma
2019-05-07T04:57:16.268Z,1557205036.268 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Courier0010.lzma.bak
2019-05-07T04:57:16.268Z,1557205036.268 [DataOverHttps](INFO): SBD MOMSN=10950084
2019-05-07T04:57:28.102Z,1557205048.102 [DataOverHttps](INFO): Sending 304 bytes from file Logs/20190507T044752/Express0005.lzma
2019-05-07T04:57:28.911Z,1557205048.911 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Express0005.lzma.bak
2019-05-07T04:57:28.912Z,1557205048.912 [DataOverHttps](INFO): SBD MOMSN=10950087
2019-05-07T04:57:39.861Z,1557205059.861 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T04:57:39.938Z,1557205059.938 [NAL9602](FAULT): received: 
+CSQ:0

OK28, 0, 0, 0, 0

OK
2019-05-07T04:57:39.938Z,1557205059.938 [NAL9602] Data Fault, FailCount= 1
2019-05-07T04:57:39.938Z,1557205059.938 [NAL9602](ERROR): Data Fault
2019-05-07T04:57:39.991Z,1557205059.991 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T04:57:40.264Z,1557205060.264 [NAL9602](INFO): Powering down
2019-05-07T04:57:41.103Z,1557205061.103 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T04:57:41.103Z,1557205061.103 [NAL9602] No Fault, FailCount= 1
2019-05-07T04:57:41.262Z,1557205061.262 [DataOverHttps](INFO): Sending 172 bytes from file Logs/20190507T044752/Express0006.lzma
2019-05-07T04:57:42.068Z,1557205062.068 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Express0006.lzma.bak
2019-05-07T04:57:42.068Z,1557205062.068 [DataOverHttps](INFO): SBD MOMSN=10950093
2019-05-07T04:57:57.091Z,1557205077.091 [DataOverHttps](INFO): Sending 989 bytes from file Logs/20190507T044752/Express0008.lzma
2019-05-07T04:57:57.896Z,1557205077.896 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Express0008.lzma.bak
2019-05-07T04:57:57.896Z,1557205077.896 [DataOverHttps](INFO): SBD MOMSN=10950106
2019-05-07T04:58:02.387Z,1557205082.387 [CommandLine](IMPORTANT): got command restart application
2019-05-07T04:58:03.390Z,1557205083.390 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:03.391Z,1557205083.391 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:03.518Z,1557205083.518 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-07T04:58:03.518Z,1557205083.518 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:03.519Z,1557205083.519 [CommandLine](INFO): Join timeout helper Thread ID is 2132
2019-05-07T04:58:03.531Z,1557205083.531 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-07T04:58:03.531Z,1557205083.531 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:03.533Z,1557205083.533 [NavChartDb](INFO): Join timeout helper Thread ID is 2133
2019-05-07T04:58:03.578Z,1557205083.578 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:03.579Z,1557205083.579 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:03.591Z,1557205083.591 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-07T04:58:03.591Z,1557205083.591 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:03.591Z,1557205083.591 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 2134
2019-05-07T04:58:03.986Z,1557205083.986 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:03.987Z,1557205083.987 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T04:58:03.987Z,1557205083.987 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.006Z,1557205084.006 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-07T04:58:04.006Z,1557205084.006 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.007Z,1557205084.007 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2135
2019-05-07T04:58:04.030Z,1557205084.030 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:04.031Z,1557205084.031 [CTD_NeilBrown](INFO): Powering down
2019-05-07T04:58:04.042Z,1557205084.042 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.046Z,1557205084.046 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-07T04:58:04.046Z,1557205084.046 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.047Z,1557205084.047 [Radio_Surface](INFO): Join timeout helper Thread ID is 2136
2019-05-07T04:58:04.250Z,1557205084.250 [Radio_Surface](INFO): Powering down
2019-05-07T04:58:04.251Z,1557205084.251 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:04.252Z,1557205084.252 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.255Z,1557205084.255 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-07T04:58:04.255Z,1557205084.255 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.256Z,1557205084.256 [DataOverHttps](INFO): Join timeout helper Thread ID is 2137
2019-05-07T04:58:04.302Z,1557205084.302 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:04.306Z,1557205084.306 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.323Z,1557205084.323 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-07T04:58:04.323Z,1557205084.323 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.323Z,1557205084.323 [logger](INFO): Join timeout helper Thread ID is 2138
2019-05-07T04:58:04.414Z,1557205084.414 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:04.415Z,1557205084.415 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.423Z,1557205084.423 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-07T04:58:04.423Z,1557205084.423 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.423Z,1557205084.423 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-07T04:58:04.423Z,1557205084.423 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.424Z,1557205084.424 [controlThread](INFO): Join timeout helper Thread ID is 2139
2019-05-07T04:58:04.518Z,1557205084.518 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:58:04.519Z,1557205084.519 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-07T04:58:04.519Z,1557205084.519 [AHRS_M2](INFO): Powering down
2019-05-07T04:58:04.591Z,1557205084.591 [DUSBL_Hydroid](INFO): Powering down
2019-05-07T04:58:04.663Z,1557205084.663 [Micromodem](INFO): Powering down
2019-05-07T04:58:04.759Z,1557205084.759 [NAL9602](INFO): Powering down
2019-05-07T04:58:04.830Z,1557205084.830 [RDI_Pathfinder](INFO): Powering down
2019-05-07T04:58:04.832Z,1557205084.832 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-07T04:58:04.833Z,1557205084.833 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-07T04:58:04.833Z,1557205084.833 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-07T04:58:04.833Z,1557205084.833 [MissionManager](INFO): Uninitializing Mission Default
2019-05-07T04:58:04.834Z,1557205084.834 [Default] Stopped
2019-05-07T04:58:04.834Z,1557205084.834 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T04:58:04.834Z,1557205084.834 [Default:B.GoToSurface] Stopped
2019-05-07T04:58:04.834Z,1557205084.834 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T04:58:04.834Z,1557205084.834 [Default:CheckIn] Stopped
2019-05-07T04:58:04.834Z,1557205084.834 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:58:04.834Z,1557205084.834 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T04:58:04.836Z,1557205084.836 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-07T04:58:04.837Z,1557205084.837 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-07T04:58:04.837Z,1557205084.837 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-07T04:58:04.837Z,1557205084.837 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-07T04:58:04.838Z,1557205084.838 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-07T04:58:04.838Z,1557205084.838 [BuoyancyServo](INFO): Powering down
2019-05-07T04:58:04.850Z,1557205084.850 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-07T04:58:04.850Z,1557205084.850 [ElevatorServo](INFO): Powering down
2019-05-07T04:58:04.851Z,1557205084.851 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-07T04:58:04.851Z,1557205084.851 [MassServo](INFO): Powering down
2019-05-07T04:58:04.852Z,1557205084.852 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T04:58:04.852Z,1557205084.852 [RudderServo](INFO): Powering down
2019-05-07T04:58:04.853Z,1557205084.853 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-07T04:58:04.853Z,1557205084.853 [ThrusterServo](INFO): Powering down
2019-05-07T04:58:04.854Z,1557205084.854 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-07T04:58:04.854Z,1557205084.854 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-07T04:58:04.855Z,1557205084.855 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-07T04:58:04.855Z,1557205084.855 [CBIT](DEBUG): Powering off loads.
2019-05-07T04:58:04.866Z,1557205084.866 [CBIT](DEBUG): Disabling WDT.
2019-05-07T04:58:04.878Z,1557205084.878 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-07T04:58:04.879Z,1557205084.879 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.919Z,1557205084.919 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.927Z,1557205084.927 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.971Z,1557205084.971 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:04.973Z,1557205084.973 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:05.027Z,1557205085.027 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:58:05.094Z,1557205085.094 [logger ThreadHandler](INFO): Thread cancelled.