2019-05-01T00:12:33.390Z,1556669553.390 [Supervisor](DEBUG): Initializing supervisor.
2019-05-01T00:12:33.393Z,1556669553.393 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-01T00:12:33.394Z,1556669553.394 [SyncHandler](INFO): Protected caller Thread ID is 2989
2019-05-01T00:12:33.394Z,1556669553.394 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-01T00:12:33.395Z,1556669553.395 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-01T00:12:33.395Z,1556669553.395 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2990
2019-05-01T00:12:33.399Z,1556669553.399 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-01T00:12:33.412Z,1556669553.412 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-01T00:12:33.413Z,1556669553.413 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-01T00:12:33.413Z,1556669553.413 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2991
2019-05-01T00:12:33.414Z,1556669553.414 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-01T00:12:33.415Z,1556669553.415 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-01T00:12:33.415Z,1556669553.415 [logger ThreadHandler](INFO): Protected caller Thread ID is 2992
2019-05-01T00:12:33.417Z,1556669553.417 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-01T00:12:33.418Z,1556669553.418 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-01T00:12:33.419Z,1556669553.419 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-01T00:12:33.909Z,1556669553.909 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-01T00:12:33.910Z,1556669553.910 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-01T00:12:34.009Z,1556669554.009 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-01T00:12:34.010Z,1556669554.010 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-01T00:12:34.362Z,1556669554.362 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-01T00:12:34.363Z,1556669554.363 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-01T00:12:34.507Z,1556669554.507 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-01T00:12:34.508Z,1556669554.508 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-01T00:12:34.701Z,1556669554.701 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-01T00:12:34.702Z,1556669554.702 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-01T00:12:35.159Z,1556669555.159 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-01T00:12:35.160Z,1556669555.160 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-01T00:12:35.371Z,1556669555.371 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-01T00:12:35.372Z,1556669555.372 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-01T00:12:35.519Z,1556669555.519 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-01T00:12:35.520Z,1556669555.520 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-01T00:12:35.717Z,1556669555.717 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-01T00:12:35.718Z,1556669555.718 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-01T00:12:35.815Z,1556669555.815 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-01T00:12:35.815Z,1556669555.815 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-01T00:12:36.139Z,1556669556.139 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-01T00:12:36.140Z,1556669556.140 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-01T00:12:36.222Z,1556669556.222 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-01T00:12:36.327Z,1556669556.327 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-01T00:12:36.327Z,1556669556.327 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-01T00:12:36.907Z,1556669556.907 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-01T00:12:36.908Z,1556669556.908 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-01T00:12:37.302Z,1556669557.302 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-01T00:12:37.304Z,1556669557.304 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-01T00:12:37.305Z,1556669557.305 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-01T00:12:37.537Z,1556669557.537 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-01T00:12:37.675Z,1556669557.675 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-01T00:12:37.775Z,1556669557.775 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-01T00:12:38.001Z,1556669558.001 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-01T00:12:38.002Z,1556669558.002 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-01T00:12:38.088Z,1556669558.088 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-01T00:12:38.182Z,1556669558.182 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-01T00:12:38.280Z,1556669558.280 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-01T00:12:38.364Z,1556669558.364 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-01T00:12:38.473Z,1556669558.473 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-01T00:12:38.644Z,1556669558.644 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-01T00:12:38.777Z,1556669558.777 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-01T00:12:38.778Z,1556669558.778 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-01T00:12:38.792Z,1556669558.792 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-01T00:12:39.253Z,1556669559.253 [AHRS_M2] Loaded
2019-05-01T00:12:39.254Z,1556669559.254 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-01T00:12:39.327Z,1556669559.327 [DataOverHttps] Loaded
2019-05-01T00:12:39.327Z,1556669559.327 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-01T00:12:39.328Z,1556669559.328 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-01T00:12:39.329Z,1556669559.329 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3071
2019-05-01T00:12:39.342Z,1556669559.342 [Depth_Keller] Loaded
2019-05-01T00:12:39.342Z,1556669559.342 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-01T00:12:39.347Z,1556669559.347 [DropWeight] Loaded
2019-05-01T00:12:39.347Z,1556669559.347 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-01T00:12:39.403Z,1556669559.403 [DUSBL_Hydroid] Loaded
2019-05-01T00:12:39.403Z,1556669559.403 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-01T00:12:39.443Z,1556669559.443 [Micromodem] Loaded
2019-05-01T00:12:39.443Z,1556669559.443 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-01T00:12:39.541Z,1556669559.541 [NAL9602] Loaded
2019-05-01T00:12:39.541Z,1556669559.541 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-01T00:12:39.557Z,1556669559.557 [Onboard] Loaded
2019-05-01T00:12:39.557Z,1556669559.557 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-01T00:12:39.563Z,1556669559.563 [PowerOnly] Loaded
2019-05-01T00:12:39.563Z,1556669559.563 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-01T00:12:39.570Z,1556669559.570 [Radio_Surface] Loaded
2019-05-01T00:12:39.570Z,1556669559.570 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-01T00:12:39.571Z,1556669559.571 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-01T00:12:39.571Z,1556669559.571 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3072
2019-05-01T00:12:39.615Z,1556669559.615 [RDI_Pathfinder] Loaded
2019-05-01T00:12:39.615Z,1556669559.615 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-01T00:12:41.094Z,1556669561.094 [BPC1] Loaded
2019-05-01T00:12:41.094Z,1556669561.094 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-01T00:12:41.095Z,1556669561.095 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-01T00:12:41.095Z,1556669561.095 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-01T00:12:41.122Z,1556669561.122 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-01T00:12:41.122Z,1556669561.122 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-01T00:12:41.957Z,1556669561.957 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-01T00:12:41.957Z,1556669561.957 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-01T00:12:41.977Z,1556669561.977 [NavChart] Loaded
2019-05-01T00:12:41.978Z,1556669561.978 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-01T00:12:41.982Z,1556669561.982 [UniversalFixResidualReporter] Loaded
2019-05-01T00:12:41.982Z,1556669561.982 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-01T00:12:41.982Z,1556669561.982 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-01T00:12:41.983Z,1556669561.983 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-01T00:12:42.114Z,1556669562.114 [BuoyancyServo] Loaded
2019-05-01T00:12:42.114Z,1556669562.114 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-01T00:12:42.129Z,1556669562.129 [ElevatorServo] Loaded
2019-05-01T00:12:42.129Z,1556669562.129 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-01T00:12:42.144Z,1556669562.144 [MassServo] Loaded
2019-05-01T00:12:42.144Z,1556669562.144 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-01T00:12:42.159Z,1556669562.159 [RudderServo] Loaded
2019-05-01T00:12:42.159Z,1556669562.159 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-01T00:12:42.174Z,1556669562.174 [ThrusterServo] Loaded
2019-05-01T00:12:42.174Z,1556669562.174 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-01T00:12:42.175Z,1556669562.175 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-01T00:12:42.175Z,1556669562.175 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-01T00:12:42.495Z,1556669562.495 [CTD_NeilBrown] Loaded
2019-05-01T00:12:42.495Z,1556669562.495 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-01T00:12:42.497Z,1556669562.497 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-01T00:12:42.497Z,1556669562.497 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3073
2019-05-01T00:12:42.541Z,1556669562.541 [WetLabsSeaOWL_UV_A] Loaded
2019-05-01T00:12:42.541Z,1556669562.541 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-01T00:12:42.542Z,1556669562.542 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-01T00:12:42.543Z,1556669562.543 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3074
2019-05-01T00:12:42.543Z,1556669562.543 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-01T00:12:42.544Z,1556669562.544 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-01T00:12:42.882Z,1556669562.882 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-01T00:12:42.882Z,1556669562.882 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-01T00:12:42.936Z,1556669562.936 [DepthRateCalculator] Loaded
2019-05-01T00:12:42.937Z,1556669562.937 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-01T00:12:42.942Z,1556669562.942 [PitchRateCalculator] Loaded
2019-05-01T00:12:42.943Z,1556669562.943 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-01T00:12:42.955Z,1556669562.955 [SpeedCalculator] Loaded
2019-05-01T00:12:42.955Z,1556669562.955 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-01T00:12:42.976Z,1556669562.976 [TempGradientCalculator] Loaded
2019-05-01T00:12:42.976Z,1556669562.976 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-01T00:12:42.982Z,1556669562.982 [YawRateCalculator] Loaded
2019-05-01T00:12:42.982Z,1556669562.982 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-01T00:12:43.022Z,1556669563.022 [ElevatorOffsetCalculator] Loaded
2019-05-01T00:12:43.022Z,1556669563.022 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-01T00:12:43.023Z,1556669563.023 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-01T00:12:43.023Z,1556669563.023 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-01T00:12:43.184Z,1556669563.184 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-01T00:12:43.206Z,1556669563.206 [SBIT] Loaded
2019-05-01T00:12:43.206Z,1556669563.206 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-01T00:12:43.207Z,1556669563.207 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-01T00:12:43.218Z,1556669563.218 [IBIT] Loaded
2019-05-01T00:12:43.219Z,1556669563.219 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-01T00:12:43.222Z,1556669563.222 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-01T00:12:43.360Z,1556669563.360 [CBIT] Loaded
2019-05-01T00:12:43.360Z,1556669563.360 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-01T00:12:43.360Z,1556669563.360 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-01T00:12:43.361Z,1556669563.361 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-01T00:12:43.472Z,1556669563.472 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-01T00:12:43.472Z,1556669563.472 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-01T00:12:43.597Z,1556669563.597 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-01T00:12:43.597Z,1556669563.597 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-01T00:12:43.683Z,1556669563.683 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-01T00:12:43.767Z,1556669563.767 [VerticalControl] Loaded
2019-05-01T00:12:43.767Z,1556669563.767 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-01T00:12:43.768Z,1556669563.768 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-01T00:12:43.825Z,1556669563.825 [HorizontalControl] Loaded
2019-05-01T00:12:43.826Z,1556669563.826 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-01T00:12:43.826Z,1556669563.826 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-01T00:12:43.828Z,1556669563.828 [SpeedControl] Loaded
2019-05-01T00:12:43.828Z,1556669563.828 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-01T00:12:43.829Z,1556669563.829 [LoopControl](DEBUG): Construct LoopControl.
2019-05-01T00:12:43.829Z,1556669563.829 [LoopControl] Loaded
2019-05-01T00:12:43.830Z,1556669563.830 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-01T00:12:43.830Z,1556669563.830 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-01T00:12:43.831Z,1556669563.831 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-01T00:12:43.871Z,1556669563.871 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-01T00:12:43.875Z,1556669563.875 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-01T00:12:43.876Z,1556669563.876 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-01T00:12:43.882Z,1556669563.882 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-01T00:12:43.883Z,1556669563.883 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-01T00:12:43.884Z,1556669563.884 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3075
2019-05-01T00:12:43.889Z,1556669563.889 [Supervisor](INFO): Main Thread ID is 802
2019-05-01T00:12:43.889Z,1556669563.889 [Supervisor](DEBUG): Running supervisor.
2019-05-01T00:12:43.889Z,1556669563.889 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3076
2019-05-01T00:12:43.892Z,1556669563.892 [controlThread ThreadHandler](INFO): Handler Thread ID is 3077
2019-05-01T00:12:43.892Z,1556669563.892 [controlThread](DEBUG): Initializing ControlThread
2019-05-01T00:12:43.901Z,1556669563.901 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-01T00:12:43.901Z,1556669563.901 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-01T00:12:43.902Z,1556669563.902 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-01T00:12:43.902Z,1556669563.902 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-01T00:12:43.903Z,1556669563.903 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-01T00:12:43.903Z,1556669563.903 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-01T00:12:43.903Z,1556669563.903 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-01T00:12:43.904Z,1556669563.904 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-01T00:12:43.904Z,1556669563.904 [SBIT](INFO): Initialize SBIT Component.
2019-05-01T00:12:43.905Z,1556669563.905 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-01T00:12:43.905Z,1556669563.905 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-01T00:12:43.905Z,1556669563.905 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-01T00:12:43.906Z,1556669563.906 [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-01T00:12:43.908Z,1556669563.908 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-01T00:12:43.908Z,1556669563.908 [IBIT](INFO): Initialize IBIT Component.
2019-05-01T00:12:43.909Z,1556669563.909 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-01T00:12:43.910Z,1556669563.910 [logger ThreadHandler](INFO): Handler Thread ID is 3078
2019-05-01T00:12:43.921Z,1556669563.921 [CBIT](DEBUG): Initialized mux pins.
2019-05-01T00:12:43.921Z,1556669563.921 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-01T00:12:43.929Z,1556669563.929 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3079
2019-05-01T00:12:43.930Z,1556669563.930 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-01T00:12:43.941Z,1556669563.941 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3080
2019-05-01T00:12:43.945Z,1556669563.945 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-01T00:12:43.945Z,1556669563.945 [CBIT](DEBUG): Initializing heartbeat.
2019-05-01T00:12:43.961Z,1556669563.961 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3081
2019-05-01T00:12:43.962Z,1556669563.962 [CTD_NeilBrown](INFO): Powering down
2019-05-01T00:12:43.997Z,1556669563.997 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3082
2019-05-01T00:12:43.998Z,1556669563.998 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-01T00:12:44.017Z,1556669564.017 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-01T00:12:44.017Z,1556669564.017 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-01T00:12:44.018Z,1556669564.018 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3083
2019-05-01T00:12:44.024Z,1556669564.024 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-01T00:12:44.025Z,1556669564.025 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-01T00:12:44.025Z,1556669564.025 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-01T00:12:44.025Z,1556669564.025 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-01T00:12:44.025Z,1556669564.025 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-01T00:12:44.026Z,1556669564.026 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-01T00:12:44.026Z,1556669564.026 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-01T00:12:44.026Z,1556669564.026 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-01T00:12:44.026Z,1556669564.026 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-01T00:12:44.026Z,1556669564.026 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-01T00:12:44.027Z,1556669564.027 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-01T00:12:44.027Z,1556669564.027 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-01T00:12:44.027Z,1556669564.027 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-01T00:12:44.027Z,1556669564.027 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-01T00:12:44.027Z,1556669564.027 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-01T00:12:44.027Z,1556669564.027 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-01T00:12:44.053Z,1556669564.053 [CBIT](DEBUG): Backplane powered.
2019-05-01T00:12:44.053Z,1556669564.053 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-01T00:12:44.055Z,1556669564.055 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-01T00:12:44.056Z,1556669564.056 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-01T00:12:44.056Z,1556669564.056 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-01T00:12:44.057Z,1556669564.057 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-01T00:12:44.071Z,1556669564.071 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-01T00:12:44.091Z,1556669564.091 [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-01T00:12:44.092Z,1556669564.092 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-01T00:12:44.155Z,1556669564.155 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-01T00:12:44.156Z,1556669564.156 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-01T00:12:44.174Z,1556669564.174 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-01T00:12:44.200Z,1556669564.200 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-01T00:12:44.203Z,1556669564.203 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-01T00:12:44.218Z,1556669564.218 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-01T00:12:44.237Z,1556669564.237 [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-01T00:12:44.242Z,1556669564.242 [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-01T00:12:44.261Z,1556669564.261 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-01T00:12:44.290Z,1556669564.290 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-01T00:12:44.291Z,1556669564.291 [DUSBL_Hydroid](INFO): Powering up
2019-05-01T00:12:44.291Z,1556669564.291 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-01T00:12:44.345Z,1556669564.345 [Radio_Surface](INFO): Powering up
2019-05-01T00:12:44.365Z,1556669564.365 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-01T00:12:44.393Z,1556669564.393 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-01T00:12:44.401Z,1556669564.401 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-01T00:12:44.402Z,1556669564.402 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-01T00:12:44.409Z,1556669564.409 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-01T00:12:44.410Z,1556669564.410 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-01T00:12:44.418Z,1556669564.418 [MassServo](DEBUG): Initializing MassServo.
2019-05-01T00:12:44.418Z,1556669564.418 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-01T00:12:44.425Z,1556669564.425 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-01T00:12:44.426Z,1556669564.426 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-01T00:12:44.433Z,1556669564.433 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-01T00:12:44.667Z,1556669564.667 [Micromodem](INFO): Powering up
2019-05-01T00:12:44.667Z,1556669564.667 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-01T00:12:44.701Z,1556669564.701 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-01T00:12:45.385Z,1556669565.385 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-01T00:12:45.385Z,1556669565.385 [RudderServo](FAULT): Rudder failed to initialize
2019-05-01T00:12:45.385Z,1556669565.385 [RudderServo] Communications Fault, FailCount= 1
2019-05-01T00:12:45.385Z,1556669565.385 [RudderServo](ERROR): Communications Fault
2019-05-01T00:12:45.497Z,1556669565.497 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-01T00:12:45.658Z,1556669565.658 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-01T00:12:45.658Z,1556669565.658 [RudderServo](INFO): Powering down
2019-05-01T00:12:46.356Z,1556669566.356 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-01T00:12:46.474Z,1556669566.474 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-01T00:12:46.478Z,1556669566.478 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-01T00:12:46.478Z,1556669566.478 [RudderServo] No Fault, FailCount= 1
2019-05-01T00:12:49.583Z,1556669569.583 [Micromodem](DEBUG): Nmea buf: $CCCFG,ALL,0*33

2019-05-01T00:12:49.583Z,1556669569.583 [Micromodem](DEBUG): Nmea buf: $CCCFG,SRC,1*31

2019-05-01T00:12:49.584Z,1556669569.584 [Micromodem](DEBUG): Nmea buf: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-01T00:12:49.584Z,1556669569.584 [Micromodem](DEBUG): Nmea buf: $CCCFG,BND,1*3B

2019-05-01T00:12:57.656Z,1556669577.656 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-01T00:13:00.859Z,1556669580.859 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-05-01T00:13:02.486Z,1556669582.486 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-01T00:13:09.753Z,1556669589.753 [NAL9602](INFO): Powering up NAL9602
2019-05-01T00:13:20.655Z,1556669600.655 [NAL9602](INFO): NAL9602 initialized
2019-05-01T00:13:21.497Z,1556669601.497 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:13:24.981Z,1556669604.981 [CommandLine](IMPORTANT): got command failComponent
2019-05-01T00:13:24.982Z,1556669604.982 [CommandLine](IMPORTANT): Failed components:
2019-05-01T00:13:24.982Z,1556669604.982 [CommandLine](IMPORTANT): No failed Components.
2019-05-01T00:13:28.399Z,1556669608.399 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-01T00:13:28.407Z,1556669608.407 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-01T00:13:34.598Z,1556669614.598 [CommandLine](IMPORTANT): got command failComponent
2019-05-01T00:13:34.598Z,1556669614.598 [CommandLine](IMPORTANT): Failed components:
2019-05-01T00:13:34.598Z,1556669614.598 [CommandLine](IMPORTANT): No failed Components.
2019-05-01T00:13:39.174Z,1556669619.174 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010980
CHAN A1 (24V): -0.027836
CHAN A2 (12V): -0.006549
CHAN A3 (5V): -0.002006
CHAN B0 (3.3V): 0.000687
CHAN B1 (3.15aV): 0.000437
CHAN B2 (3.15bV): -0.000073
CHAN B3 (GND): 0.001707
OPEN: 0.007231
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-01T00:13:40.291Z,1556669620.291 [Micromodem](DEBUG): Nmea buf: $CCTMS,2019-05-01T00:13:41Z,0*7D

2019-05-01T00:14:22.536Z,1556669662.536 [SBIT](IMPORTANT): SBIT PASSED
2019-05-01T00:14:22.577Z,1556669662.577 [CommandLine](IMPORTANT): got command configSet list
2019-05-01T00:14:22.577Z,1556669662.577 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-01T00:14:22.578Z,1556669662.578 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-01T00:14:22.578Z,1556669662.578 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-01T00:14:22.579Z,1556669662.579 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-01T00:14:22.580Z,1556669662.580 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-01T00:14:22.580Z,1556669662.580 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-01T00:14:22.899Z,1556669662.899 [MissionManager](IMPORTANT): Started mission Startup
2019-05-01T00:14:22.899Z,1556669662.899 [Startup] Running Loop=1
2019-05-01T00:14:22.899Z,1556669662.899 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-01T00:14:22.899Z,1556669662.899 [Startup:A.GoToSurface] Running Loop=1
2019-05-01T00:14:22.899Z,1556669662.899 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-01T00:14:22.900Z,1556669662.900 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-01T00:14:22.900Z,1556669662.900 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-01T00:14:22.901Z,1556669662.901 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-01T00:14:22.901Z,1556669662.901 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-01T00:14:22.902Z,1556669662.902 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-01T00:14:22.903Z,1556669662.903 [Startup:StartupSatComms] Running Loop=1
2019-05-01T00:14:22.903Z,1556669662.903 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-01T00:14:22.903Z,1556669662.903 [Startup:StartupSatComms:A] Running Loop=1
2019-05-01T00:14:23.302Z,1556669663.302 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-01T00:14:30.095Z,1556669670.095 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:14:30.095Z,1556669670.095 [Micromodem] Hardware Fault, FailCount= 1
2019-05-01T00:14:30.095Z,1556669670.095 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:14:30.095Z,1556669670.095 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:14:30.142Z,1556669670.142 [Micromodem](INFO): Powering down
2019-05-01T00:14:30.294Z,1556669670.294 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:14:30.997Z,1556669670.997 [CBIT](INFO): Clearing failed state for component Micromodem
2019-05-01T00:14:30.997Z,1556669670.997 [Micromodem] No Fault, FailCount= 1
2019-05-01T00:14:33.778Z,1556669673.778 [Micromodem](INFO): Powering up
2019-05-01T00:14:33.779Z,1556669673.779 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-01T00:14:38.628Z,1556669678.628 [Micromodem](DEBUG): Nmea buf: $CCCFG,ALL,0*33

2019-05-01T00:14:38.630Z,1556669678.630 [Micromodem](DEBUG): Nmea buf: $CCCFG,SRC,1*31

2019-05-01T00:14:38.631Z,1556669678.631 [Micromodem](DEBUG): Nmea buf: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-01T00:14:38.632Z,1556669678.632 [Micromodem](DEBUG): Nmea buf: $CCCFG,BND,1*3B

2019-05-01T00:15:05.293Z,1556669705.293 [NAL9602](INFO): SBD MO Status=2, MOMSN=3770, MT Status=2, MTMSN=0
2019-05-01T00:15:05.293Z,1556669705.293 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:15:08.932Z,1556669708.932 [Micromodem](DEBUG): Nmea buf: $CCTMS,2019-05-01T00:15:09Z,0*77

2019-05-01T00:15:09.331Z,1556669709.331 [Micromodem](ERROR): Response from modem unexpected: $CADQF,191,1*59

2019-05-01T00:15:09.735Z,1556669709.735 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-01T00:15:10.143Z,1556669710.143 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190501001508.681827,05,116,14,009,0150,246,0000,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,191,0.00,-999,9760,4000*52

2019-05-01T00:15:10.311Z,1556669710.311 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004977
2019-05-01T00:15:22.664Z,1556669722.664 [NAL9602](INFO): SBD MO Status=2, MOMSN=3770, MT Status=2, MTMSN=0
2019-05-01T00:15:22.665Z,1556669722.665 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:15:23.110Z,1556669723.110 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-01T00:14:22.9Z
2019-05-01T00:15:23.110Z,1556669723.110 [Startup:StartupSatComms:A] Stopped
2019-05-01T00:15:23.110Z,1556669723.110 [Startup:StartupSatComms:B] Running Loop=1
2019-05-01T00:15:23.523Z,1556669723.523 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-01T00:15:28.528Z,1556669728.528 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190430T235746/Courier0010.lzma
2019-05-01T00:15:29.334Z,1556669729.334 [DataOverHttps](INFO): Moved sent file to Logs/20190430T235746/Courier0010.lzma.bak
2019-05-01T00:15:29.335Z,1556669729.335 [DataOverHttps](INFO): SBD MOMSN=10877754
2019-05-01T00:15:38.854Z,1556669738.854 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-01T00:15:38.854Z,1556669738.854 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19043017241083,35.0, -0.1,   .9,  0
2019-05-01T00:15:40.677Z,1556669740.677 [DataOverHttps](INFO): Sending 249 bytes from file Logs/20190430T235746/Express0011.lzma
2019-05-01T00:15:41.483Z,1556669741.483 [DataOverHttps](INFO): Moved sent file to Logs/20190430T235746/Express0011.lzma.bak
2019-05-01T00:15:41.483Z,1556669741.483 [DataOverHttps](INFO): SBD MOMSN=10877756
2019-05-01T00:15:44.097Z,1556669744.097 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-01T00:15:44.097Z,1556669744.097 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-01T00:15:44.112Z,1556669744.112 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-01T00:15:44.492Z,1556669744.492 [NAL9602](INFO): SBD MO Status=2, MOMSN=3770, MT Status=2, MTMSN=0
2019-05-01T00:15:44.493Z,1556669744.493 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:15:44.597Z,1556669744.597 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-01T00:15:44.598Z,1556669744.598 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-01T00:15:52.843Z,1556669752.843 [DataOverHttps](INFO): Sending 1363 bytes from file Logs/20190501T001233/Express0001.lzma
2019-05-01T00:15:53.646Z,1556669753.646 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0001.lzma.bak
2019-05-01T00:15:53.646Z,1556669753.646 [DataOverHttps](INFO): SBD MOMSN=10877759
2019-05-01T00:15:54.214Z,1556669754.214 [Startup:StartupSatComms:B] Stopped
2019-05-01T00:15:54.214Z,1556669754.214 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-01T00:15:54.214Z,1556669754.214 [Startup:StartupSatComms] Stopped
2019-05-01T00:15:54.214Z,1556669754.214 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-01T00:15:54.215Z,1556669754.215 [Startup](INFO): Completed Startup
2019-05-01T00:15:54.215Z,1556669754.215 [MissionManager](INFO): Startup is completed.
2019-05-01T00:15:54.215Z,1556669754.215 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-01T00:15:54.215Z,1556669754.215 [Startup] Stopped
2019-05-01T00:15:54.215Z,1556669754.215 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-01T00:15:54.215Z,1556669754.215 [Startup:A.GoToSurface] Stopped
2019-05-01T00:15:54.216Z,1556669754.216 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-01T00:15:54.630Z,1556669754.630 [MissionManager](IMPORTANT): Started mission Default
2019-05-01T00:15:54.630Z,1556669754.630 [Default] Running Loop=1
2019-05-01T00:15:54.630Z,1556669754.630 [Default](DEBUG): Aggregate::initialize Default
2019-05-01T00:15:54.630Z,1556669754.630 [Default:B.GoToSurface] Running Loop=1
2019-05-01T00:15:54.630Z,1556669754.630 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-01T00:15:54.630Z,1556669754.630 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-01T00:15:54.631Z,1556669754.631 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-01T00:15:54.631Z,1556669754.631 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-01T00:15:54.631Z,1556669754.631 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-01T00:15:54.632Z,1556669754.632 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-01T00:15:54.632Z,1556669754.632 [Default:A.Wait] Running Loop=1
2019-05-01T00:15:54.632Z,1556669754.632 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:15:58.620Z,1556669758.620 [NAL9602](INFO): SBD MO Status=2, MOMSN=3770, MT Status=2, MTMSN=0
2019-05-01T00:15:58.620Z,1556669758.620 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:16:07.958Z,1556669767.958 [Default:A.Wait](INFO): Done Waiting.
2019-05-01T00:16:07.959Z,1556669767.959 [Default:A.Wait] Stopped
2019-05-01T00:16:07.959Z,1556669767.959 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:16:08.350Z,1556669768.350 [Default:CheckIn] Running Loop=1
2019-05-01T00:16:08.350Z,1556669768.350 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-01T00:16:08.351Z,1556669768.351 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-01T00:16:08.767Z,1556669768.767 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-01T00:16:27.712Z,1556669787.712 [NAL9602](INFO): SBD MO Status=0, MOMSN=3770, MT Status=0, MTMSN=0
2019-05-01T00:16:27.712Z,1556669787.712 [NAL9602](INFO): No messages in MT queue
2019-05-01T00:16:28.529Z,1556669788.529 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:30.957Z,1556669790.957 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:33.781Z,1556669793.781 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:37.017Z,1556669797.017 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:39.841Z,1556669799.841 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:43.073Z,1556669803.073 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:45.901Z,1556669805.901 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:48.733Z,1556669808.733 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:51.961Z,1556669811.961 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:54.797Z,1556669814.797 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:16:58.029Z,1556669818.029 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:00.853Z,1556669820.853 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:03.693Z,1556669823.693 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:06.921Z,1556669826.921 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:09.753Z,1556669829.753 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:12.985Z,1556669832.985 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:15.809Z,1556669835.809 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:19.041Z,1556669839.041 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:21.869Z,1556669841.869 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:24.701Z,1556669844.701 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:27.937Z,1556669847.937 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:30.757Z,1556669850.757 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:33.993Z,1556669853.993 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:17:34.403Z,1556669854.403 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001702.00,A,3648.16683,N,12147.27986,W,0.311,355.64,010519,,,A*76
2019-05-01T00:17:34.406Z,1556669854.406 [NAL9602](INFO): GPS fix at 20190501T001702: (36.802780, -121.787998)
2019-05-01T00:17:34.436Z,1556669854.436 [Default:CheckIn:Read_GPS] Stopped
2019-05-01T00:17:34.437Z,1556669854.437 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-01T00:17:34.845Z,1556669854.845 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-01T00:17:43.577Z,1556669863.577 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190501T001233/Courier0004.lzma
2019-05-01T00:17:44.388Z,1556669864.388 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Courier0004.lzma.bak
2019-05-01T00:17:44.388Z,1556669864.388 [DataOverHttps](INFO): SBD MOMSN=10877794
2019-05-01T00:17:57.333Z,1556669877.333 [DataOverHttps](INFO): Sending 425 bytes from file Logs/20190501T001233/Express0005.lzma
2019-05-01T00:17:58.138Z,1556669878.138 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0005.lzma.bak
2019-05-01T00:17:58.138Z,1556669878.138 [DataOverHttps](INFO): SBD MOMSN=10877800
2019-05-01T00:17:58.719Z,1556669878.719 [Default:CheckIn:Read_Iridium] Stopped
2019-05-01T00:17:58.719Z,1556669878.719 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-01T00:17:58.719Z,1556669878.719 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:18:06.772Z,1556669886.772 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-01T00:19:13.488Z,1556669953.488 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2019-05-01T00:19:13.497Z,1556669953.497 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,    +0    +0,A
2019-05-01T00:19:23.491Z,1556669963.491 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:19:23.491Z,1556669963.491 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:19:23.597Z,1556669963.597 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-01T00:19:23.605Z,1556669963.605 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-01T00:19:23.618Z,1556669963.618 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-01T00:19:23.633Z,1556669963.633 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-01T00:19:23.645Z,1556669963.645 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-01T00:19:23.646Z,1556669963.646 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-01T00:19:23.663Z,1556669963.663 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-01T00:19:23.684Z,1556669963.684 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-01T00:19:23.691Z,1556669963.691 [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-01T00:19:23.706Z,1556669963.706 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:19:23.962Z,1556669963.962 [Default] Stopped
2019-05-01T00:19:23.962Z,1556669963.962 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-01T00:19:23.963Z,1556669963.963 [Default:B.GoToSurface] Stopped
2019-05-01T00:19:23.963Z,1556669963.963 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-01T00:19:23.963Z,1556669963.963 [Default:CheckIn] Stopped
2019-05-01T00:19:23.963Z,1556669963.963 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-01T00:19:23.963Z,1556669963.963 [Default:CheckIn:C.Wait] Stopped
2019-05-01T00:19:23.963Z,1556669963.963 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:19:23.963Z,1556669963.963 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-01T00:19:23.963Z,1556669963.963 [DUSBL] Running Loop=1
2019-05-01T00:19:23.963Z,1556669963.963 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:A.Pitch] Running Loop=1
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:C] Running Loop=1
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:RequestRepeater] Running Loop=1
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:19:23.964Z,1556669963.964 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:19:23.969Z,1556669963.969 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:19:23.969Z,1556669963.969 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:19:23.970Z,1556669963.970 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:19:23.970Z,1556669963.970 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:19:23.970Z,1556669963.970 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:19:23.971Z,1556669963.971 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-01T00:19:23.972Z,1556669963.972 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-01T00:19:23.972Z,1556669963.972 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-01T00:19:23.972Z,1556669963.972 [DUSBL:A.Pitch] Running Loop=1
2019-05-01T00:19:25.548Z,1556669965.548 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:25.553Z,1556669965.553 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:29.587Z,1556669969.587 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:29.592Z,1556669969.592 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:32.420Z,1556669972.420 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:32.426Z,1556669972.426 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:32.842Z,1556669972.842 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,189,80,81,04,FF
2019-05-01T00:19:34.064Z,1556669974.064 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:19:34.064Z,1556669974.064 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:19:34.064Z,1556669974.064 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:19:34.065Z,1556669974.065 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:19:34.065Z,1556669974.065 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:19:34.065Z,1556669974.065 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater] Running Loop=2
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:19:34.066Z,1556669974.066 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:19:36.482Z,1556669976.482 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:36.508Z,1556669976.508 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:36.859Z,1556669976.859 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,186,80,81,05,FF
2019-05-01T00:19:40.500Z,1556669980.500 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:40.504Z,1556669980.504 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:40.903Z,1556669980.903 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,187,80,81,03,FF
2019-05-01T00:19:44.535Z,1556669984.535 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:44.540Z,1556669984.540 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:44.596Z,1556669984.596 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:19:44.596Z,1556669984.596 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:19:44.596Z,1556669984.596 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:19:44.597Z,1556669984.597 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:19:44.598Z,1556669984.598 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:19:44.598Z,1556669984.598 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:19:44.598Z,1556669984.598 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:19:44.598Z,1556669984.598 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:19:44.598Z,1556669984.598 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-01T00:19:44.598Z,1556669984.598 [DUSBL:RequestRepeater] Running Loop=3
2019-05-01T00:19:44.598Z,1556669984.598 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:19:44.599Z,1556669984.599 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:19:44.599Z,1556669984.599 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:19:44.599Z,1556669984.599 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:19:44.599Z,1556669984.599 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:19:44.939Z,1556669984.939 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,186,80,81,0C,FF
2019-05-01T00:19:48.574Z,1556669988.574 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:48.576Z,1556669988.576 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:49.382Z,1556669989.382 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:49.384Z,1556669989.384 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:49.785Z,1556669989.785 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:19:49.787Z,1556669989.787 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,001948.31*58

2019-05-01T00:19:53.429Z,1556669993.429 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:53.434Z,1556669993.434 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:53.827Z,1556669993.827 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,04,FF
2019-05-01T00:19:55.068Z,1556669995.068 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:19:55.068Z,1556669995.068 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:19:55.068Z,1556669995.068 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:19:55.068Z,1556669995.068 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:19:55.069Z,1556669995.069 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:19:55.069Z,1556669995.069 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:19:55.069Z,1556669995.069 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:19:55.069Z,1556669995.069 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:19:55.069Z,1556669995.069 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-01T00:19:55.069Z,1556669995.069 [DUSBL:RequestRepeater] Running Loop=4
2019-05-01T00:19:55.069Z,1556669995.069 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:19:55.070Z,1556669995.070 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:19:55.070Z,1556669995.070 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:19:55.070Z,1556669995.070 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:19:55.070Z,1556669995.070 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:19:57.484Z,1556669997.484 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:57.488Z,1556669997.488 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:58.271Z,1556669998.271 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:19:58.276Z,1556669998.276 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:19:58.679Z,1556669998.679 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:19:58.681Z,1556669998.681 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,001957.22*54

2019-05-01T00:20:02.311Z,1556670002.311 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:02.315Z,1556670002.315 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:02.715Z,1556670002.715 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,06,FF
2019-05-01T00:20:05.608Z,1556670005.608 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:20:05.608Z,1556670005.608 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:20:05.608Z,1556670005.608 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:20:05.609Z,1556670005.609 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater] Running Loop=5
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:20:05.610Z,1556670005.610 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:20:06.355Z,1556670006.355 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:06.359Z,1556670006.359 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:07.159Z,1556670007.159 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:07.164Z,1556670007.164 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:07.567Z,1556670007.567 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:20:07.568Z,1556670007.568 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,002006.09*53

2019-05-01T00:20:11.203Z,1556670011.203 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:11.207Z,1556670011.207 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:11.249Z,1556670011.249 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-01T00:20:11.253Z,1556670011.253 [BPC1](INFO): Received data from all battery sticks.
2019-05-01T00:20:11.602Z,1556670011.602 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,07,FF
2019-05-01T00:20:15.247Z,1556670015.247 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:15.252Z,1556670015.252 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:15.643Z,1556670015.643 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,05,FF
2019-05-01T00:20:16.083Z,1556670016.083 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:20:16.083Z,1556670016.083 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:20:16.083Z,1556670016.083 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:20:16.084Z,1556670016.084 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:20:16.084Z,1556670016.084 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:20:16.084Z,1556670016.084 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:20:16.084Z,1556670016.084 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:20:16.084Z,1556670016.084 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:20:16.084Z,1556670016.084 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-01T00:20:16.084Z,1556670016.084 [DUSBL:RequestRepeater] Running Loop=6
2019-05-01T00:20:16.085Z,1556670016.085 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:20:16.085Z,1556670016.085 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:20:16.086Z,1556670016.086 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:20:16.086Z,1556670016.086 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:20:16.086Z,1556670016.086 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:20:19.276Z,1556670019.276 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:19.280Z,1556670019.280 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:19.686Z,1556670019.686 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,186,80,81,06,FF
2019-05-01T00:20:23.318Z,1556670023.318 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:23.319Z,1556670023.319 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:23.735Z,1556670023.735 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,ED1,80,81,04,FF
2019-05-01T00:20:26.630Z,1556670026.630 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:20:26.630Z,1556670026.630 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:20:26.630Z,1556670026.630 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater] Running Loop=7
2019-05-01T00:20:26.631Z,1556670026.631 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:20:26.632Z,1556670026.632 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:20:26.632Z,1556670026.632 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:20:26.632Z,1556670026.632 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:20:26.632Z,1556670026.632 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:20:27.375Z,1556670027.375 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:27.380Z,1556670027.380 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:30.187Z,1556670030.187 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:30.191Z,1556670030.191 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:33.426Z,1556670033.426 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:33.431Z,1556670033.431 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:36.247Z,1556670036.247 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:36.258Z,1556670036.258 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:36.651Z,1556670036.651 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,08,FF
2019-05-01T00:20:36.679Z,1556670036.679 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190501002034.611444,06,320,13,0090,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,190,0.00,-999,9760,4000*5B

2019-05-01T00:20:37.099Z,1556670037.099 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:20:37.099Z,1556670037.099 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:20:37.099Z,1556670037.099 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater] Running Loop=8
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:20:37.100Z,1556670037.100 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:20:37.101Z,1556670037.101 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:20:40.291Z,1556670040.291 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:40.296Z,1556670040.296 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:43.119Z,1556670043.119 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:43.138Z,1556670043.138 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:43.522Z,1556670043.522 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,188,80,81,05,FF
2019-05-01T00:20:47.159Z,1556670047.159 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:47.164Z,1556670047.164 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:47.562Z,1556670047.562 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,184,80,81,05,FF
2019-05-01T00:20:47.579Z,1556670047.579 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190501002045.579238,06,435,14,0104,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,195,-0.10,-999,9760,4000*7C

2019-05-01T00:20:47.658Z,1556670047.658 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:20:47.658Z,1556670047.658 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:20:47.658Z,1556670047.658 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:20:47.659Z,1556670047.659 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:20:47.659Z,1556670047.659 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:20:47.659Z,1556670047.659 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater] Running Loop=9
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:20:47.660Z,1556670047.660 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:20:51.199Z,1556670051.199 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:51.203Z,1556670051.203 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:51.602Z,1556670051.602 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,06,FF
2019-05-01T00:20:54.854Z,1556670054.854 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,    -2,    -1,    +1,-32768,A
2019-05-01T00:20:55.239Z,1556670055.239 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:55.244Z,1556670055.244 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:55.645Z,1556670055.645 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,07,FF
2019-05-01T00:20:58.088Z,1556670058.088 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:20:58.088Z,1556670058.088 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:20:58.088Z,1556670058.088 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:20:58.089Z,1556670058.089 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:20:58.089Z,1556670058.089 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:20:58.089Z,1556670058.089 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:20:58.089Z,1556670058.089 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:20:58.089Z,1556670058.089 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:20:58.089Z,1556670058.089 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-01T00:20:58.089Z,1556670058.089 [DUSBL:RequestRepeater] Running Loop=10
2019-05-01T00:20:58.090Z,1556670058.090 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:20:58.090Z,1556670058.090 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:20:58.090Z,1556670058.090 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:20:58.090Z,1556670058.090 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:20:58.090Z,1556670058.090 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:20:59.275Z,1556670059.275 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:20:59.303Z,1556670059.303 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:20:59.678Z,1556670059.678 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,186,80,81,08,FF
2019-05-01T00:21:03.319Z,1556670063.319 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:21:03.324Z,1556670063.324 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:21:03.721Z,1556670063.721 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,189,80,81,08,FF
2019-05-01T00:21:05.744Z,1556670065.744 [CommandLine](IMPORTANT): got command stop
2019-05-01T00:21:05.744Z,1556670065.744 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-01T00:21:05.744Z,1556670065.744 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-01T00:21:05.817Z,1556670065.817 [MissionManager](INFO): MissionManager is completed.
2019-05-01T00:21:05.818Z,1556670065.818 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:A.Pitch] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:B.SetSpeed] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:C] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:21:05.818Z,1556670065.818 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:21:06.183Z,1556670066.183 [MissionManager](IMPORTANT): Started mission Default
2019-05-01T00:21:06.184Z,1556670066.184 [Default] Running Loop=1
2019-05-01T00:21:06.184Z,1556670066.184 [Default](DEBUG): Aggregate::initialize Default
2019-05-01T00:21:06.184Z,1556670066.184 [Default:B.GoToSurface] Running Loop=1
2019-05-01T00:21:06.184Z,1556670066.184 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-01T00:21:06.184Z,1556670066.184 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-01T00:21:06.184Z,1556670066.184 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-01T00:21:06.185Z,1556670066.185 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-01T00:21:06.185Z,1556670066.185 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-01T00:21:06.186Z,1556670066.186 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-01T00:21:06.186Z,1556670066.186 [Default:A.Wait] Running Loop=1
2019-05-01T00:21:06.186Z,1556670066.186 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:21:19.532Z,1556670079.532 [Default:A.Wait](INFO): Done Waiting.
2019-05-01T00:21:19.532Z,1556670079.532 [Default:A.Wait] Stopped
2019-05-01T00:21:19.532Z,1556670079.532 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:21:19.908Z,1556670079.908 [Default:CheckIn] Running Loop=1
2019-05-01T00:21:19.908Z,1556670079.908 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-01T00:21:19.908Z,1556670079.908 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-01T00:21:21.513Z,1556670081.513 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:21:21.906Z,1556670081.906 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002049.00,A,3648.16900,N,12147.28439,W,0.350,358.46,010519,,,A*77
2019-05-01T00:21:21.908Z,1556670081.908 [NAL9602](INFO): GPS fix at 20190501T002049: (36.802817, -121.788073)
2019-05-01T00:21:21.932Z,1556670081.932 [Default:CheckIn:Read_GPS] Stopped
2019-05-01T00:21:21.932Z,1556670081.932 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-01T00:21:32.149Z,1556670092.149 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190501T001233/Courier0007.lzma
2019-05-01T00:21:32.954Z,1556670092.954 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Courier0007.lzma.bak
2019-05-01T00:21:32.955Z,1556670092.955 [DataOverHttps](INFO): SBD MOMSN=10877817
2019-05-01T00:21:44.535Z,1556670104.535 [DataOverHttps](INFO): Sending 776 bytes from file Logs/20190501T001233/Express0008.lzma
2019-05-01T00:21:45.338Z,1556670105.338 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0008.lzma.bak
2019-05-01T00:21:45.339Z,1556670105.339 [DataOverHttps](INFO): SBD MOMSN=10877820
2019-05-01T00:21:46.180Z,1556670106.180 [Default:CheckIn:Read_Iridium] Stopped
2019-05-01T00:21:46.180Z,1556670106.180 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-01T00:21:46.180Z,1556670106.180 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:21:55.850Z,1556670115.850 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-01T00:21:55.850Z,1556670115.850 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19043017302783,35.0, -0.1,   0.0,1448.9A,  0.00,   0.00,  92.93,  96.42,  95.42
2019-05-01T00:23:36.429Z,1556670216.429 [Micromodem](ERROR): Response from modem failed NMEA checksum: 090,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-5

2019-05-01T00:24:30.972Z,1556670270.972 [NAL9602](INFO): SBD MO Status=2, MOMSN=3771, MT Status=2, MTMSN=0
2019-05-01T00:24:30.972Z,1556670270.972 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:24:35.478Z,1556670275.478 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-01T00:24:35.478Z,1556670275.478 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,  96.42,  95.42
2019-05-01T00:24:49.152Z,1556670289.152 [NAL9602](INFO): SBD MO Status=2, MOMSN=3771, MT Status=2, MTMSN=0
2019-05-01T00:24:49.152Z,1556670289.152 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:24:59.252Z,1556670299.252 [NAL9602](INFO): SBD MO Status=0, MOMSN=3771, MT Status=0, MTMSN=0
2019-05-01T00:24:59.252Z,1556670299.252 [NAL9602](INFO): No messages in MT queue
2019-05-01T00:25:29.954Z,1556670329.954 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-01T00:26:46.751Z,1556670406.751 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-01T00:26:46.751Z,1556670406.751 [Default:CheckIn:C.Wait] Stopped
2019-05-01T00:26:46.751Z,1556670406.751 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:26:46.751Z,1556670406.751 [Default:CheckIn:D] Running Loop=1
2019-05-01T00:26:47.148Z,1556670407.148 [Default:CheckIn:D] Stopped
2019-05-01T00:26:47.148Z,1556670407.148 [Default:CheckIn:E] Running Loop=1
2019-05-01T00:26:47.559Z,1556670407.559 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.682742 min 
2019-05-01T00:26:47.559Z,1556670407.559 [Default:CheckIn:E] Stopped
2019-05-01T00:26:47.559Z,1556670407.559 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-01T00:26:47.559Z,1556670407.559 [Default:CheckIn] Stopped
2019-05-01T00:26:47.560Z,1556670407.560 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-01T00:26:47.560Z,1556670407.560 [Default:CheckIn](INFO): Running loop #2
2019-05-01T00:26:47.560Z,1556670407.560 [Default:CheckIn] Running Loop=2
2019-05-01T00:26:47.560Z,1556670407.560 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-01T00:26:47.560Z,1556670407.560 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-01T00:26:49.153Z,1556670409.153 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:26:49.556Z,1556670409.556 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002617.00,A,3648.16712,N,12147.28350,W,0.078,101.84,010519,,,A*76
2019-05-01T00:26:49.559Z,1556670409.559 [NAL9602](INFO): GPS fix at 20190501T002617: (36.802785, -121.788058)
2019-05-01T00:26:49.605Z,1556670409.605 [Default:CheckIn:Read_GPS] Stopped
2019-05-01T00:26:49.605Z,1556670409.605 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-01T00:26:55.440Z,1556670415.440 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190501T001233/Courier0010.lzma
2019-05-01T00:26:56.226Z,1556670416.226 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Courier0010.lzma.bak
2019-05-01T00:26:56.226Z,1556670416.226 [DataOverHttps](INFO): SBD MOMSN=10877851
2019-05-01T00:27:07.822Z,1556670427.822 [DataOverHttps](INFO): Sending 606 bytes from file Logs/20190501T001233/Express0011.lzma
2019-05-01T00:27:08.626Z,1556670428.626 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0011.lzma.bak
2019-05-01T00:27:08.627Z,1556670428.627 [DataOverHttps](INFO): SBD MOMSN=10877854
2019-05-01T00:27:09.364Z,1556670429.364 [Default:CheckIn:Read_Iridium] Stopped
2019-05-01T00:27:09.364Z,1556670429.364 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-01T00:27:09.364Z,1556670429.364 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:27:09.740Z,1556670429.740 [NAL9602](INFO): SBD MO Status=0, MOMSN=3772, MT Status=0, MTMSN=0
2019-05-01T00:27:09.740Z,1556670429.740 [NAL9602](INFO): No messages in MT queue
2019-05-01T00:27:40.462Z,1556670460.462 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-01T00:29:20.235Z,1556670560.235 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,002825,AUV,2.0.2760$CAREV,002919,AUV,2.0.27690*16

2019-05-01T00:31:57.427Z,1556670717.427 [Micromodem](ERROR): Response from modem failed NMEA checksum: 39,COPROC,0.10.0.46*48

2019-05-01T00:31:57.846Z,1556670717.846 [RDI_Pathfinder](ERROR): Failed to parse:.00,   0.00,  93.93,  96.42,  95.42
2019-05-01T00:31:59.617Z,1556670719.617 [CommandLine](IMPORTANT): got command failComponent
2019-05-01T00:31:59.618Z,1556670719.618 [CommandLine](IMPORTANT): Failed components:
2019-05-01T00:31:59.618Z,1556670719.618 [CommandLine](IMPORTANT): No failed Components.
2019-05-01T00:32:09.961Z,1556670729.961 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-01T00:32:09.961Z,1556670729.961 [Default:CheckIn:C.Wait] Stopped
2019-05-01T00:32:09.961Z,1556670729.961 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:32:09.961Z,1556670729.961 [Default:CheckIn:D] Running Loop=1
2019-05-01T00:32:10.370Z,1556670730.370 [Default:CheckIn:D] Stopped
2019-05-01T00:32:10.370Z,1556670730.370 [Default:CheckIn:E] Running Loop=1
2019-05-01T00:32:10.783Z,1556670730.783 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.069772 min 
2019-05-01T00:32:10.783Z,1556670730.783 [Default:CheckIn:E] Stopped
2019-05-01T00:32:10.784Z,1556670730.784 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-01T00:32:10.784Z,1556670730.784 [Default:CheckIn] Stopped
2019-05-01T00:32:10.784Z,1556670730.784 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-01T00:32:10.784Z,1556670730.784 [Default:CheckIn](INFO): Running loop #3
2019-05-01T00:32:10.784Z,1556670730.784 [Default:CheckIn] Running Loop=3
2019-05-01T00:32:10.784Z,1556670730.784 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-01T00:32:10.784Z,1556670730.784 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-01T00:32:12.373Z,1556670732.373 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:32:12.769Z,1556670732.769 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,003140.00,A,3648.16870,N,12147.28230,W,0.330,101.84,010519,,,A*71
2019-05-01T00:32:12.771Z,1556670732.771 [NAL9602](INFO): GPS fix at 20190501T003140: (36.802812, -121.788038)
2019-05-01T00:32:12.810Z,1556670732.810 [Default:CheckIn:Read_GPS] Stopped
2019-05-01T00:32:12.811Z,1556670732.811 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-01T00:32:18.421Z,1556670738.421 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190501T001233/Courier0013.lzma
2019-05-01T00:32:19.226Z,1556670739.226 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Courier0013.lzma.bak
2019-05-01T00:32:19.226Z,1556670739.226 [DataOverHttps](INFO): SBD MOMSN=10877874
2019-05-01T00:32:31.141Z,1556670751.141 [DataOverHttps](INFO): Sending 620 bytes from file Logs/20190501T001233/Express0014.lzma
2019-05-01T00:32:31.946Z,1556670751.946 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0014.lzma.bak
2019-05-01T00:32:31.947Z,1556670751.947 [DataOverHttps](INFO): SBD MOMSN=10877877
2019-05-01T00:32:32.625Z,1556670752.625 [Default:CheckIn:Read_Iridium] Stopped
2019-05-01T00:32:32.625Z,1556670752.625 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-01T00:32:32.625Z,1556670752.625 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:32:53.592Z,1556670773.592 [NAL9602](INFO): SBD MO Status=2, MOMSN=3773, MT Status=2, MTMSN=0
2019-05-01T00:32:53.592Z,1556670773.592 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:33:01.766Z,1556670781.766 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:01.766Z,1556670781.766 [Micromodem] Hardware Fault, FailCount= 2
2019-05-01T00:33:01.766Z,1556670781.766 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:33:01.766Z,1556670781.766 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:02.074Z,1556670782.074 [Micromodem](INFO): Powering down
2019-05-01T00:33:02.209Z,1556670782.209 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:33:02.494Z,1556670782.494 [Micromodem](FAULT): LCB 2 fault:  Software Overcurrent.
2019-05-01T00:33:02.706Z,1556670782.706 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:02.706Z,1556670782.706 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:02.927Z,1556670782.927 [CBIT](INFO): Clearing failed state for component Micromodem
2019-05-01T00:33:02.927Z,1556670782.927 [Micromodem] No Fault, FailCount= 2
2019-05-01T00:33:03.042Z,1556670783.042 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:03.042Z,1556670783.042 [Micromodem] Hardware Fault, FailCount= 3
2019-05-01T00:33:03.042Z,1556670783.042 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:33:03.042Z,1556670783.042 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:03.370Z,1556670783.370 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:33:03.371Z,1556670783.371 [CBIT](INFO): Clearing failed state for component Micromodem
2019-05-01T00:33:03.371Z,1556670783.371 [Micromodem] No Fault, FailCount= 3
2019-05-01T00:33:03.394Z,1556670783.394 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:03.394Z,1556670783.394 [Micromodem] Hardware Fault, FailCount= 4
2019-05-01T00:33:03.394Z,1556670783.394 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:33:03.394Z,1556670783.394 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:03.726Z,1556670783.726 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:03.726Z,1556670783.726 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:03.755Z,1556670783.755 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:33:03.755Z,1556670783.755 [CBIT](INFO): Clearing failed state for component Micromodem
2019-05-01T00:33:03.755Z,1556670783.755 [Micromodem] No Fault, FailCount= 4
2019-05-01T00:33:03.994Z,1556670783.994 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:03.994Z,1556670783.994 [Micromodem] Hardware Fault, FailCount= 5
2019-05-01T00:33:03.994Z,1556670783.994 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:33:03.994Z,1556670783.994 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:04.126Z,1556670784.126 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:33:04.126Z,1556670784.126 [CBIT](INFO): Clearing failed state for component Micromodem
2019-05-01T00:33:04.126Z,1556670784.126 [Micromodem] No Fault, FailCount= 5
2019-05-01T00:33:05.170Z,1556670785.170 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:05.170Z,1556670785.170 [Micromodem] Hardware Fault, FailCount= 6
2019-05-01T00:33:05.170Z,1556670785.170 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:33:05.170Z,1556670785.170 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:05.322Z,1556670785.322 [Micromodem](INFO): Powering down
2019-05-01T00:33:05.384Z,1556670785.384 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:33:05.562Z,1556670785.562 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:05.562Z,1556670785.562 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:05.717Z,1556670785.717 [Micromodem](FAULT): LCB 2 fault:  Software Overcurrent.
2019-05-01T00:33:05.834Z,1556670785.834 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:05.835Z,1556670785.835 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:06.058Z,1556670786.058 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:06.058Z,1556670786.058 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:06.181Z,1556670786.181 [CBIT](INFO): Clearing failed state for component Micromodem
2019-05-01T00:33:06.181Z,1556670786.181 [Micromodem] No Fault, FailCount= 6
2019-05-01T00:33:06.306Z,1556670786.306 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:06.306Z,1556670786.306 [Micromodem] Hardware Fault, FailCount= 7
2019-05-01T00:33:06.306Z,1556670786.306 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:33:06.306Z,1556670786.306 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:06.586Z,1556670786.586 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:06.586Z,1556670786.586 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:06.595Z,1556670786.595 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:33:06.595Z,1556670786.595 [CBIT](INFO): Clearing failed state for component Micromodem
2019-05-01T00:33:06.595Z,1556670786.595 [Micromodem] No Fault, FailCount= 7
2019-05-01T00:33:07.328Z,1556670787.328 [NAL9602](INFO): SBD MO Status=2, MOMSN=3773, MT Status=2, MTMSN=0
2019-05-01T00:33:07.328Z,1556670787.328 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:33:08.551Z,1556670788.551 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:08.551Z,1556670788.551 [Micromodem] Hardware Fault, FailCount= 8
2019-05-01T00:33:08.551Z,1556670788.551 [Micromodem](ERROR): Hardware Fault
2019-05-01T00:33:08.552Z,1556670788.552 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:08.591Z,1556670788.591 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-05-01T00:33:08.592Z,1556670788.592 [CBIT](FAULT): Hardware Fault in component: Micromodem
2019-05-01T00:33:08.862Z,1556670788.862 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:08.862Z,1556670788.862 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:08.938Z,1556670788.938 [Micromodem](INFO): Powering down
2019-05-01T00:33:09.122Z,1556670789.122 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:09.122Z,1556670789.122 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:09.370Z,1556670789.370 [Micromodem](FAULT): LCB 2 fault:  Software Overcurrent.
2019-05-01T00:33:09.378Z,1556670789.378 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:09.379Z,1556670789.379 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:09.614Z,1556670789.614 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-05-01T00:33:09.614Z,1556670789.614 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-05-01T00:33:14.879Z,1556670794.879 [CommandLine](IMPORTANT): got command failComponent
2019-05-01T00:33:14.879Z,1556670794.879 [CommandLine](IMPORTANT): Failed components:
2019-05-01T00:33:14.879Z,1556670794.879 [CommandLine](IMPORTANT): Micromodem: Hardware Fault
2019-05-01T00:34:13.176Z,1556670853.176 [NAL9602](INFO): SBD MO Status=0, MOMSN=3773, MT Status=0, MTMSN=0
2019-05-01T00:34:13.176Z,1556670853.176 [NAL9602](INFO): No messages in MT queue
2019-05-01T00:34:43.894Z,1556670883.894 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-01T00:34:44.978Z,1556670884.978 [CommandLine](IMPORTANT): got command failComponent
2019-05-01T00:34:44.979Z,1556670884.979 [CommandLine](IMPORTANT): Failed components:
2019-05-01T00:34:44.979Z,1556670884.979 [CommandLine](IMPORTANT): Micromodem: Hardware Fault
2019-05-01T00:34:48.322Z,1556670888.322 [CommandLine](IMPORTANT): got command failComponent none Micromodem
2019-05-01T00:34:48.322Z,1556670888.322 [Micromodem] No Fault, FailCount= 8
2019-05-01T00:34:48.322Z,1556670888.322 [CommandLine](IMPORTANT): Micromodem failureMode is No Fault
2019-05-01T00:34:48.726Z,1556670888.726 [Micromodem](INFO): Powering up
2019-05-01T00:34:48.726Z,1556670888.726 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-01T00:34:53.576Z,1556670893.576 [Micromodem](DEBUG): Nmea buf: $CCCFG,ALL,0*33

2019-05-01T00:34:53.577Z,1556670893.577 [Micromodem](DEBUG): Nmea buf: $CCCFG,SRC,1*31

2019-05-01T00:34:53.579Z,1556670893.579 [Micromodem](DEBUG): Nmea buf: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-01T00:34:53.580Z,1556670893.580 [Micromodem](DEBUG): Nmea buf: $CCCFG,BND,1*3B

2019-05-01T00:35:13.562Z,1556670913.562 [CommandLine](IMPORTANT): got command get Onboard.Humidity
2019-05-01T00:35:13.562Z,1556670913.562 [CommandLine](IMPORTANT): Onboard.Humidity 12.312294 %
2019-05-01T00:35:24.282Z,1556670924.282 [Micromodem](ERROR): Nmea resend: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-01T00:35:35.594Z,1556670935.594 [Micromodem](ERROR): Nmea resend: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-01T00:35:46.906Z,1556670946.906 [Micromodem](ERROR): Nmea resend: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-01T00:35:50.539Z,1556670950.539 [Micromodem](DEBUG): Nmea buf: $CCTMS,2019-05-01T00:35:51Z,0*78

2019-05-01T00:36:20.476Z,1556670980.476 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-01T00:36:20.476Z,1556670980.476 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   +4,    +0,A
2019-05-01T00:37:33.192Z,1556671053.192 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-01T00:37:33.193Z,1556671053.193 [Default:CheckIn:C.Wait] Stopped
2019-05-01T00:37:33.193Z,1556671053.193 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:37:33.193Z,1556671053.193 [Default:CheckIn:D] Running Loop=1
2019-05-01T00:37:33.607Z,1556671053.607 [Default:CheckIn:D] Stopped
2019-05-01T00:37:33.607Z,1556671053.607 [Default:CheckIn:E] Running Loop=1
2019-05-01T00:37:33.996Z,1556671053.996 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.457048 min 
2019-05-01T00:37:33.996Z,1556671053.996 [Default:CheckIn:E] Stopped
2019-05-01T00:37:33.996Z,1556671053.996 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-01T00:37:33.996Z,1556671053.996 [Default:CheckIn] Stopped
2019-05-01T00:37:33.997Z,1556671053.997 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-01T00:37:33.997Z,1556671053.997 [Default:CheckIn](INFO): Running loop #4
2019-05-01T00:37:33.997Z,1556671053.997 [Default:CheckIn] Running Loop=4
2019-05-01T00:37:33.997Z,1556671053.997 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-01T00:37:33.997Z,1556671053.997 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-01T00:37:35.597Z,1556671055.597 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:37:35.988Z,1556671055.988 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,003703.00,A,3648.16789,N,12147.27656,W,0.350,101.84,010519,,,A*74
2019-05-01T00:37:35.990Z,1556671055.990 [NAL9602](INFO): GPS fix at 20190501T003703: (36.802798, -121.787943)
2019-05-01T00:37:36.015Z,1556671056.015 [Default:CheckIn:Read_GPS] Stopped
2019-05-01T00:37:36.015Z,1556671056.015 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-01T00:37:41.756Z,1556671061.756 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190501T001233/Courier0016.lzma
2019-05-01T00:37:42.562Z,1556671062.562 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Courier0016.lzma.bak
2019-05-01T00:37:42.563Z,1556671062.563 [DataOverHttps](INFO): SBD MOMSN=10877910
2019-05-01T00:37:54.030Z,1556671074.030 [DataOverHttps](INFO): Sending 978 bytes from file Logs/20190501T001233/Express0017.lzma
2019-05-01T00:37:54.834Z,1556671074.834 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0017.lzma.bak
2019-05-01T00:37:54.835Z,1556671074.835 [DataOverHttps](INFO): SBD MOMSN=10877913
2019-05-01T00:37:55.420Z,1556671075.420 [Default:CheckIn:Read_Iridium] Stopped
2019-05-01T00:37:55.420Z,1556671075.420 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-01T00:37:55.420Z,1556671075.420 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:38:02.256Z,1556671082.256 [NAL9602](INFO): SBD MO Status=2, MOMSN=3774, MT Status=2, MTMSN=0
2019-05-01T00:38:02.256Z,1556671082.256 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-01T00:41:38.846Z,1556671298.846 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-01T00:41:38.846Z,1556671298.846 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,  95.42,  95.42
2019-05-01T00:42:37.783Z,1556671357.783 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-01T00:42:56.002Z,1556671376.002 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-01T00:42:56.002Z,1556671376.002 [Default:CheckIn:C.Wait] Stopped
2019-05-01T00:42:56.002Z,1556671376.002 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:42:56.002Z,1556671376.002 [Default:CheckIn:D] Running Loop=1
2019-05-01T00:42:56.418Z,1556671376.418 [Default:CheckIn:D] Stopped
2019-05-01T00:42:56.418Z,1556671376.418 [Default:CheckIn:E] Running Loop=1
2019-05-01T00:42:56.824Z,1556671376.824 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.837248 min 
2019-05-01T00:42:56.824Z,1556671376.824 [Default:CheckIn:E] Stopped
2019-05-01T00:42:56.824Z,1556671376.824 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-01T00:42:56.824Z,1556671376.824 [Default:CheckIn] Stopped
2019-05-01T00:42:56.825Z,1556671376.825 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-01T00:42:56.825Z,1556671376.825 [Default:CheckIn](INFO): Running loop #5
2019-05-01T00:42:56.825Z,1556671376.825 [Default:CheckIn] Running Loop=5
2019-05-01T00:42:56.825Z,1556671376.825 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-01T00:42:56.825Z,1556671376.825 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-01T00:42:58.405Z,1556671378.405 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:42:58.805Z,1556671378.805 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004226.00,A,3648.17036,N,12147.28286,W,0.233,0.00,010519,,,A*7D
2019-05-01T00:42:58.807Z,1556671378.807 [NAL9602](INFO): GPS fix at 20190501T004226: (36.802839, -121.788048)
2019-05-01T00:42:58.839Z,1556671378.839 [Default:CheckIn:Read_GPS] Stopped
2019-05-01T00:42:58.839Z,1556671378.839 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-01T00:43:04.481Z,1556671384.481 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190501T001233/Courier0019.lzma
2019-05-01T00:43:05.286Z,1556671385.286 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Courier0019.lzma.bak
2019-05-01T00:43:05.287Z,1556671385.287 [DataOverHttps](INFO): SBD MOMSN=10877981
2019-05-01T00:43:16.734Z,1556671396.734 [DataOverHttps](INFO): Sending 681 bytes from file Logs/20190501T001233/Express0020.lzma
2019-05-01T00:43:17.538Z,1556671397.538 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0020.lzma.bak
2019-05-01T00:43:17.539Z,1556671397.539 [DataOverHttps](INFO): SBD MOMSN=10877984
2019-05-01T00:43:18.220Z,1556671398.220 [Default:CheckIn:Read_Iridium] Stopped
2019-05-01T00:43:18.220Z,1556671398.220 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-01T00:43:18.220Z,1556671398.220 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:43:21.846Z,1556671401.846 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-01T00:43:21.846Z,1556671401.846 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,  96.42,  95.42
2019-05-01T00:43:30.718Z,1556671410.718 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-01T00:44:41.836Z,1556671481.836 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-01T00:44:41.836Z,1556671481.836 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19043017531383,35.0, -0.1,   0.0,144

2019-05-01T00:44:44.679Z,1556671484.679 [RDI_Pathfinder](ERROR): Failed to parse:
   -2.30,        +0.68,        +0.29,   9.57,  0.00
2019-05-01T00:46:09.810Z,1556671569.810 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:46:09.810Z,1556671569.810 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:46:09.852Z,1556671569.852 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-01T00:46:09.854Z,1556671569.854 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-01T00:46:09.857Z,1556671569.857 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-01T00:46:09.859Z,1556671569.859 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-01T00:46:09.861Z,1556671569.861 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-01T00:46:09.862Z,1556671569.862 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-01T00:46:09.866Z,1556671569.866 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-01T00:46:09.895Z,1556671569.895 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-01T00:46:09.956Z,1556671569.956 [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-01T00:46:09.959Z,1556671569.959 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:46:10.324Z,1556671570.324 [Default] Stopped
2019-05-01T00:46:10.324Z,1556671570.324 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-01T00:46:10.324Z,1556671570.324 [Default:B.GoToSurface] Stopped
2019-05-01T00:46:10.324Z,1556671570.324 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-01T00:46:10.324Z,1556671570.324 [Default:CheckIn] Stopped
2019-05-01T00:46:10.324Z,1556671570.324 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-01T00:46:10.324Z,1556671570.324 [Default:CheckIn:C.Wait] Stopped
2019-05-01T00:46:10.324Z,1556671570.324 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:46:10.324Z,1556671570.324 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-01T00:46:10.325Z,1556671570.325 [DUSBL] Running Loop=1
2019-05-01T00:46:10.325Z,1556671570.325 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-01T00:46:10.325Z,1556671570.325 [DUSBL:A.Pitch] Running Loop=1
2019-05-01T00:46:10.325Z,1556671570.325 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-01T00:46:10.325Z,1556671570.325 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-01T00:46:10.325Z,1556671570.325 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-01T00:46:10.325Z,1556671570.325 [DUSBL:C] Running Loop=1
2019-05-01T00:46:10.326Z,1556671570.326 [DUSBL:RequestRepeater] Running Loop=1
2019-05-01T00:46:10.326Z,1556671570.326 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:46:10.326Z,1556671570.326 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:46:10.326Z,1556671570.326 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:46:10.326Z,1556671570.326 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:46:10.326Z,1556671570.326 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:46:10.327Z,1556671570.327 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:46:10.327Z,1556671570.327 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:46:10.328Z,1556671570.328 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-01T00:46:10.328Z,1556671570.328 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-01T00:46:10.328Z,1556671570.328 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-01T00:46:10.328Z,1556671570.328 [DUSBL:A.Pitch] Running Loop=1
2019-05-01T00:46:11.915Z,1556671571.915 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:11.919Z,1556671571.919 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:14.739Z,1556671574.739 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:14.740Z,1556671574.740 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:17.971Z,1556671577.971 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:17.977Z,1556671577.977 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:20.419Z,1556671580.419 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:46:20.420Z,1556671580.420 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:46:20.420Z,1556671580.420 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:46:20.420Z,1556671580.420 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:46:20.420Z,1556671580.420 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:46:20.420Z,1556671580.420 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:46:20.420Z,1556671580.420 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:46:20.420Z,1556671580.420 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:46:20.421Z,1556671580.421 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-01T00:46:20.421Z,1556671580.421 [DUSBL:RequestRepeater] Running Loop=2
2019-05-01T00:46:20.421Z,1556671580.421 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:46:20.421Z,1556671580.421 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:46:20.421Z,1556671580.421 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:46:20.421Z,1556671580.421 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:46:20.421Z,1556671580.421 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:46:20.799Z,1556671580.799 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:20.803Z,1556671580.803 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:21.206Z,1556671581.206 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,E0E,80,81,04,FF
2019-05-01T00:46:24.847Z,1556671584.847 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:24.852Z,1556671584.852 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:25.647Z,1556671585.647 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:25.652Z,1556671585.652 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:26.051Z,1556671586.051 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:46:26.053Z,1556671586.053 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,004624.58*57

2019-05-01T00:46:29.687Z,1556671589.687 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:29.692Z,1556671589.692 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:30.094Z,1556671590.094 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,189,80,81,05,FF
2019-05-01T00:46:30.932Z,1556671590.932 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:46:30.932Z,1556671590.932 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:46:30.932Z,1556671590.932 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:46:30.933Z,1556671590.933 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:46:30.933Z,1556671590.933 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:46:30.933Z,1556671590.933 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:46:30.933Z,1556671590.933 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:46:30.933Z,1556671590.933 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:46:30.933Z,1556671590.933 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-01T00:46:30.933Z,1556671590.933 [DUSBL:RequestRepeater] Running Loop=3
2019-05-01T00:46:30.934Z,1556671590.934 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:46:30.934Z,1556671590.934 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:46:30.934Z,1556671590.934 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:46:30.934Z,1556671590.934 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:46:30.934Z,1556671590.934 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:46:33.724Z,1556671593.724 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:33.728Z,1556671593.728 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:34.135Z,1556671594.135 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,18A,80,81,04,FF
2019-05-01T00:46:37.776Z,1556671597.776 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:37.779Z,1556671597.779 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:38.171Z,1556671598.171 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,187,80,81,07,FF
2019-05-01T00:46:41.454Z,1556671601.454 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:46:41.455Z,1556671601.455 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:46:41.455Z,1556671601.455 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:46:41.457Z,1556671601.457 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:46:41.458Z,1556671601.458 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:46:41.458Z,1556671601.458 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:46:41.458Z,1556671601.458 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:46:41.458Z,1556671601.458 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:46:41.459Z,1556671601.459 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-01T00:46:41.459Z,1556671601.459 [DUSBL:RequestRepeater] Running Loop=4
2019-05-01T00:46:41.460Z,1556671601.460 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:46:41.460Z,1556671601.460 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:46:41.460Z,1556671601.460 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:46:41.461Z,1556671601.461 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:46:41.461Z,1556671601.461 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:46:41.806Z,1556671601.806 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:41.808Z,1556671601.808 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:44.635Z,1556671604.635 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:44.639Z,1556671604.639 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:45.042Z,1556671605.042 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,0A,FF
2019-05-01T00:46:48.682Z,1556671608.682 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:48.686Z,1556671608.686 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:49.079Z,1556671609.079 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,EBF,000,0031,FF
2019-05-01T00:46:51.944Z,1556671611.944 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:46:51.944Z,1556671611.944 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:46:51.944Z,1556671611.944 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:46:51.949Z,1556671611.949 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:46:51.949Z,1556671611.949 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:46:51.949Z,1556671611.949 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:46:51.949Z,1556671611.949 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:46:51.949Z,1556671611.949 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:46:51.950Z,1556671611.950 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-01T00:46:51.950Z,1556671611.950 [DUSBL:RequestRepeater] Running Loop=5
2019-05-01T00:46:51.950Z,1556671611.950 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:46:51.950Z,1556671611.950 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:46:51.950Z,1556671611.950 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:46:51.950Z,1556671611.950 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:46:51.950Z,1556671611.950 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:46:52.714Z,1556671612.714 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:52.716Z,1556671612.716 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:53.119Z,1556671613.119 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,08,FF
2019-05-01T00:46:56.755Z,1556671616.755 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:46:56.759Z,1556671616.759 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:46:57.170Z,1556671617.170 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !0000,187,80,81,04,FF
2019-05-01T00:47:00.799Z,1556671620.799 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:00.803Z,1556671620.803 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:02.480Z,1556671622.480 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:47:02.480Z,1556671622.480 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:47:02.480Z,1556671622.480 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:47:02.481Z,1556671622.481 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:47:02.481Z,1556671622.481 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater] Running Loop=6
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:47:02.482Z,1556671622.482 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:47:03.627Z,1556671623.627 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:03.632Z,1556671623.632 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:04.030Z,1556671624.030 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,09,FF
2019-05-01T00:47:07.663Z,1556671627.663 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:07.667Z,1556671627.667 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:10.492Z,1556671630.492 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:10.495Z,1556671630.495 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:10.894Z,1556671630.894 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,186,80,81,08,FF
2019-05-01T00:47:12.944Z,1556671632.944 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:47:12.944Z,1556671632.944 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:47:12.944Z,1556671632.944 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:47:12.961Z,1556671632.961 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:47:12.961Z,1556671632.961 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:47:12.961Z,1556671632.961 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater] Running Loop=7
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:47:12.962Z,1556671632.962 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:47:14.531Z,1556671634.531 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:14.536Z,1556671634.536 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:14.942Z,1556671634.942 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,186,80,81,04,FF
2019-05-01T00:47:18.575Z,1556671638.575 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:18.579Z,1556671638.579 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:19.383Z,1556671639.383 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:19.388Z,1556671639.388 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:19.787Z,1556671639.787 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:47:19.788Z,1556671639.788 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,004718.31*56

2019-05-01T00:47:23.420Z,1556671643.420 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:23.425Z,1556671643.425 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:23.512Z,1556671643.512 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:47:23.512Z,1556671643.512 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:47:23.512Z,1556671643.512 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:47:23.517Z,1556671643.517 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:47:23.517Z,1556671643.517 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater] Running Loop=8
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:47:23.518Z,1556671643.518 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:47:23.823Z,1556671643.823 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !0000,186,80,81,04,FF
2019-05-01T00:47:27.483Z,1556671647.483 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:27.489Z,1556671647.489 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:27.862Z,1556671647.862 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,187,80,81,04,FF
2019-05-01T00:47:31.499Z,1556671651.499 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:31.504Z,1556671651.504 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:31.906Z,1556671651.906 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,EFB,000,0006,FF
2019-05-01T00:47:33.962Z,1556671653.962 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:47:33.962Z,1556671653.962 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:47:33.962Z,1556671653.962 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:47:33.962Z,1556671653.962 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater] Running Loop=9
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:47:33.963Z,1556671653.963 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:47:35.547Z,1556671655.547 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:35.551Z,1556671655.551 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:35.944Z,1556671655.944 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,0A,FF
2019-05-01T00:47:39.583Z,1556671659.583 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:39.587Z,1556671659.587 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:39.990Z,1556671659.990 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-01T00:47:40.387Z,1556671660.387 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:40.392Z,1556671660.392 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:40.791Z,1556671660.791 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:47:40.793Z,1556671660.793 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,004739.32*56

2019-05-01T00:47:44.432Z,1556671664.432 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:44.437Z,1556671664.437 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:44.528Z,1556671664.528 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:47:44.528Z,1556671664.528 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:47:44.528Z,1556671664.528 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater] Running Loop=10
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:47:44.530Z,1556671664.530 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:47:44.531Z,1556671664.531 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:47:44.531Z,1556671664.531 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:47:44.831Z,1556671664.831 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,188,80,81,05,FF
2019-05-01T00:47:48.479Z,1556671668.479 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:48.484Z,1556671668.484 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:48.871Z,1556671668.871 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,06,FF
2019-05-01T00:47:52.507Z,1556671672.507 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:47:52.511Z,1556671672.511 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:47:52.915Z,1556671672.915 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,185,80,81,05,FF
2019-05-01T00:47:54.958Z,1556671674.958 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:47:54.958Z,1556671674.958 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:47:54.958Z,1556671674.958 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:47:54.959Z,1556671674.959 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:47:54.959Z,1556671674.959 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:47:54.959Z,1556671674.959 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:47:54.959Z,1556671674.959 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:47:54.959Z,1556671674.959 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:47:54.959Z,1556671674.959 [DUSBL](INFO): Completed DUSBL
2019-05-01T00:47:54.960Z,1556671674.960 [MissionManager](INFO): DUSBL is completed.
2019-05-01T00:47:54.960Z,1556671674.960 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-01T00:47:54.960Z,1556671674.960 [DUSBL] Stopped
2019-05-01T00:47:54.960Z,1556671674.960 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-01T00:47:54.960Z,1556671674.960 [DUSBL:A.Pitch] Stopped
2019-05-01T00:47:54.960Z,1556671674.960 [DUSBL:B.SetSpeed] Stopped
2019-05-01T00:47:54.960Z,1556671674.960 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-01T00:47:54.960Z,1556671674.960 [DUSBL:C] Stopped
2019-05-01T00:47:55.360Z,1556671675.360 [MissionManager](IMPORTANT): Started mission Default
2019-05-01T00:47:55.360Z,1556671675.360 [Default] Running Loop=1
2019-05-01T00:47:55.360Z,1556671675.360 [Default](DEBUG): Aggregate::initialize Default
2019-05-01T00:47:55.360Z,1556671675.360 [Default:B.GoToSurface] Running Loop=1
2019-05-01T00:47:55.360Z,1556671675.360 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-01T00:47:55.361Z,1556671675.361 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-01T00:47:55.361Z,1556671675.361 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-01T00:47:55.361Z,1556671675.361 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-01T00:47:55.362Z,1556671675.362 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-01T00:47:55.362Z,1556671675.362 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-01T00:47:55.362Z,1556671675.362 [Default:A.Wait] Running Loop=1
2019-05-01T00:47:55.362Z,1556671675.362 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:48:08.724Z,1556671688.724 [Default:A.Wait](INFO): Done Waiting.
2019-05-01T00:48:08.724Z,1556671688.724 [Default:A.Wait] Stopped
2019-05-01T00:48:08.724Z,1556671688.724 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:48:09.104Z,1556671689.104 [Default:CheckIn] Running Loop=1
2019-05-01T00:48:09.104Z,1556671689.104 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-01T00:48:09.104Z,1556671689.104 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-01T00:48:10.705Z,1556671690.705 [NAL9602](DEBUG): Fix Requested
2019-05-01T00:48:11.107Z,1556671691.107 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004738.00,A,3648.16803,N,12147.28453,W,0.855,0.00,010519,,,A*7C
2019-05-01T00:48:11.109Z,1556671691.109 [NAL9602](INFO): GPS fix at 20190501T004738: (36.802801, -121.788076)
2019-05-01T00:48:11.133Z,1556671691.133 [Default:CheckIn:Read_GPS] Stopped
2019-05-01T00:48:11.133Z,1556671691.133 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-01T00:48:16.652Z,1556671696.652 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190501T001233/Courier0022.lzma
2019-05-01T00:48:17.462Z,1556671697.462 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Courier0022.lzma.bak
2019-05-01T00:48:17.462Z,1556671697.462 [DataOverHttps](INFO): SBD MOMSN=10878008
2019-05-01T00:48:29.005Z,1556671709.005 [DataOverHttps](INFO): Sending 673 bytes from file Logs/20190501T001233/Express0023.lzma
2019-05-01T00:48:29.810Z,1556671709.810 [DataOverHttps](INFO): Moved sent file to Logs/20190501T001233/Express0023.lzma.bak
2019-05-01T00:48:29.811Z,1556671709.811 [DataOverHttps](INFO): SBD MOMSN=10878011
2019-05-01T00:48:30.524Z,1556671710.524 [Default:CheckIn:Read_Iridium] Stopped
2019-05-01T00:48:30.524Z,1556671710.524 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-01T00:48:30.524Z,1556671710.524 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:48:41.793Z,1556671721.793 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-01T00:48:41.869Z,1556671721.869 [NAL9602](FAULT): received: 
+CSQ:1

OK74, 2, 0, 0, 0

OK
2019-05-01T00:48:41.869Z,1556671721.869 [NAL9602] Data Fault, FailCount= 1
2019-05-01T00:48:41.869Z,1556671721.869 [NAL9602](ERROR): Data Fault
2019-05-01T00:48:41.917Z,1556671721.917 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-01T00:48:42.199Z,1556671722.199 [NAL9602](INFO): Powering down
2019-05-01T00:48:43.050Z,1556671723.050 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-01T00:48:43.050Z,1556671723.050 [NAL9602] No Fault, FailCount= 1
2019-05-01T00:49:05.671Z,1556671745.671 [RDI_Pathfinder](ERROR): Failed to parse:
   -3.84,        +1.30,        +0.05,   9.53,  0.00
2019-05-01T00:49:12.503Z,1556671752.503 [NAL9602](INFO): Powering up NAL9602
2019-05-01T00:49:23.411Z,1556671763.411 [NAL9602](INFO): NAL9602 initialized
2019-05-01T00:49:54.519Z,1556671794.519 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-01T00:50:46.831Z,1556671846.831 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:50:46.831Z,1556671846.831 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:50:46.856Z,1556671846.856 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-01T00:50:46.858Z,1556671846.858 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-01T00:50:46.860Z,1556671846.860 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-01T00:50:46.864Z,1556671846.864 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-01T00:50:46.870Z,1556671846.870 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-01T00:50:46.871Z,1556671846.871 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-01T00:50:46.875Z,1556671846.875 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-01T00:50:46.926Z,1556671846.926 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-01T00:50:46.930Z,1556671846.930 [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-01T00:50:46.932Z,1556671846.932 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-01T00:50:47.064Z,1556671847.064 [Default] Stopped
2019-05-01T00:50:47.064Z,1556671847.064 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-01T00:50:47.064Z,1556671847.064 [Default:B.GoToSurface] Stopped
2019-05-01T00:50:47.064Z,1556671847.064 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-01T00:50:47.064Z,1556671847.064 [Default:CheckIn] Stopped
2019-05-01T00:50:47.064Z,1556671847.064 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-01T00:50:47.064Z,1556671847.064 [Default:CheckIn:C.Wait] Stopped
2019-05-01T00:50:47.064Z,1556671847.064 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:50:47.064Z,1556671847.064 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-01T00:50:47.065Z,1556671847.065 [DUSBL] Running Loop=1
2019-05-01T00:50:47.065Z,1556671847.065 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-01T00:50:47.065Z,1556671847.065 [DUSBL:A.Pitch] Running Loop=1
2019-05-01T00:50:47.065Z,1556671847.065 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-01T00:50:47.065Z,1556671847.065 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-01T00:50:47.065Z,1556671847.065 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-01T00:50:47.065Z,1556671847.065 [DUSBL:C] Running Loop=1
2019-05-01T00:50:47.066Z,1556671847.066 [DUSBL:RequestRepeater] Running Loop=1
2019-05-01T00:50:47.066Z,1556671847.066 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:50:47.066Z,1556671847.066 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:50:47.066Z,1556671847.066 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:50:47.066Z,1556671847.066 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:50:47.066Z,1556671847.066 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:50:47.067Z,1556671847.067 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:50:47.067Z,1556671847.067 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:50:47.068Z,1556671847.068 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-01T00:50:47.068Z,1556671847.068 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-01T00:50:47.068Z,1556671847.068 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-01T00:50:47.068Z,1556671847.068 [DUSBL:A.Pitch] Running Loop=1
2019-05-01T00:50:48.655Z,1556671848.655 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:50:48.673Z,1556671848.673 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:50:49.055Z,1556671849.055 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,06,FF
2019-05-01T00:50:52.691Z,1556671852.691 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:50:52.698Z,1556671852.698 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:50:53.094Z,1556671853.094 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !0000,187,80,81,07,FF
2019-05-01T00:50:56.731Z,1556671856.731 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:50:56.736Z,1556671856.736 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:50:57.165Z,1556671857.165 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:50:57.165Z,1556671857.165 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:50:57.165Z,1556671857.165 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:50:57.166Z,1556671857.166 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:50:57.166Z,1556671857.166 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:50:57.166Z,1556671857.166 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:50:57.166Z,1556671857.166 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:50:57.166Z,1556671857.166 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:50:57.166Z,1556671857.166 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-01T00:50:57.167Z,1556671857.167 [DUSBL:RequestRepeater] Running Loop=2
2019-05-01T00:50:57.167Z,1556671857.167 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:50:57.167Z,1556671857.167 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:50:57.167Z,1556671857.167 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:50:57.167Z,1556671857.167 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:50:57.167Z,1556671857.167 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:50:57.538Z,1556671857.538 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:50:57.540Z,1556671857.540 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:50:57.943Z,1556671857.943 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:50:57.944Z,1556671857.944 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,005056.46*5A

2019-05-01T00:51:01.579Z,1556671861.579 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:01.583Z,1556671861.583 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:01.983Z,1556671861.983 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,0B,FF
2019-05-01T00:51:05.635Z,1556671865.635 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:05.645Z,1556671865.645 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:06.026Z,1556671866.026 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,18A,80,81,05,FF
2019-05-01T00:51:07.675Z,1556671867.675 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:51:07.675Z,1556671867.675 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:51:07.675Z,1556671867.675 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater] Running Loop=3
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:51:07.676Z,1556671867.676 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:51:07.677Z,1556671867.677 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:51:07.677Z,1556671867.677 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:51:07.677Z,1556671867.677 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:51:09.659Z,1556671869.659 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:09.664Z,1556671869.664 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:10.475Z,1556671870.475 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:10.482Z,1556671870.482 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:10.892Z,1556671870.892 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:51:10.898Z,1556671870.898 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,005109.39*59

2019-05-01T00:51:11.274Z,1556671871.274 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:15.315Z,1556671875.315 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:15.319Z,1556671875.319 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:15.718Z,1556671875.718 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,0,189,80,81,04,FF
2019-05-01T00:51:18.180Z,1556671878.180 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:51:18.180Z,1556671878.180 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:51:18.180Z,1556671878.180 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:51:18.181Z,1556671878.181 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:51:18.181Z,1556671878.181 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:51:18.181Z,1556671878.181 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:51:18.181Z,1556671878.181 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:51:18.181Z,1556671878.181 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:51:18.182Z,1556671878.182 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-01T00:51:18.182Z,1556671878.182 [DUSBL:RequestRepeater] Running Loop=4
2019-05-01T00:51:18.182Z,1556671878.182 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:51:18.182Z,1556671878.182 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:51:18.182Z,1556671878.182 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:51:18.182Z,1556671878.182 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:51:18.182Z,1556671878.182 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:51:19.355Z,1556671879.355 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:19.360Z,1556671879.360 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:20.167Z,1556671880.167 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:20.172Z,1556671880.172 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:20.567Z,1556671880.567 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:51:20.569Z,1556671880.569 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,005119.09*5B

2019-05-01T00:51:24.204Z,1556671884.204 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:24.208Z,1556671884.208 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:24.606Z,1556671884.606 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,187,80,81,04,FF
2019-05-01T00:51:28.242Z,1556671888.242 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:28.243Z,1556671888.243 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:28.655Z,1556671888.655 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U100,187,80,81,08,FF
2019-05-01T00:51:28.721Z,1556671888.721 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:51:28.721Z,1556671888.721 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:51:28.721Z,1556671888.721 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater] Running Loop=5
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:51:28.722Z,1556671888.722 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:51:28.723Z,1556671888.723 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:51:32.287Z,1556671892.287 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:32.291Z,1556671892.291 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:32.686Z,1556671892.686 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,0B,FF
2019-05-01T00:51:36.323Z,1556671896.323 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:36.328Z,1556671896.328 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:36.726Z,1556671896.726 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,0B,FF
2019-05-01T00:51:39.181Z,1556671899.181 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:51:39.181Z,1556671899.181 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:51:39.181Z,1556671899.181 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater] Running Loop=6
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:51:39.182Z,1556671899.182 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:51:39.183Z,1556671899.183 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:51:39.183Z,1556671899.183 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:51:40.367Z,1556671900.367 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:40.371Z,1556671900.371 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:40.783Z,1556671900.783 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,0A,FF
2019-05-01T00:51:44.415Z,1556671904.415 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:44.419Z,1556671904.419 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:45.211Z,1556671905.211 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:45.217Z,1556671905.217 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:45.619Z,1556671905.619 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:51:45.620Z,1556671905.620 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,005144.15*5E

2019-05-01T00:51:49.255Z,1556671909.255 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:49.260Z,1556671909.260 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:49.658Z,1556671909.658 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,187,80,81,0A,FF
2019-05-01T00:51:49.744Z,1556671909.744 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:51:49.744Z,1556671909.744 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:51:49.744Z,1556671909.744 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:51:49.749Z,1556671909.749 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:51:49.749Z,1556671909.749 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:51:49.749Z,1556671909.749 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:51:49.749Z,1556671909.749 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:51:49.749Z,1556671909.749 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:51:49.749Z,1556671909.749 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-01T00:51:49.750Z,1556671909.750 [DUSBL:RequestRepeater] Running Loop=7
2019-05-01T00:51:49.750Z,1556671909.750 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:51:49.750Z,1556671909.750 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:51:49.750Z,1556671909.750 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:51:49.750Z,1556671909.750 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:51:49.750Z,1556671909.750 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:51:53.295Z,1556671913.295 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:53.300Z,1556671913.300 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:53.698Z,1556671913.698 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,186,80,81,05,FF
2019-05-01T00:51:57.335Z,1556671917.335 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:51:57.339Z,1556671917.339 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:51:57.735Z,1556671917.735 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,186,80,81,07,FF
2019-05-01T00:52:00.196Z,1556671920.196 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:52:00.196Z,1556671920.196 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:52:00.196Z,1556671920.196 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:52:00.200Z,1556671920.200 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:52:00.200Z,1556671920.200 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:52:00.200Z,1556671920.200 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:52:00.200Z,1556671920.200 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:52:00.200Z,1556671920.200 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:52:00.200Z,1556671920.200 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-01T00:52:00.205Z,1556671920.205 [DUSBL:RequestRepeater] Running Loop=8
2019-05-01T00:52:00.205Z,1556671920.205 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:52:00.205Z,1556671920.205 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:52:00.205Z,1556671920.205 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:52:00.205Z,1556671920.205 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:52:00.205Z,1556671920.205 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:52:01.375Z,1556671921.375 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:01.379Z,1556671921.379 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:01.775Z,1556671921.775 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,189,80,81,04,FF
2019-05-01T00:52:05.414Z,1556671925.414 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:05.416Z,1556671925.416 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:05.814Z,1556671925.814 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-01T00:52:06.219Z,1556671926.219 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:06.220Z,1556671926.220 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:06.623Z,1556671926.623 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:52:06.625Z,1556671926.625 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,005205.14*59

2019-05-01T00:52:10.259Z,1556671930.259 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:10.264Z,1556671930.264 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:10.666Z,1556671930.666 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !0000,185,80,81,05,FF
2019-05-01T00:52:10.716Z,1556671930.716 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:52:10.716Z,1556671930.716 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:52:10.716Z,1556671930.716 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:52:10.717Z,1556671930.717 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:52:10.717Z,1556671930.717 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:52:10.717Z,1556671930.717 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:52:10.717Z,1556671930.717 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:52:10.717Z,1556671930.717 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:52:10.717Z,1556671930.717 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-01T00:52:10.717Z,1556671930.717 [DUSBL:RequestRepeater] Running Loop=9
2019-05-01T00:52:10.718Z,1556671930.718 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:52:10.718Z,1556671930.718 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:52:10.718Z,1556671930.718 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:52:10.718Z,1556671930.718 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:52:10.718Z,1556671930.718 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:52:14.303Z,1556671934.303 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:14.337Z,1556671934.337 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:15.105Z,1556671935.105 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:15.122Z,1556671935.122 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:15.528Z,1556671935.528 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-05-01T00:52:15.530Z,1556671935.530 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,005214.10*5D

2019-05-01T00:52:19.150Z,1556671939.150 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:19.155Z,1556671939.155 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:19.555Z,1556671939.555 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,186,80,81,03,FF
2019-05-01T00:52:19.572Z,1556671939.572 [Micromodem](ERROR): Response from modem unexpected: $CADQF,194,1*5C

2019-05-01T00:52:19.963Z,1556671939.963 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAMSG,BAD_CRC,*21

2019-05-01T00:52:19.970Z,1556671939.970 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190501005218.272683,06,324,13,0107,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,194,0.05,-999,9760,4000*52

2019-05-01T00:52:21.196Z,1556671941.196 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-01T00:52:21.196Z,1556671941.196 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:52:21.196Z,1556671941.196 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:52:21.196Z,1556671941.196 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-01T00:52:21.197Z,1556671941.197 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:52:21.197Z,1556671941.197 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:52:21.197Z,1556671941.197 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:52:21.197Z,1556671941.197 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:52:21.197Z,1556671941.197 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-01T00:52:21.197Z,1556671941.197 [DUSBL:RequestRepeater] Running Loop=10
2019-05-01T00:52:21.197Z,1556671941.197 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-01T00:52:21.198Z,1556671941.198 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-01T00:52:21.198Z,1556671941.198 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-01T00:52:21.198Z,1556671941.198 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-01T00:52:21.198Z,1556671941.198 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:52:23.184Z,1556671943.184 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:23.190Z,1556671943.190 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:23.594Z,1556671943.594 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U000,187,80,81,04,FF
2019-05-01T00:52:27.138Z,1556671947.138 [CommandLine](IMPORTANT): got command quit
2019-05-01T00:52:27.227Z,1556671947.227 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-01T00:52:27.232Z,1556671947.232 [Micromodem](DEBUG): Nmea buf: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-05-01T00:52:27.634Z,1556671947.634 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 00000,189,80,81,05,FF
2019-05-01T00:52:28.141Z,1556671948.141 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-01T00:52:28.141Z,1556671948.141 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:28.142Z,1556671948.142 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.289Z,1556671948.289 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-01T00:52:28.289Z,1556671948.289 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.290Z,1556671948.290 [CommandLine](INFO): Join timeout helper Thread ID is 3172
2019-05-01T00:52:28.290Z,1556671948.290 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-01T00:52:28.291Z,1556671948.291 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.291Z,1556671948.291 [NavChartDb](INFO): Join timeout helper Thread ID is 3173
2019-05-01T00:52:28.317Z,1556671948.317 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:28.317Z,1556671948.317 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.329Z,1556671948.329 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-01T00:52:28.329Z,1556671948.329 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.330Z,1556671948.330 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 3174
2019-05-01T00:52:28.502Z,1556671948.502 [MissionManager](INFO): MissionManager is completed.
2019-05-01T00:52:28.502Z,1556671948.502 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL] Stopped
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL:A.Pitch] Stopped
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL:B.SetSpeed] Stopped
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL:C] Stopped
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL:RequestRepeater] Stopped
2019-05-01T00:52:28.502Z,1556671948.502 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-01T00:52:28.503Z,1556671948.503 [DUSBL:RequestRepeater:A] Stopped
2019-05-01T00:52:28.503Z,1556671948.503 [DUSBL:RequestRepeater:B] Stopped
2019-05-01T00:52:28.503Z,1556671948.503 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-01T00:52:28.503Z,1556671948.503 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:52:28.625Z,1556671948.625 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:28.625Z,1556671948.625 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-01T00:52:28.626Z,1556671948.626 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.629Z,1556671948.629 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-01T00:52:28.629Z,1556671948.629 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.629Z,1556671948.629 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3175
2019-05-01T00:52:28.697Z,1556671948.697 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:28.697Z,1556671948.697 [CTD_NeilBrown](INFO): Powering down
2019-05-01T00:52:28.709Z,1556671948.709 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.709Z,1556671948.709 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-01T00:52:28.709Z,1556671948.709 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:28.710Z,1556671948.710 [Radio_Surface](INFO): Join timeout helper Thread ID is 3176
2019-05-01T00:52:28.880Z,1556671948.880 [MissionManager](IMPORTANT): Started mission Default
2019-05-01T00:52:28.880Z,1556671948.880 [Default] Running Loop=1
2019-05-01T00:52:28.880Z,1556671948.880 [Default](DEBUG): Aggregate::initialize Default
2019-05-01T00:52:28.880Z,1556671948.880 [Default:B.GoToSurface] Running Loop=1
2019-05-01T00:52:28.880Z,1556671948.880 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-01T00:52:28.885Z,1556671948.885 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-01T00:52:28.885Z,1556671948.885 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-01T00:52:28.885Z,1556671948.885 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-01T00:52:28.886Z,1556671948.886 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-01T00:52:28.886Z,1556671948.886 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-01T00:52:28.886Z,1556671948.886 [Default:A.Wait] Running Loop=1
2019-05-01T00:52:28.886Z,1556671948.886 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-01T00:52:29.029Z,1556671949.029 [Radio_Surface](INFO): Powering down
2019-05-01T00:52:29.030Z,1556671949.030 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:29.030Z,1556671949.030 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:29.042Z,1556671949.042 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-01T00:52:29.042Z,1556671949.042 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:29.042Z,1556671949.042 [DataOverHttps](INFO): Join timeout helper Thread ID is 3177
2019-05-01T00:52:29.165Z,1556671949.165 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:29.165Z,1556671949.165 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:29.182Z,1556671949.182 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-01T00:52:29.182Z,1556671949.182 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:29.182Z,1556671949.182 [logger](INFO): Join timeout helper Thread ID is 3178
2019-05-01T00:52:29.281Z,1556671949.281 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:29.281Z,1556671949.281 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:29.286Z,1556671949.286 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-01T00:52:29.286Z,1556671949.286 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:29.286Z,1556671949.286 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-01T00:52:29.286Z,1556671949.286 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:29.286Z,1556671949.286 [controlThread](INFO): Join timeout helper Thread ID is 3179
2019-05-01T00:52:29.633Z,1556671949.633 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-01T00:52:29.633Z,1556671949.633 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-01T00:52:29.634Z,1556671949.634 [AHRS_M2](INFO): Powering down
2019-05-01T00:52:29.705Z,1556671949.705 [DUSBL_Hydroid](INFO): Powering down
2019-05-01T00:52:29.777Z,1556671949.777 [Micromodem](INFO): Powering down
2019-05-01T00:52:29.873Z,1556671949.873 [NAL9602](INFO): Powering down
2019-05-01T00:52:29.945Z,1556671949.945 [RDI_Pathfinder](INFO): Powering down
2019-05-01T00:52:29.946Z,1556671949.946 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-01T00:52:29.947Z,1556671949.947 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-01T00:52:29.947Z,1556671949.947 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-01T00:52:29.948Z,1556671949.948 [MissionManager](INFO): Uninitializing Mission Default
2019-05-01T00:52:29.948Z,1556671949.948 [Default] Stopped
2019-05-01T00:52:29.948Z,1556671949.948 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-01T00:52:29.948Z,1556671949.948 [Default:A.Wait] Stopped
2019-05-01T00:52:29.948Z,1556671949.948 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-01T00:52:29.948Z,1556671949.948 [Default:B.GoToSurface] Stopped
2019-05-01T00:52:29.948Z,1556671949.948 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-01T00:52:29.951Z,1556671949.951 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-01T00:52:29.951Z,1556671949.951 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-01T00:52:29.951Z,1556671949.951 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-01T00:52:29.952Z,1556671949.952 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-01T00:52:29.952Z,1556671949.952 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-01T00:52:29.952Z,1556671949.952 [BuoyancyServo](INFO): Powering down
2019-05-01T00:52:29.965Z,1556671949.965 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-01T00:52:29.965Z,1556671949.965 [ElevatorServo](INFO): Powering down
2019-05-01T00:52:29.966Z,1556671949.966 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-01T00:52:29.966Z,1556671949.966 [MassServo](INFO): Powering down
2019-05-01T00:52:29.967Z,1556671949.967 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-01T00:52:29.967Z,1556671949.967 [RudderServo](INFO): Powering down
2019-05-01T00:52:29.968Z,1556671949.968 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-01T00:52:29.968Z,1556671949.968 [ThrusterServo](INFO): Powering down
2019-05-01T00:52:29.969Z,1556671949.969 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-01T00:52:29.969Z,1556671949.969 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-01T00:52:29.969Z,1556671949.969 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-01T00:52:29.969Z,1556671949.969 [CBIT](DEBUG): Powering off loads.
2019-05-01T00:52:29.981Z,1556671949.981 [CBIT](DEBUG): Disabling WDT.
2019-05-01T00:52:29.993Z,1556671949.993 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-01T00:52:29.994Z,1556671949.994 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:30.042Z,1556671950.042 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:30.051Z,1556671950.051 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:30.093Z,1556671950.093 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:30.095Z,1556671950.095 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:30.150Z,1556671950.150 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-01T00:52:30.217Z,1556671950.217 [logger ThreadHandler](INFO): Thread cancelled.