2019-03-14T22:23:56.010Z,1552602236.010 [Supervisor](DEBUG): Initializing supervisor.
2019-03-14T22:23:56.013Z,1552602236.013 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-03-14T22:23:56.014Z,1552602236.014 [SyncHandler](INFO): Protected caller Thread ID is 1665
2019-03-14T22:23:56.015Z,1552602236.015 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-03-14T22:23:56.016Z,1552602236.016 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-03-14T22:23:56.016Z,1552602236.016 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1666
2019-03-14T22:23:56.019Z,1552602236.019 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-03-14T22:23:56.031Z,1552602236.031 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-03-14T22:23:56.032Z,1552602236.032 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-03-14T22:23:56.032Z,1552602236.032 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1667
2019-03-14T22:23:56.033Z,1552602236.033 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-03-14T22:23:56.034Z,1552602236.034 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-03-14T22:23:56.034Z,1552602236.034 [logger ThreadHandler](INFO): Protected caller Thread ID is 1668
2019-03-14T22:23:56.036Z,1552602236.036 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-03-14T22:23:56.037Z,1552602236.037 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-03-14T22:23:56.038Z,1552602236.038 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-03-14T22:23:56.470Z,1552602236.470 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-03-14T22:23:56.471Z,1552602236.471 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-03-14T22:23:56.570Z,1552602236.570 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-03-14T22:23:56.571Z,1552602236.571 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-03-14T22:23:56.907Z,1552602236.907 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-03-14T22:23:56.908Z,1552602236.908 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-03-14T22:23:57.053Z,1552602237.053 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-03-14T22:23:57.054Z,1552602237.054 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-03-14T22:23:57.251Z,1552602237.251 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-03-14T22:23:57.252Z,1552602237.252 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-03-14T22:23:57.720Z,1552602237.720 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-03-14T22:23:57.721Z,1552602237.721 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-03-14T22:23:57.938Z,1552602237.938 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-03-14T22:23:57.939Z,1552602237.939 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-03-14T22:23:58.088Z,1552602238.088 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-03-14T22:23:58.088Z,1552602238.088 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-03-14T22:23:58.291Z,1552602238.291 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-03-14T22:23:58.291Z,1552602238.291 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-03-14T22:23:58.388Z,1552602238.388 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-03-14T22:23:58.389Z,1552602238.389 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-03-14T22:23:58.707Z,1552602238.707 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-03-14T22:23:58.707Z,1552602238.707 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-03-14T22:23:58.788Z,1552602238.788 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-03-14T22:23:58.894Z,1552602238.894 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-03-14T22:23:58.894Z,1552602238.894 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-03-14T22:23:59.402Z,1552602239.402 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-03-14T22:23:59.403Z,1552602239.403 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-03-14T22:23:59.805Z,1552602239.805 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-03-14T22:23:59.807Z,1552602239.807 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-03-14T22:23:59.808Z,1552602239.808 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-03-14T22:24:00.092Z,1552602240.092 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-03-14T22:24:00.365Z,1552602240.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-03-14T22:24:00.469Z,1552602240.469 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-03-14T22:24:00.875Z,1552602240.875 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-03-14T22:24:00.875Z,1552602240.875 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-03-14T22:24:00.961Z,1552602240.961 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-03-14T22:24:01.057Z,1552602241.057 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-03-14T22:24:01.156Z,1552602241.156 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-03-14T22:24:01.240Z,1552602241.240 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-03-14T22:24:01.351Z,1552602241.351 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-03-14T22:24:01.529Z,1552602241.529 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-03-14T22:24:01.664Z,1552602241.664 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-03-14T22:24:01.665Z,1552602241.665 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-03-14T22:24:01.669Z,1552602241.669 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-03-14T22:24:01.987Z,1552602241.987 [DataOverHttps] Loaded
2019-03-14T22:24:01.988Z,1552602241.988 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-03-14T22:24:01.989Z,1552602241.989 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4074D4E0
2019-03-14T22:24:01.989Z,1552602241.989 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1747
2019-03-14T22:24:02.026Z,1552602242.026 [Depth_Keller] Loaded
2019-03-14T22:24:02.026Z,1552602242.026 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-03-14T22:24:02.031Z,1552602242.031 [DropWeight] Loaded
2019-03-14T22:24:02.031Z,1552602242.031 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-03-14T22:24:02.078Z,1552602242.078 [DUSBL_Hydroid] Loaded
2019-03-14T22:24:02.078Z,1552602242.078 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-03-14T22:24:02.117Z,1552602242.117 [Micromodem] Loaded
2019-03-14T22:24:02.117Z,1552602242.117 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-03-14T22:24:02.211Z,1552602242.211 [NAL9602] Loaded
2019-03-14T22:24:02.212Z,1552602242.212 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-03-14T22:24:02.227Z,1552602242.227 [Onboard] Loaded
2019-03-14T22:24:02.227Z,1552602242.227 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-03-14T22:24:02.234Z,1552602242.234 [Radio_Surface] Loaded
2019-03-14T22:24:02.234Z,1552602242.234 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-03-14T22:24:02.235Z,1552602242.235 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4077D4E0
2019-03-14T22:24:02.235Z,1552602242.235 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1748
2019-03-14T22:24:02.294Z,1552602242.294 [RDI_Pathfinder] Loaded
2019-03-14T22:24:02.294Z,1552602242.294 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-03-14T22:24:02.315Z,1552602242.315 [RDI_PathfinderUp] Loaded
2019-03-14T22:24:02.315Z,1552602242.315 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2019-03-14T22:24:04.054Z,1552602244.054 [BPC1] Loaded
2019-03-14T22:24:04.054Z,1552602244.054 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-03-14T22:24:04.055Z,1552602244.055 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-03-14T22:24:04.055Z,1552602244.055 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-03-14T22:24:04.068Z,1552602244.068 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-03-14T22:24:04.068Z,1552602244.068 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-03-14T22:24:04.171Z,1552602244.171 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-03-14T22:24:04.171Z,1552602244.171 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-03-14T22:24:04.229Z,1552602244.229 [DeadReckonUsingSpeedCalculator] Loaded
2019-03-14T22:24:04.229Z,1552602244.229 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2019-03-14T22:24:04.288Z,1552602244.288 [DeadReckonWithRespectToSeafloor] Loaded
2019-03-14T22:24:04.288Z,1552602244.288 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2019-03-14T22:24:04.308Z,1552602244.308 [NavChart] Loaded
2019-03-14T22:24:04.308Z,1552602244.308 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-03-14T22:24:04.312Z,1552602244.312 [UniversalFixResidualReporter] Loaded
2019-03-14T22:24:04.313Z,1552602244.313 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-03-14T22:24:04.313Z,1552602244.313 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-03-14T22:24:04.313Z,1552602244.313 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-03-14T22:24:04.412Z,1552602244.412 [BuoyancyServo] Loaded
2019-03-14T22:24:04.413Z,1552602244.413 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-03-14T22:24:04.428Z,1552602244.428 [ElevatorServo] Loaded
2019-03-14T22:24:04.428Z,1552602244.428 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-03-14T22:24:04.443Z,1552602244.443 [MassServo] Loaded
2019-03-14T22:24:04.443Z,1552602244.443 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-03-14T22:24:04.458Z,1552602244.458 [RudderServo] Loaded
2019-03-14T22:24:04.458Z,1552602244.458 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-03-14T22:24:04.472Z,1552602244.472 [ThrusterServo] Loaded
2019-03-14T22:24:04.473Z,1552602244.473 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-03-14T22:24:04.473Z,1552602244.473 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-03-14T22:24:04.474Z,1552602244.474 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-03-14T22:24:04.715Z,1552602244.715 [CTD_NeilBrown] Loaded
2019-03-14T22:24:04.715Z,1552602244.715 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-03-14T22:24:04.716Z,1552602244.716 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408C24E0
2019-03-14T22:24:04.717Z,1552602244.717 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1749
2019-03-14T22:24:04.760Z,1552602244.760 [WetLabsSeaOWL_UV_A] Loaded
2019-03-14T22:24:04.761Z,1552602244.761 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-03-14T22:24:04.761Z,1552602244.761 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408F24E0
2019-03-14T22:24:04.762Z,1552602244.762 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1750
2019-03-14T22:24:04.763Z,1552602244.763 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-03-14T22:24:04.763Z,1552602244.763 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-03-14T22:24:04.991Z,1552602244.991 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-03-14T22:24:04.991Z,1552602244.991 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-03-14T22:24:05.030Z,1552602245.030 [DepthRateCalculator] Loaded
2019-03-14T22:24:05.031Z,1552602245.031 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-03-14T22:24:05.036Z,1552602245.036 [PitchRateCalculator] Loaded
2019-03-14T22:24:05.037Z,1552602245.037 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-03-14T22:24:05.049Z,1552602245.049 [SpeedCalculator] Loaded
2019-03-14T22:24:05.049Z,1552602245.049 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-03-14T22:24:05.070Z,1552602245.070 [TempGradientCalculator] Loaded
2019-03-14T22:24:05.070Z,1552602245.070 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-03-14T22:24:05.076Z,1552602245.076 [YawRateCalculator] Loaded
2019-03-14T22:24:05.076Z,1552602245.076 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-03-14T22:24:05.115Z,1552602245.115 [ElevatorOffsetCalculator] Loaded
2019-03-14T22:24:05.116Z,1552602245.116 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-03-14T22:24:05.116Z,1552602245.116 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-03-14T22:24:05.117Z,1552602245.117 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-03-14T22:24:05.498Z,1552602245.498 [SBIT](DEBUG): Construct Startup Built In Test.
2019-03-14T22:24:05.558Z,1552602245.558 [SBIT] Loaded
2019-03-14T22:24:05.558Z,1552602245.558 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-03-14T22:24:05.559Z,1552602245.559 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-03-14T22:24:05.571Z,1552602245.571 [IBIT] Loaded
2019-03-14T22:24:05.571Z,1552602245.571 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-03-14T22:24:05.574Z,1552602245.574 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-03-14T22:24:05.764Z,1552602245.764 [CBIT] Loaded
2019-03-14T22:24:05.764Z,1552602245.764 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-03-14T22:24:05.764Z,1552602245.764 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-03-14T22:24:05.765Z,1552602245.765 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-03-14T22:24:05.936Z,1552602245.936 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-03-14T22:24:05.936Z,1552602245.936 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-03-14T22:24:06.030Z,1552602246.030 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-03-14T22:24:06.030Z,1552602246.030 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-03-14T22:24:06.094Z,1552602246.094 [VerticalControl](DEBUG): Construct VerticalControl.
2019-03-14T22:24:06.176Z,1552602246.176 [VerticalControl] Loaded
2019-03-14T22:24:06.176Z,1552602246.176 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-03-14T22:24:06.177Z,1552602246.177 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-03-14T22:24:06.233Z,1552602246.233 [HorizontalControl] Loaded
2019-03-14T22:24:06.234Z,1552602246.234 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-03-14T22:24:06.234Z,1552602246.234 [SpeedControl](DEBUG): Construct SpeedControl.
2019-03-14T22:24:06.236Z,1552602246.236 [SpeedControl] Loaded
2019-03-14T22:24:06.236Z,1552602246.236 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-03-14T22:24:06.237Z,1552602246.237 [LoopControl](DEBUG): Construct LoopControl.
2019-03-14T22:24:06.237Z,1552602246.237 [LoopControl] Loaded
2019-03-14T22:24:06.238Z,1552602246.238 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-03-14T22:24:06.238Z,1552602246.238 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-03-14T22:24:06.239Z,1552602246.239 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-03-14T22:24:06.265Z,1552602246.265 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-03-14T22:24:06.268Z,1552602246.268 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-03-14T22:24:06.269Z,1552602246.269 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-03-14T22:24:06.276Z,1552602246.276 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-03-14T22:24:06.277Z,1552602246.277 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AB04E0
2019-03-14T22:24:06.277Z,1552602246.277 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1751
2019-03-14T22:24:06.282Z,1552602246.282 [Supervisor](INFO): Main Thread ID is 800
2019-03-14T22:24:06.282Z,1552602246.282 [Supervisor](DEBUG): Running supervisor.
2019-03-14T22:24:06.283Z,1552602246.283 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1752
2019-03-14T22:24:06.285Z,1552602246.285 [controlThread ThreadHandler](INFO): Handler Thread ID is 1753
2019-03-14T22:24:06.285Z,1552602246.285 [controlThread](DEBUG): Initializing ControlThread
2019-03-14T22:24:06.293Z,1552602246.293 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:24:06.294Z,1552602246.294 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-03-14T22:24:06.295Z,1552602246.295 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-03-14T22:24:06.296Z,1552602246.296 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-03-14T22:24:06.296Z,1552602246.296 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-03-14T22:24:06.296Z,1552602246.296 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-03-14T22:24:06.296Z,1552602246.296 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-03-14T22:24:06.297Z,1552602246.297 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-03-14T22:24:06.297Z,1552602246.297 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-03-14T22:24:06.298Z,1552602246.298 [SBIT](INFO): Initialize SBIT Component.
2019-03-14T22:24:06.299Z,1552602246.299 [SBIT](IMPORTANT): git: 2019-03-04-36-g743def3
2019-03-14T22:24:06.299Z,1552602246.299 [SBIT](INFO): git hash: 743def31acf12ef8e20e672f0fefb031590b97fa
2019-03-14T22:24:06.299Z,1552602246.299 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-03-14T22:24:06.299Z,1552602246.299 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-03-14T22:24:06.300Z,1552602246.300 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-03-14T22:24:06.301Z,1552602246.301 [IBIT](INFO): Initialize IBIT Component.
2019-03-14T22:24:06.302Z,1552602246.302 [CBIT](DEBUG): Initialize CBIT Component.
2019-03-14T22:24:06.303Z,1552602246.303 [logger ThreadHandler](INFO): Handler Thread ID is 1754
2019-03-14T22:24:06.314Z,1552602246.314 [CBIT](DEBUG): Initialized mux pins.
2019-03-14T22:24:06.314Z,1552602246.314 [CBIT](DEBUG): Initializing the watchdog timer.
2019-03-14T22:24:06.323Z,1552602246.323 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1755
2019-03-14T22:24:06.324Z,1552602246.324 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-03-14T22:24:06.335Z,1552602246.335 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1756
2019-03-14T22:24:06.338Z,1552602246.338 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2019-03-14T22:24:06.338Z,1552602246.338 [CBIT](DEBUG): Initializing heartbeat.
2019-03-14T22:24:06.347Z,1552602246.347 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1757
2019-03-14T22:24:06.347Z,1552602246.347 [CTD_NeilBrown](INFO): Powering down
2019-03-14T22:24:06.375Z,1552602246.375 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1758
2019-03-14T22:24:06.375Z,1552602246.375 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-03-14T22:24:06.410Z,1552602246.410 [CBIT](DEBUG): Deactivating GF circuits.
2019-03-14T22:24:06.410Z,1552602246.410 [CBIT](DEBUG): Deactivating emergency mode.
2019-03-14T22:24:06.411Z,1552602246.411 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1759
2019-03-14T22:24:06.414Z,1552602246.414 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-03-14T22:24:06.414Z,1552602246.414 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-03-14T22:24:06.415Z,1552602246.415 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-03-14T22:24:06.415Z,1552602246.415 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-03-14T22:24:06.415Z,1552602246.415 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-03-14T22:24:06.415Z,1552602246.415 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-03-14T22:24:06.415Z,1552602246.415 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-03-14T22:24:06.416Z,1552602246.416 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-03-14T22:24:06.416Z,1552602246.416 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-03-14T22:24:06.416Z,1552602246.416 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-03-14T22:24:06.416Z,1552602246.416 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-03-14T22:24:06.416Z,1552602246.416 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-03-14T22:24:06.416Z,1552602246.416 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-03-14T22:24:06.417Z,1552602246.417 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-03-14T22:24:06.417Z,1552602246.417 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-03-14T22:24:06.417Z,1552602246.417 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-03-14T22:24:06.446Z,1552602246.446 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-03-14T22:24:06.448Z,1552602246.448 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-03-14T22:24:06.449Z,1552602246.449 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-03-14T22:24:06.449Z,1552602246.449 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-03-14T22:24:06.450Z,1552602246.450 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-03-14T22:24:06.460Z,1552602246.460 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-03-14T22:24:06.487Z,1552602246.487 [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-03-14T22:24:06.488Z,1552602246.488 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-03-14T22:24:06.542Z,1552602246.542 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-03-14T22:24:06.559Z,1552602246.559 [Default:A.Wait](DEBUG): Construct Wait.
2019-03-14T22:24:06.561Z,1552602246.561 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-03-14T22:24:06.587Z,1552602246.587 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-03-14T22:24:06.590Z,1552602246.590 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-03-14T22:24:06.611Z,1552602246.611 [Default:E.Execute](DEBUG): Construct Execute.
2019-03-14T22:24:06.619Z,1552602246.619 [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-03-14T22:24:06.624Z,1552602246.624 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,RDI_Pathfinder,RDI_PathfinderUp,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-03-14T22:24:06.660Z,1552602246.660 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-03-14T22:24:06.661Z,1552602246.661 [DUSBL_Hydroid](INFO): Powering up
2019-03-14T22:24:06.661Z,1552602246.661 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-14T22:24:06.738Z,1552602246.738 [Radio_Surface](INFO): Powering up
2019-03-14T22:24:06.747Z,1552602246.747 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-03-14T22:24:06.784Z,1552602246.784 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-03-14T22:24:06.798Z,1552602246.798 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-03-14T22:24:06.799Z,1552602246.799 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-03-14T22:24:06.806Z,1552602246.806 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-03-14T22:24:06.807Z,1552602246.807 [MassServo](DEBUG): Initializing EZServoServo.
2019-03-14T22:24:06.814Z,1552602246.814 [MassServo](DEBUG): Initializing MassServo.
2019-03-14T22:24:06.815Z,1552602246.815 [RudderServo](DEBUG): Initializing EZServoServo.
2019-03-14T22:24:06.837Z,1552602246.837 [RudderServo](DEBUG): Initializing RudderServo.
2019-03-14T22:24:06.838Z,1552602246.838 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-03-14T22:24:06.846Z,1552602246.846 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-03-14T22:24:06.848Z,1552602246.848 [CommandLine](FAULT): Scheduling is paused
2019-03-14T22:24:06.849Z,1552602246.849 [CBIT](INFO): Critical error at 20190314T222406
2019-03-14T22:24:06.849Z,1552602246.849 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-03-14T22:24:07.048Z,1552602247.048 [Micromodem](INFO): Powering up
2019-03-14T22:24:07.048Z,1552602247.048 [Micromodem](DEBUG): Initializing Micromodem.
2019-03-14T22:24:07.150Z,1552602247.150 [RDI_PathfinderUp](INFO): Powering down
2019-03-14T22:24:07.198Z,1552602247.198 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-03-14T22:24:11.920Z,1552602251.920 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-03-14T22:24:20.025Z,1552602260.025 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-03-14T22:24:23.233Z,1552602263.233 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-03-14T22:24:24.868Z,1552602264.868 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-14T22:24:32.524Z,1552602272.524 [NAL9602](INFO): Powering up NAL9602
2019-03-14T22:24:33.332Z,1552602273.332 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-03-14T22:24:34.995Z,1552602274.995 [SBIT](IMPORTANT): Beginning Startup BIT
2019-03-14T22:24:35.004Z,1552602275.004 [CBIT](IMPORTANT): Beginning ground fault scan
2019-03-14T22:24:43.212Z,1552602283.212 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-03-14T22:24:43.617Z,1552602283.617 [NAL9602](INFO): NAL9602 initialized
2019-03-14T22:24:44.434Z,1552602284.434 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:24:45.723Z,1552602285.723 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.015654
CHAN A1 (24V): -0.027424
CHAN A2 (12V): -0.006747
CHAN A3 (5V): -0.001265
CHAN B0 (3.3V): 0.000446
CHAN B1 (3.15aV): -0.000117
CHAN B2 (3.15bV): 0.000310
CHAN B3 (GND): 0.002194
OPEN: 0.006283
Full Scale Calc: 4.765 mA, -1.589 mA
2019-03-14T22:24:53.062Z,1552602293.062 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-03-14T22:24:53.868Z,1552602293.868 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,2225,CPROC,0.10.0.46*41

2019-03-14T22:24:59.036Z,1552602299.036 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-03-14T22:25:01.296Z,1552602301.296 [CommandLine](IMPORTANT): got command show stack
2019-03-14T22:25:01.296Z,1552602301.296 [CommandLine](IMPORTANT): Behavior Stack:

2019-03-14T22:25:01.296Z,1552602301.296 [MissionManager](IMPORTANT): Mission loaded, but not running.
2019-03-14T22:25:03.162Z,1552602303.162 [Micromodem](INFO): Nmea out: $CCTMS,2019-03-14T22:25:04Z,0*7B

2019-03-14T22:25:03.868Z,1552602303.868 [CommandLine](IMPORTANT): got command show variable USBL
2019-03-14T22:25:03.910Z,1552602303.910 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-03-14T22:25:03.910Z,1552602303.910 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-03-14T22:25:03.911Z,1552602303.911 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-03-14T22:25:03.911Z,1552602303.911 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-03-14T22:25:03.911Z,1552602303.911 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-03-14T22:25:03.912Z,1552602303.912 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-03-14T22:25:03.912Z,1552602303.912 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-03-14T22:25:03.912Z,1552602303.912 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-03-14T22:25:03.913Z,1552602303.913 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-03-14T22:25:03.913Z,1552602303.913 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-03-14T22:25:03.913Z,1552602303.913 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-03-14T22:25:03.914Z,1552602303.914 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-03-14T22:25:03.923Z,1552602303.923 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-03-14T22:25:03.923Z,1552602303.923 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-03-14T22:25:03.924Z,1552602303.924 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-03-14T22:25:03.926Z,1552602303.926 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-03-14T22:25:03.927Z,1552602303.927 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-03-14T22:25:03.927Z,1552602303.927 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-03-14T22:25:03.927Z,1552602303.927 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-03-14T22:25:03.928Z,1552602303.928 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-03-14T22:25:03.928Z,1552602303.928 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-03-14T22:25:03.928Z,1552602303.928 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-03-14T22:25:03.929Z,1552602303.929 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-03-14T22:25:03.929Z,1552602303.929 [CommandLine](IMPORTANT): DUSBL_Hydroid.range (meter)
2019-03-14T22:25:03.929Z,1552602303.929 [CommandLine](IMPORTANT): DUSBL_Hydroid.direction (none)
2019-03-14T22:25:12.624Z,1552602312.624 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.range
2019-03-14T22:25:22.063Z,1552602322.063 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-03-14T22:25:28.741Z,1552602328.741 [SBIT](IMPORTANT): SBIT PASSED
2019-03-14T22:25:28.805Z,1552602328.805 [CommandLine](IMPORTANT): got command configSet list
2019-03-14T22:25:28.805Z,1552602328.805 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-03-14T22:25:28.807Z,1552602328.807 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2019-03-14T22:25:28.808Z,1552602328.808 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2019-03-14T22:25:28.808Z,1552602328.808 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-03-14T22:25:29.143Z,1552602329.143 [MissionManager](IMPORTANT): Started mission Startup
2019-03-14T22:25:29.143Z,1552602329.143 [Startup] Running Loop=1
2019-03-14T22:25:29.143Z,1552602329.143 [Startup](DEBUG): Aggregate::initialize Startup
2019-03-14T22:25:29.143Z,1552602329.143 [Startup:A.GoToSurface] Running Loop=1
2019-03-14T22:25:29.143Z,1552602329.143 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-14T22:25:29.144Z,1552602329.144 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-14T22:25:29.144Z,1552602329.144 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-14T22:25:29.144Z,1552602329.144 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-14T22:25:29.145Z,1552602329.145 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-14T22:25:29.145Z,1552602329.145 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-14T22:25:29.147Z,1552602329.147 [Startup:StartupSatComms] Running Loop=1
2019-03-14T22:25:29.147Z,1552602329.147 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-03-14T22:25:29.147Z,1552602329.147 [Startup:StartupSatComms:A] Running Loop=1
2019-03-14T22:25:29.540Z,1552602329.540 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-03-14T22:25:59.808Z,1552602359.808 [NAL9602](INFO): SBD MO Status=2, MOMSN=2281, MT Status=2, MTMSN=0
2019-03-14T22:25:59.808Z,1552602359.808 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-14T22:26:06.690Z,1552602366.690 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:26:06.690Z,1552602366.690 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-03-14T22:26:06.690Z,1552602366.690 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:26:06.692Z,1552602366.692 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:26:06.692Z,1552602366.692 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-03-14T22:26:06.692Z,1552602366.692 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:26:06.693Z,1552602366.693 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:26:06.693Z,1552602366.693 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-14T22:26:06.693Z,1552602366.693 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:26:06.705Z,1552602366.705 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:26:06.705Z,1552602366.705 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:26:06.705Z,1552602366.705 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:26:07.119Z,1552602367.119 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:26:07.119Z,1552602367.119 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-03-14T22:26:07.119Z,1552602367.119 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:26:07.119Z,1552602367.119 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-03-14T22:26:07.120Z,1552602367.120 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:26:07.120Z,1552602367.120 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-14T22:26:07.552Z,1552602367.552 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:26:17.199Z,1552602377.199 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-03-14T22:26:17.199Z,1552602377.199 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19031415290841,35.0, -0.1,   0.0,1448:RA,  0.00,   0.00,   0.00,   0.00, :BI,-32768,-32768,-32768,-32768,V
2019-03-14T22:26:18.927Z,1552602378.927 [CommandLine](IMPORTANT): got command show stack
2019-03-14T22:26:18.927Z,1552602378.927 [CommandLine](IMPORTANT): Behavior Stack:

2019-03-14T22:26:18.927Z,1552602378.927 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-03-14T22:26:18.928Z,1552602378.928 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:A
2019-03-14T22:26:26.904Z,1552602386.904 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-03-14T22:26:29.316Z,1552602389.316 [Startup:StartupSatComms:A](INFO): Timed out from 2019-03-14T22:25:29.1Z
2019-03-14T22:26:29.316Z,1552602389.316 [Startup:StartupSatComms:A] Stopped
2019-03-14T22:26:29.316Z,1552602389.316 [Startup:StartupSatComms:B] Running Loop=1
2019-03-14T22:26:29.720Z,1552602389.720 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-03-14T22:26:32.597Z,1552602392.597 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005837
2019-03-14T22:26:34.677Z,1552602394.677 [NAL9602](INFO): SBD MO Status=0, MOMSN=2281, MT Status=0, MTMSN=0
2019-03-14T22:26:34.678Z,1552602394.678 [NAL9602](INFO): No messages in MT queue
2019-03-14T22:26:35.498Z,1552602395.498 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:37.678Z,1552602397.678 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190314T221629/Courier0007.lzma
2019-03-14T22:26:37.922Z,1552602397.922 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:38.484Z,1552602398.484 [DataOverHttps](INFO): Moved sent file to Logs/20190314T221629/Courier0007.lzma.bak
2019-03-14T22:26:38.484Z,1552602398.484 [DataOverHttps](INFO): SBD MOMSN=10140601
2019-03-14T22:26:41.154Z,1552602401.154 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:43.982Z,1552602403.982 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:46.823Z,1552602406.823 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:49.422Z,1552602409.422 [DataOverHttps](INFO): Sending 99 bytes from file Logs/20190314T222355/Courier0000.lzma
2019-03-14T22:26:50.046Z,1552602410.046 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:50.228Z,1552602410.228 [DataOverHttps](INFO): Moved sent file to Logs/20190314T222355/Courier0000.lzma.bak
2019-03-14T22:26:50.228Z,1552602410.228 [DataOverHttps](INFO): SBD MOMSN=10140603
2019-03-14T22:26:52.870Z,1552602412.870 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:56.106Z,1552602416.106 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:26:58.930Z,1552602418.930 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:01.674Z,1552602421.674 [DataOverHttps](INFO): Sending 304 bytes from file Logs/20190314T221629/Express0008.lzma
2019-03-14T22:27:02.162Z,1552602422.162 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:02.480Z,1552602422.480 [DataOverHttps](INFO): Moved sent file to Logs/20190314T221629/Express0008.lzma.bak
2019-03-14T22:27:02.480Z,1552602422.480 [DataOverHttps](INFO): SBD MOMSN=10140607
2019-03-14T22:27:04.990Z,1552602424.990 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:07.834Z,1552602427.834 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:09.021Z,1552602429.021 [Micromodem](FAULT): LCB 2 fault: 
2019-03-14T22:27:09.021Z,1552602429.021 [Micromodem] Hardware Fault, FailCount= 1
2019-03-14T22:27:09.021Z,1552602429.021 [Micromodem](ERROR): Hardware Fault
2019-03-14T22:27:09.021Z,1552602429.021 [Micromodem](INFO): Powering down
2019-03-14T22:27:09.156Z,1552602429.156 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-03-14T22:27:09.420Z,1552602429.420 [Micromodem](INFO): Powering down
2019-03-14T22:27:09.825Z,1552602429.825 [Micromodem](FAULT): LCB 2 fault:  Software Overcurrent.
2019-03-14T22:27:10.285Z,1552602430.285 [CBIT](INFO): Clearing failed state for component Micromodem
2019-03-14T22:27:10.285Z,1552602430.285 [Micromodem] No Fault, FailCount= 1
2019-03-14T22:27:11.050Z,1552602431.050 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:13.064Z,1552602433.064 [Micromodem](INFO): Powering up
2019-03-14T22:27:13.064Z,1552602433.064 [Micromodem](DEBUG): Initializing Micromodem.
2019-03-14T22:27:13.878Z,1552602433.878 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:13.904Z,1552602433.904 [DataOverHttps](INFO): Sending 1419 bytes from file Logs/20190314T222355/Express0001.lzma
2019-03-14T22:27:14.707Z,1552602434.707 [DataOverHttps](INFO): Moved sent file to Logs/20190314T222355/Express0001.lzma.bak
2019-03-14T22:27:14.708Z,1552602434.708 [DataOverHttps](INFO): SBD MOMSN=10140618
2019-03-14T22:27:15.507Z,1552602435.507 [Startup:StartupSatComms:B] Stopped
2019-03-14T22:27:15.507Z,1552602435.507 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-03-14T22:27:15.508Z,1552602435.508 [Startup:StartupSatComms] Stopped
2019-03-14T22:27:15.508Z,1552602435.508 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-03-14T22:27:15.508Z,1552602435.508 [Startup](INFO): Completed Startup
2019-03-14T22:27:15.509Z,1552602435.509 [MissionManager](INFO): Startup is completed.
2019-03-14T22:27:15.509Z,1552602435.509 [MissionManager](INFO): Uninitializing Mission Startup
2019-03-14T22:27:15.509Z,1552602435.509 [Startup] Stopped
2019-03-14T22:27:15.509Z,1552602435.509 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-03-14T22:27:15.509Z,1552602435.509 [Startup:A.GoToSurface] Stopped
2019-03-14T22:27:15.509Z,1552602435.509 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-14T22:27:15.917Z,1552602435.917 [MissionManager](IMPORTANT): Started mission Default
2019-03-14T22:27:15.918Z,1552602435.918 [Default] Running Loop=1
2019-03-14T22:27:15.918Z,1552602435.918 [Default](DEBUG): Aggregate::initialize Default
2019-03-14T22:27:15.918Z,1552602435.918 [Default:B.GoToSurface] Running Loop=1
2019-03-14T22:27:15.918Z,1552602435.918 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-14T22:27:15.918Z,1552602435.918 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-14T22:27:15.919Z,1552602435.919 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-14T22:27:15.919Z,1552602435.919 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-14T22:27:15.919Z,1552602435.919 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-14T22:27:15.920Z,1552602435.920 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-14T22:27:15.920Z,1552602435.920 [Default:A.Wait] Running Loop=1
2019-03-14T22:27:15.920Z,1552602435.920 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:27:17.110Z,1552602437.110 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:17.913Z,1552602437.913 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-03-14T22:27:19.942Z,1552602439.942 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:23.178Z,1552602443.178 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:26.002Z,1552602446.002 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:27.200Z,1552602447.200 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-03-14T22:27:28.830Z,1552602448.830 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:29.260Z,1552602449.260 [Default:A.Wait](INFO): Done Waiting.
2019-03-14T22:27:29.260Z,1552602449.260 [Default:A.Wait] Stopped
2019-03-14T22:27:29.260Z,1552602449.260 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:27:29.671Z,1552602449.671 [Default:CheckIn] Running Loop=1
2019-03-14T22:27:29.671Z,1552602449.671 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-14T22:27:29.671Z,1552602449.671 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-14T22:27:30.057Z,1552602450.057 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-03-14T22:27:32.062Z,1552602452.062 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:34.890Z,1552602454.890 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:37.296Z,1552602457.296 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-03-14T22:27:38.118Z,1552602458.118 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:27:38.512Z,1552602458.512 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222208.00,A,3648.16191,N,12147.28467,W,0.117,102.30,140319,,,A*74
2019-03-14T22:27:38.516Z,1552602458.516 [NAL9602](INFO): GPS fix at 20190314T222208: (36.802698, -121.788078)
2019-03-14T22:27:38.550Z,1552602458.550 [Default:CheckIn:Read_GPS] Stopped
2019-03-14T22:27:38.550Z,1552602458.550 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-03-14T22:27:38.976Z,1552602458.976 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-03-14T22:27:45.934Z,1552602465.934 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20190314T222355/Courier0004.lzma
2019-03-14T22:27:46.740Z,1552602466.740 [DataOverHttps](INFO): Moved sent file to Logs/20190314T222355/Courier0004.lzma.bak
2019-03-14T22:27:46.740Z,1552602466.740 [DataOverHttps](INFO): SBD MOMSN=10140675
2019-03-14T22:27:46.992Z,1552602466.992 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-03-14T22:27:57.092Z,1552602477.092 [Micromodem](INFO): Nmea out: $CCTMS,2019-03-14T22:27:58Z,0*70

2019-03-14T22:27:58.886Z,1552602478.886 [DataOverHttps](INFO): Sending 273 bytes from file Logs/20190314T222355/Express0005.lzma
2019-03-14T22:27:59.692Z,1552602479.692 [DataOverHttps](INFO): Moved sent file to Logs/20190314T222355/Express0005.lzma.bak
2019-03-14T22:27:59.692Z,1552602479.692 [DataOverHttps](INFO): SBD MOMSN=10140678
2019-03-14T22:28:00.753Z,1552602480.753 [Default:CheckIn:Read_Iridium] Stopped
2019-03-14T22:28:00.753Z,1552602480.753 [Default:CheckIn:C.Wait] Running Loop=1
2019-03-14T22:28:00.753Z,1552602480.753 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:28:07.637Z,1552602487.637 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:28:07.637Z,1552602487.637 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-03-14T22:28:07.637Z,1552602487.637 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:28:07.644Z,1552602487.644 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:28:07.644Z,1552602487.644 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-03-14T22:28:07.644Z,1552602487.644 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:28:07.645Z,1552602487.645 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:28:07.646Z,1552602487.646 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-14T22:28:07.646Z,1552602487.646 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:28:07.669Z,1552602487.669 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:28:07.669Z,1552602487.669 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:28:07.669Z,1552602487.669 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:28:08.075Z,1552602488.075 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:28:08.075Z,1552602488.075 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-03-14T22:28:08.076Z,1552602488.076 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:28:08.076Z,1552602488.076 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-03-14T22:28:08.076Z,1552602488.076 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:28:08.076Z,1552602488.076 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-14T22:28:08.429Z,1552602488.429 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:28:10.827Z,1552602490.827 [NAL9602](INFO): Powering down
2019-03-14T22:29:56.697Z,1552602596.697 [Micromodem](FAULT): LCB 2 fault: 
2019-03-14T22:29:56.697Z,1552602596.697 [Micromodem] Hardware Fault, FailCount= 2
2019-03-14T22:29:56.697Z,1552602596.697 [Micromodem](ERROR): Hardware Fault
2019-03-14T22:29:56.697Z,1552602596.697 [Micromodem](INFO): Powering down
2019-03-14T22:29:56.839Z,1552602596.839 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-03-14T22:29:57.099Z,1552602597.099 [Micromodem](INFO): Powering down
2019-03-14T22:29:57.500Z,1552602597.500 [Micromodem](FAULT): LCB 2 fault:  Software Overcurrent.
2019-03-14T22:29:57.938Z,1552602597.938 [CBIT](INFO): Clearing failed state for component Micromodem
2019-03-14T22:29:57.938Z,1552602597.938 [Micromodem] No Fault, FailCount= 2
2019-03-14T22:30:00.728Z,1552602600.728 [Micromodem](INFO): Powering up
2019-03-14T22:30:00.728Z,1552602600.728 [Micromodem](DEBUG): Initializing Micromodem.
2019-03-14T22:30:05.580Z,1552602605.580 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-03-14T22:30:08.439Z,1552602608.439 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:30:08.439Z,1552602608.439 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-03-14T22:30:08.439Z,1552602608.439 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:30:08.441Z,1552602608.441 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:30:08.441Z,1552602608.441 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2019-03-14T22:30:08.441Z,1552602608.441 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:30:08.443Z,1552602608.443 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:30:08.443Z,1552602608.443 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 2
2019-03-14T22:30:08.443Z,1552602608.443 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:30:08.454Z,1552602608.454 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:30:08.454Z,1552602608.454 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:30:08.455Z,1552602608.455 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:30:08.863Z,1552602608.863 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:30:08.863Z,1552602608.863 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-03-14T22:30:08.864Z,1552602608.864 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:30:08.864Z,1552602608.864 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2019-03-14T22:30:08.865Z,1552602608.865 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:30:08.865Z,1552602608.865 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 2
2019-03-14T22:30:09.258Z,1552602609.258 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:30:16.888Z,1552602616.888 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-03-14T22:30:22.552Z,1552602622.552 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-03-14T22:30:32.647Z,1552602632.647 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-03-14T22:30:32.665Z,1552602632.665 [CommandLine](IMPORTANT): got command show stack
2019-03-14T22:30:32.665Z,1552602632.665 [CommandLine](IMPORTANT): Behavior Stack:

2019-03-14T22:30:32.665Z,1552602632.665 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-03-14T22:30:32.666Z,1552602632.666 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-03-14T22:30:34.187Z,1552602634.187 [CommandLine](IMPORTANT): got command report 
2019-03-14T22:30:34.187Z,1552602634.187 [Reporter](INFO): DUSBL_Hydroid.range reporting when touched
2019-03-14T22:30:34.188Z,1552602634.188 [Reporter](INFO): DUSBL_Hydroid.xAngle reporting when touched
2019-03-14T22:30:39.392Z,1552602639.392 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:30:39.392Z,1552602639.392 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:30:39.477Z,1552602639.477 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-03-14T22:30:39.481Z,1552602639.481 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-03-14T22:30:39.485Z,1552602639.485 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-03-14T22:30:39.500Z,1552602639.500 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-03-14T22:30:39.579Z,1552602639.579 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = 1.000000 bool
2019-03-14T22:30:39.581Z,1552602639.581 [DUSBL:A.Pitch](DEBUG): Construct.
2019-03-14T22:30:39.607Z,1552602639.607 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-03-14T22:30:39.644Z,1552602639.644 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-03-14T22:30:39.664Z,1552602639.664 [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><Science: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>
        <While>
            <Arg Name="EnabledDUSBL"/>
        </While>
        <Sensor:DUSBL_Hydroid.range/>
        <Sensor:DUSBL_Hydroid.direction/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

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


2019-03-14T22:30:39.666Z,1552602639.666 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:30:39.968Z,1552602639.968 [Default] Stopped
2019-03-14T22:30:39.968Z,1552602639.968 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-14T22:30:39.969Z,1552602639.969 [Default:B.GoToSurface] Stopped
2019-03-14T22:30:39.969Z,1552602639.969 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-14T22:30:39.969Z,1552602639.969 [Default:CheckIn] Stopped
2019-03-14T22:30:39.969Z,1552602639.969 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-14T22:30:39.969Z,1552602639.969 [Default:CheckIn:C.Wait] Stopped
2019-03-14T22:30:39.969Z,1552602639.969 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:30:39.969Z,1552602639.969 [MissionManager](IMPORTANT): Started mission DUSBL
2019-03-14T22:30:39.969Z,1552602639.969 [DUSBL] Running Loop=1
2019-03-14T22:30:39.970Z,1552602639.970 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-03-14T22:30:39.970Z,1552602639.970 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:30:39.970Z,1552602639.970 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-03-14T22:30:39.970Z,1552602639.970 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:30:39.970Z,1552602639.970 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-03-14T22:30:39.970Z,1552602639.970 [DUSBL:C] Running Loop=1
2019-03-14T22:30:39.970Z,1552602639.970 [DUSBL:RequestRepeater] Running Loop=1
2019-03-14T22:30:39.971Z,1552602639.971 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:30:39.971Z,1552602639.971 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:30:39.971Z,1552602639.971 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:30:39.971Z,1552602639.971 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:30:39.971Z,1552602639.971 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:30:39.971Z,1552602639.971 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:30:39.971Z,1552602639.971 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:30:39.972Z,1552602639.972 [DUSBL:C] Running Loop=1
2019-03-14T22:30:39.972Z,1552602639.972 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.range
2019-03-14T22:30:39.973Z,1552602639.973 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.direction
2019-03-14T22:30:39.973Z,1552602639.973 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:30:39.973Z,1552602639.973 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:30:41.533Z,1552602641.533 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:30:42.745Z,1552602642.745 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-03-14T22:30:45.578Z,1552602645.578 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:30:49.613Z,1552602649.613 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:30:50.070Z,1552602650.070 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:30:50.070Z,1552602650.070 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:30:50.070Z,1552602650.070 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:30:50.071Z,1552602650.071 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:30:50.071Z,1552602650.071 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:30:50.071Z,1552602650.071 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:30:50.071Z,1552602650.071 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:30:50.071Z,1552602650.071 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:30:50.071Z,1552602650.071 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-03-14T22:30:50.071Z,1552602650.071 [DUSBL:RequestRepeater] Running Loop=2
2019-03-14T22:30:50.072Z,1552602650.072 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:30:50.072Z,1552602650.072 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:30:50.072Z,1552602650.072 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:30:50.072Z,1552602650.072 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:30:50.072Z,1552602650.072 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:30:51.371Z,1552602651.371 [CommandLine](IMPORTANT): got command stop
2019-03-14T22:30:51.371Z,1552602651.371 [CommandLine](IMPORTANT): Scheduling is paused
2019-03-14T22:30:51.371Z,1552602651.371 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-03-14T22:30:51.662Z,1552602651.662 [MissionManager](INFO): MissionManager is completed.
2019-03-14T22:30:51.662Z,1552602651.662 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-03-14T22:30:51.662Z,1552602651.662 [DUSBL] Stopped
2019-03-14T22:30:51.662Z,1552602651.662 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:A.Pitch] Stopped
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:B.SetSpeed] Stopped
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:C] Stopped
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:30:51.663Z,1552602651.663 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:30:52.076Z,1552602652.076 [MissionManager](IMPORTANT): Started mission Default
2019-03-14T22:30:52.076Z,1552602652.076 [Default] Running Loop=1
2019-03-14T22:30:52.076Z,1552602652.076 [Default](DEBUG): Aggregate::initialize Default
2019-03-14T22:30:52.076Z,1552602652.076 [Default:B.GoToSurface] Running Loop=1
2019-03-14T22:30:52.077Z,1552602652.077 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-14T22:30:52.077Z,1552602652.077 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-14T22:30:52.077Z,1552602652.077 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-14T22:30:52.077Z,1552602652.077 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-14T22:30:52.078Z,1552602652.078 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-14T22:30:52.078Z,1552602652.078 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-14T22:30:52.078Z,1552602652.078 [Default:A.Wait] Running Loop=1
2019-03-14T22:30:52.078Z,1552602652.078 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:30:52.451Z,1552602652.451 [Micromodem](INFO): Nmea out: $CCTMS,2019-03-14T22:30:53Z,0*7D

2019-03-14T22:30:53.653Z,1552602653.653 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,223053,COPROC,0.10..46*5
$CATMS,0,2019-03-14T22:30:53Z*7F

2019-03-14T22:30:58.138Z,1552602658.138 [Micromodem](ERROR): Response from modem unexpected: $CATMG,2019-03-14T22:30:53Z,USER_CMD,RTC*36

2019-03-14T22:30:58.504Z,1552602658.504 [Micromodem](ERROR): Response from modem unexpected: $CADQF,195,1*5D

2019-03-14T22:30:58.906Z,1552602658.906 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-03-14T22:30:59.311Z,1552602659.311 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190314223056.809644,06,154,15,0090,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,195,0.00,-999,9760,4000*58

2019-03-14T22:31:01.575Z,1552602661.575 [CommandLine](IMPORTANT): got command failComponent
2019-03-14T22:31:01.575Z,1552602661.575 [CommandLine](IMPORTANT): Failed components:
2019-03-14T22:31:01.575Z,1552602661.575 [CommandLine](IMPORTANT): No failed Components.
2019-03-14T22:31:03.759Z,1552602663.759 [Micromodem](ERROR): Nmea resend: $CCTMS,2019-03-14T22:30:53Z,0*7D

2019-03-14T22:31:05.425Z,1552602665.425 [Default:A.Wait](INFO): Done Waiting.
2019-03-14T22:31:05.425Z,1552602665.425 [Default:A.Wait] Stopped
2019-03-14T22:31:05.425Z,1552602665.425 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:31:05.848Z,1552602665.848 [Default:CheckIn] Running Loop=1
2019-03-14T22:31:05.848Z,1552602665.848 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-14T22:31:05.849Z,1552602665.849 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-14T22:31:06.592Z,1552602666.592 [NAL9602](INFO): Powering up
2019-03-14T22:31:10.027Z,1552602670.027 [DeadReckonWithRespectToSeafloor](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-03-14T22:31:10.028Z,1552602670.028 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 3
2019-03-14T22:31:10.028Z,1552602670.028 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:31:10.076Z,1552602670.076 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:31:10.277Z,1552602670.277 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:31:10.277Z,1552602670.277 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 3
2019-03-14T22:31:17.496Z,1552602677.496 [NAL9602](INFO): NAL9602 initialized
2019-03-14T22:31:18.314Z,1552602678.314 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:31:29.228Z,1552602689.228 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-03-14T22:31:40.459Z,1552602700.459 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:31:40.459Z,1552602700.459 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:31:40.496Z,1552602700.496 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-03-14T22:31:40.499Z,1552602700.499 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-03-14T22:31:40.501Z,1552602700.501 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-03-14T22:31:40.503Z,1552602700.503 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-03-14T22:31:40.505Z,1552602700.505 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = 1.000000 bool
2019-03-14T22:31:40.534Z,1552602700.534 [DUSBL:A.Pitch](DEBUG): Construct.
2019-03-14T22:31:40.606Z,1552602700.606 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-03-14T22:31:40.629Z,1552602700.629 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-03-14T22:31:40.657Z,1552602700.657 [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><Science: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>
        <While>
            <Arg Name="EnabledDUSBL"/>
        </While>
        <Sensor:DUSBL_Hydroid.range/>
        <Sensor:DUSBL_Hydroid.direction/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

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


2019-03-14T22:31:40.667Z,1552602700.667 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:31:40.997Z,1552602700.997 [Default] Stopped
2019-03-14T22:31:40.997Z,1552602700.997 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-14T22:31:40.997Z,1552602700.997 [Default:B.GoToSurface] Stopped
2019-03-14T22:31:40.997Z,1552602700.997 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-14T22:31:40.997Z,1552602700.997 [Default:CheckIn] Stopped
2019-03-14T22:31:40.997Z,1552602700.997 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-14T22:31:40.997Z,1552602700.997 [Default:CheckIn:Read_GPS] Stopped
2019-03-14T22:31:40.998Z,1552602700.998 [MissionManager](IMPORTANT): Started mission DUSBL
2019-03-14T22:31:40.998Z,1552602700.998 [DUSBL] Running Loop=1
2019-03-14T22:31:41.002Z,1552602701.002 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-03-14T22:31:41.002Z,1552602701.002 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:31:41.002Z,1552602701.002 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:C] Running Loop=1
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:RequestRepeater] Running Loop=1
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:31:41.003Z,1552602701.003 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:31:41.004Z,1552602701.004 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:31:41.004Z,1552602701.004 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:31:41.004Z,1552602701.004 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:31:41.004Z,1552602701.004 [DUSBL:C] Running Loop=1
2019-03-14T22:31:41.005Z,1552602701.005 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.range
2019-03-14T22:31:41.005Z,1552602701.005 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.direction
2019-03-14T22:31:41.006Z,1552602701.006 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:31:41.006Z,1552602701.006 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:31:42.536Z,1552602702.536 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:31:42.538Z,1552602702.538 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:31:46.583Z,1552602706.583 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:31:46.587Z,1552602706.587 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:31:47.048Z,1552602707.048 [Reporter](INFO): DUSBL_Hydroid.range 4.559999 m
2019-03-14T22:31:47.049Z,1552602707.049 [Reporter](INFO): DUSBL_Hydroid.xAngle -3.700000 arcdeg
2019-03-14T22:31:50.616Z,1552602710.616 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:31:50.621Z,1552602710.621 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:31:51.077Z,1552602711.077 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:31:51.077Z,1552602711.077 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:31:51.077Z,1552602711.077 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:31:51.077Z,1552602711.077 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater] Running Loop=2
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:31:51.078Z,1552602711.078 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:31:51.079Z,1552602711.079 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:31:51.079Z,1552602711.079 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:31:51.079Z,1552602711.079 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:31:54.657Z,1552602714.657 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:31:54.660Z,1552602714.660 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:31:58.696Z,1552602718.696 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:31:58.700Z,1552602718.700 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:01.557Z,1552602721.557 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:32:01.557Z,1552602721.557 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:32:01.557Z,1552602721.557 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:32:01.558Z,1552602721.558 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:32:01.558Z,1552602721.558 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:32:01.558Z,1552602721.558 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:32:01.558Z,1552602721.558 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:32:01.558Z,1552602721.558 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:32:01.558Z,1552602721.558 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-03-14T22:32:01.559Z,1552602721.559 [DUSBL:RequestRepeater] Running Loop=3
2019-03-14T22:32:01.559Z,1552602721.559 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:32:01.559Z,1552602721.559 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:32:01.559Z,1552602721.559 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:32:01.559Z,1552602721.559 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:32:01.559Z,1552602721.559 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:32:02.737Z,1552602722.737 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:02.741Z,1552602722.741 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:06.777Z,1552602726.777 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:06.781Z,1552602726.781 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:07.235Z,1552602727.235 [Reporter](INFO): DUSBL_Hydroid.range 4.559999 m
2019-03-14T22:32:07.236Z,1552602727.236 [Reporter](INFO): DUSBL_Hydroid.xAngle -9.000000 arcdeg
2019-03-14T22:32:09.637Z,1552602729.637 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:32:09.637Z,1552602729.637 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-03-14T22:32:09.637Z,1552602729.637 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:32:09.639Z,1552602729.639 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:32:09.640Z,1552602729.640 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2019-03-14T22:32:09.640Z,1552602729.640 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:32:09.652Z,1552602729.652 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:32:09.652Z,1552602729.652 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:32:10.063Z,1552602730.063 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:32:10.063Z,1552602730.063 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-03-14T22:32:10.064Z,1552602730.064 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:32:10.064Z,1552602730.064 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2019-03-14T22:32:10.445Z,1552602730.445 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:32:10.825Z,1552602730.825 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:10.829Z,1552602730.829 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:12.062Z,1552602732.062 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:32:12.062Z,1552602732.062 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:32:12.063Z,1552602732.063 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:32:12.063Z,1552602732.063 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:32:12.063Z,1552602732.063 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:32:12.063Z,1552602732.063 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:32:12.063Z,1552602732.063 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:32:12.063Z,1552602732.063 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:32:12.064Z,1552602732.064 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-03-14T22:32:12.064Z,1552602732.064 [DUSBL:RequestRepeater] Running Loop=4
2019-03-14T22:32:12.064Z,1552602732.064 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:32:12.064Z,1552602732.064 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:32:12.064Z,1552602732.064 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:32:12.064Z,1552602732.064 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:32:12.064Z,1552602732.064 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:32:14.864Z,1552602734.864 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:14.869Z,1552602734.869 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:18.897Z,1552602738.897 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:18.901Z,1552602738.901 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:22.581Z,1552602742.581 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:32:22.581Z,1552602742.581 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:32:22.581Z,1552602742.581 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:32:22.582Z,1552602742.582 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:32:22.582Z,1552602742.582 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:32:22.582Z,1552602742.582 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:32:22.582Z,1552602742.582 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:32:22.582Z,1552602742.582 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:32:22.583Z,1552602742.583 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-03-14T22:32:22.583Z,1552602742.583 [DUSBL:RequestRepeater] Running Loop=5
2019-03-14T22:32:22.583Z,1552602742.583 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:32:22.583Z,1552602742.583 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:32:22.583Z,1552602742.583 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:32:22.583Z,1552602742.583 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:32:22.583Z,1552602742.583 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:32:22.940Z,1552602742.940 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:22.945Z,1552602742.945 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:26.987Z,1552602746.987 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:26.992Z,1552602746.992 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:31.017Z,1552602751.017 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:31.020Z,1552602751.020 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:33.070Z,1552602753.070 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:32:33.070Z,1552602753.070 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:32:33.070Z,1552602753.070 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater] Running Loop=6
2019-03-14T22:32:33.071Z,1552602753.071 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:32:33.072Z,1552602753.072 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:32:33.072Z,1552602753.072 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:32:33.072Z,1552602753.072 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:32:33.072Z,1552602753.072 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:32:35.056Z,1552602755.056 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:35.060Z,1552602755.060 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:39.096Z,1552602759.096 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:39.103Z,1552602759.103 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:39.501Z,1552602759.501 [Micromodem](ERROR): Response from modem unexpected: $CADQF,200,1*52

2019-03-14T22:32:39.503Z,1552602759.503 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-03-14T22:32:39.918Z,1552602759.918 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190314223226.765130,06,343,13,0095,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,200,-0.05,-999,9760,4000*7C

2019-03-14T22:32:43.137Z,1552602763.137 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:43.140Z,1552602763.140 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:43.573Z,1552602763.573 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:32:43.573Z,1552602763.573 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:32:43.573Z,1552602763.573 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater] Running Loop=7
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:32:43.575Z,1552602763.575 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:32:43.576Z,1552602763.576 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:32:43.576Z,1552602763.576 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:32:47.176Z,1552602767.176 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:47.180Z,1552602767.180 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:51.224Z,1552602771.224 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:51.242Z,1552602771.242 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:54.078Z,1552602774.078 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:32:54.078Z,1552602774.078 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:32:54.079Z,1552602774.079 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:32:54.079Z,1552602774.079 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:32:54.079Z,1552602774.079 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater] Running Loop=8
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:32:54.080Z,1552602774.080 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:32:55.260Z,1552602775.260 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:55.264Z,1552602775.264 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:59.296Z,1552602779.296 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:32:59.300Z,1552602779.300 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:32:59.750Z,1552602779.750 [Reporter](INFO): DUSBL_Hydroid.range 90.600006 m
2019-03-14T22:32:59.751Z,1552602779.751 [Reporter](INFO): DUSBL_Hydroid.xAngle 57.349998 arcdeg
2019-03-14T22:33:03.340Z,1552602783.340 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:03.345Z,1552602783.345 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:33:04.589Z,1552602784.589 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:33:04.589Z,1552602784.589 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:33:04.589Z,1552602784.589 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:33:04.590Z,1552602784.590 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:33:04.590Z,1552602784.590 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater] Running Loop=9
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:33:04.591Z,1552602784.591 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:33:07.380Z,1552602787.380 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:07.384Z,1552602787.384 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:33:11.052Z,1552602791.052 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:33:11.052Z,1552602791.052 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 4
2019-03-14T22:33:11.052Z,1552602791.052 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:33:11.064Z,1552602791.064 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:33:11.420Z,1552602791.420 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:11.431Z,1552602791.431 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:33:11.513Z,1552602791.513 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:33:11.513Z,1552602791.513 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 4
2019-03-14T22:33:15.099Z,1552602795.099 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:33:15.099Z,1552602795.099 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:33:15.099Z,1552602795.099 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:33:15.100Z,1552602795.100 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:33:15.100Z,1552602795.100 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:33:15.100Z,1552602795.100 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:33:15.100Z,1552602795.100 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:33:15.100Z,1552602795.100 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:33:15.100Z,1552602795.100 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-03-14T22:33:15.100Z,1552602795.100 [DUSBL:RequestRepeater] Running Loop=10
2019-03-14T22:33:15.101Z,1552602795.101 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:33:15.101Z,1552602795.101 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:33:15.101Z,1552602795.101 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:33:15.101Z,1552602795.101 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:33:15.101Z,1552602795.101 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:33:15.464Z,1552602795.464 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:15.470Z,1552602795.470 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:33:15.874Z,1552602795.874 [Micromodem](ERROR): Response from modem unexpected: $CADQF,189,1*50

2019-03-14T22:33:15.877Z,1552602795.877 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-03-14T22:33:16.274Z,1552602796.274 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190314223302.948024,06,169,16,0094,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,189,0.00,-999,9760,4000*5A

2019-03-14T22:33:19.497Z,1552602799.497 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:19.500Z,1552602799.500 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:33:23.537Z,1552602803.537 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:23.540Z,1552602803.540 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:33:25.585Z,1552602805.585 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:33:25.585Z,1552602805.585 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:33:25.585Z,1552602805.585 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:33:25.586Z,1552602805.586 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:33:25.587Z,1552602805.587 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:33:25.587Z,1552602805.587 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:33:25.587Z,1552602805.587 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:33:25.587Z,1552602805.587 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:33:25.587Z,1552602805.587 [DUSBL](INFO): Completed DUSBL
2019-03-14T22:33:25.588Z,1552602805.588 [MissionManager](INFO): DUSBL is completed.
2019-03-14T22:33:25.588Z,1552602805.588 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-03-14T22:33:25.588Z,1552602805.588 [DUSBL] Stopped
2019-03-14T22:33:25.588Z,1552602805.588 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-03-14T22:33:25.588Z,1552602805.588 [DUSBL:A.Pitch] Stopped
2019-03-14T22:33:25.588Z,1552602805.588 [DUSBL:B.SetSpeed] Stopped
2019-03-14T22:33:25.588Z,1552602805.588 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-03-14T22:33:25.588Z,1552602805.588 [DUSBL:C] Stopped
2019-03-14T22:33:26.023Z,1552602806.023 [MissionManager](IMPORTANT): Started mission Default
2019-03-14T22:33:26.023Z,1552602806.023 [Default] Running Loop=1
2019-03-14T22:33:26.023Z,1552602806.023 [Default](DEBUG): Aggregate::initialize Default
2019-03-14T22:33:26.023Z,1552602806.023 [Default:B.GoToSurface] Running Loop=1
2019-03-14T22:33:26.023Z,1552602806.023 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-14T22:33:26.023Z,1552602806.023 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-14T22:33:26.024Z,1552602806.024 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-14T22:33:26.024Z,1552602806.024 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-14T22:33:26.024Z,1552602806.024 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-14T22:33:26.025Z,1552602806.025 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-14T22:33:26.025Z,1552602806.025 [Default:A.Wait] Running Loop=1
2019-03-14T22:33:26.025Z,1552602806.025 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:33:30.000Z,1552602810.000 [Micromodem](FAULT): LCB 2 fault: 
2019-03-14T22:33:30.000Z,1552602810.000 [Micromodem] Hardware Fault, FailCount= 3
2019-03-14T22:33:30.000Z,1552602810.000 [Micromodem](ERROR): Hardware Fault
2019-03-14T22:33:30.001Z,1552602810.001 [Micromodem](INFO): Powering down
2019-03-14T22:33:30.016Z,1552602810.016 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:33:30.016Z,1552602810.016 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:33:30.041Z,1552602810.041 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-03-14T22:33:30.060Z,1552602810.060 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-03-14T22:33:30.062Z,1552602810.062 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-03-14T22:33:30.080Z,1552602810.080 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-03-14T22:33:30.096Z,1552602810.096 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = 1.000000 bool
2019-03-14T22:33:30.119Z,1552602810.119 [DUSBL:A.Pitch](DEBUG): Construct.
2019-03-14T22:33:30.132Z,1552602810.132 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-03-14T22:33:30.159Z,1552602810.159 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-03-14T22:33:30.171Z,1552602810.171 [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><Science: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>
        <While>
            <Arg Name="EnabledDUSBL"/>
        </While>
        <Sensor:DUSBL_Hydroid.range/>
        <Sensor:DUSBL_Hydroid.direction/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

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


2019-03-14T22:33:30.173Z,1552602810.173 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:33:30.198Z,1552602810.198 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-03-14T22:33:30.411Z,1552602810.411 [Micromodem](INFO): Powering down
2019-03-14T22:33:30.440Z,1552602810.440 [Default] Stopped
2019-03-14T22:33:30.441Z,1552602810.441 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-14T22:33:30.441Z,1552602810.441 [Default:A.Wait] Stopped
2019-03-14T22:33:30.441Z,1552602810.441 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:33:30.441Z,1552602810.441 [Default:B.GoToSurface] Stopped
2019-03-14T22:33:30.441Z,1552602810.441 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-14T22:33:30.441Z,1552602810.441 [MissionManager](IMPORTANT): Started mission DUSBL
2019-03-14T22:33:30.441Z,1552602810.441 [DUSBL] Running Loop=1
2019-03-14T22:33:30.441Z,1552602810.441 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-03-14T22:33:30.441Z,1552602810.441 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:33:30.442Z,1552602810.442 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-03-14T22:33:30.442Z,1552602810.442 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:33:30.442Z,1552602810.442 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-03-14T22:33:30.442Z,1552602810.442 [DUSBL:C] Running Loop=1
2019-03-14T22:33:30.442Z,1552602810.442 [DUSBL:RequestRepeater] Running Loop=1
2019-03-14T22:33:30.442Z,1552602810.442 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:33:30.443Z,1552602810.443 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:33:30.443Z,1552602810.443 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:33:30.443Z,1552602810.443 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:33:30.443Z,1552602810.443 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:33:30.443Z,1552602810.443 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:33:30.443Z,1552602810.443 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:33:30.444Z,1552602810.444 [DUSBL:C] Running Loop=1
2019-03-14T22:33:30.444Z,1552602810.444 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.range
2019-03-14T22:33:30.445Z,1552602810.445 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.direction
2019-03-14T22:33:30.445Z,1552602810.445 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:33:30.445Z,1552602810.445 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:33:30.813Z,1552602810.813 [Micromodem](FAULT): LCB 2 fault:  Software Overcurrent.
2019-03-14T22:33:31.258Z,1552602811.258 [CBIT](INFO): Clearing failed state for component Micromodem
2019-03-14T22:33:31.258Z,1552602811.258 [Micromodem] No Fault, FailCount= 3
2019-03-14T22:33:32.020Z,1552602812.020 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:32.487Z,1552602812.487 [Reporter](INFO): DUSBL_Hydroid.range 90.540001 m
2019-03-14T22:33:32.488Z,1552602812.488 [Reporter](INFO): DUSBL_Hydroid.xAngle 52.500000 arcdeg
2019-03-14T22:33:34.040Z,1552602814.040 [Micromodem](INFO): Powering up
2019-03-14T22:33:34.040Z,1552602814.040 [Micromodem](DEBUG): Initializing Micromodem.
2019-03-14T22:33:36.060Z,1552602816.060 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:38.888Z,1552602818.888 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-03-14T22:33:40.101Z,1552602820.101 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:40.530Z,1552602820.530 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:33:40.530Z,1552602820.530 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:33:40.530Z,1552602820.530 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater] Running Loop=2
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:33:40.531Z,1552602820.531 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:33:40.532Z,1552602820.532 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:33:44.141Z,1552602824.141 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:48.180Z,1552602828.180 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:50.200Z,1552602830.200 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-03-14T22:33:51.049Z,1552602831.049 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:33:51.049Z,1552602831.049 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:33:51.049Z,1552602831.049 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:33:51.049Z,1552602831.049 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:33:51.050Z,1552602831.050 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:33:51.050Z,1552602831.050 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:33:51.050Z,1552602831.050 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:33:51.050Z,1552602831.050 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:33:51.050Z,1552602831.050 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-03-14T22:33:51.050Z,1552602831.050 [DUSBL:RequestRepeater] Running Loop=3
2019-03-14T22:33:51.050Z,1552602831.050 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:33:51.051Z,1552602831.051 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:33:51.051Z,1552602831.051 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:33:51.051Z,1552602831.051 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:33:51.051Z,1552602831.051 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:33:51.412Z,1552602831.412 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-03-14T22:33:52.224Z,1552602832.224 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:33:56.261Z,1552602836.261 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:00.308Z,1552602840.308 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:01.109Z,1552602841.109 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-03-14T22:34:01.545Z,1552602841.545 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:34:01.545Z,1552602841.545 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:34:01.545Z,1552602841.545 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:34:01.546Z,1552602841.546 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:34:01.546Z,1552602841.546 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:34:01.546Z,1552602841.546 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:34:01.546Z,1552602841.546 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:34:01.546Z,1552602841.546 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:34:01.547Z,1552602841.547 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-03-14T22:34:01.547Z,1552602841.547 [DUSBL:RequestRepeater] Running Loop=4
2019-03-14T22:34:01.547Z,1552602841.547 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:34:01.547Z,1552602841.547 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:34:01.547Z,1552602841.547 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:34:01.547Z,1552602841.547 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:34:01.547Z,1552602841.547 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:34:01.917Z,1552602841.917 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CARE,2334,CPRC0.1.04*4D

2019-03-14T22:34:04.344Z,1552602844.344 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:08.380Z,1552602848.380 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:10.845Z,1552602850.845 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:34:10.845Z,1552602850.845 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-03-14T22:34:10.845Z,1552602850.845 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:34:10.847Z,1552602850.847 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:34:10.847Z,1552602850.847 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2019-03-14T22:34:10.847Z,1552602850.847 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:34:10.859Z,1552602850.859 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:34:10.860Z,1552602850.860 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:34:11.217Z,1552602851.217 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-03-14T22:34:11.268Z,1552602851.268 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:34:11.268Z,1552602851.268 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-03-14T22:34:11.269Z,1552602851.269 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:34:11.269Z,1552602851.269 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2019-03-14T22:34:11.657Z,1552602851.657 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:34:12.052Z,1552602852.052 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:34:12.052Z,1552602852.052 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:34:12.052Z,1552602852.052 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:34:12.053Z,1552602852.053 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:34:12.053Z,1552602852.053 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:34:12.053Z,1552602852.053 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater] Running Loop=5
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:34:12.054Z,1552602852.054 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:34:12.055Z,1552602852.055 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:34:12.428Z,1552602852.428 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:13.229Z,1552602853.229 [Micromodem](INFO): Nmea out: $CCTMS,2019-03-14T22:34:14Z,0*7A

2019-03-14T22:34:13.636Z,1552602853.636 [Micromodem](ERROR): Response from modem unexpected: $CADQF,191,1*59

2019-03-14T22:34:14.041Z,1552602854.041 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-03-14T22:34:14.445Z,1552602854.445 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190314223400.670806,05,121,14,0093,0150,246,00,00,01,00,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,191,0.00,-999,9760,4000*52

2019-03-14T22:34:16.461Z,1552602856.461 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:16.465Z,1552602856.465 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:34:16.866Z,1552602856.866 [Micromodem](ERROR): Response from modem unexpected: $CATMG,2019-03-14T22:34:14Z,USER_CMD,RTC*31

2019-03-14T22:34:17.576Z,1552602857.576 [CommandLine](IMPORTANT): got command stop
2019-03-14T22:34:17.576Z,1552602857.576 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-03-14T22:34:17.713Z,1552602857.713 [MissionManager](INFO): MissionManager is completed.
2019-03-14T22:34:17.714Z,1552602857.714 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL] Stopped
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL:A.Pitch] Stopped
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL:B.SetSpeed] Stopped
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL:C] Stopped
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:34:17.714Z,1552602857.714 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:34:17.715Z,1552602857.715 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:34:17.715Z,1552602857.715 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:34:17.715Z,1552602857.715 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:34:18.110Z,1552602858.110 [MissionManager](IMPORTANT): Started mission Default
2019-03-14T22:34:18.110Z,1552602858.110 [Default] Running Loop=1
2019-03-14T22:34:18.111Z,1552602858.111 [Default](DEBUG): Aggregate::initialize Default
2019-03-14T22:34:18.111Z,1552602858.111 [Default:B.GoToSurface] Running Loop=1
2019-03-14T22:34:18.111Z,1552602858.111 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-14T22:34:18.111Z,1552602858.111 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-14T22:34:18.111Z,1552602858.111 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-14T22:34:18.112Z,1552602858.112 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-14T22:34:18.112Z,1552602858.112 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-14T22:34:18.112Z,1552602858.112 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-14T22:34:18.112Z,1552602858.112 [Default:A.Wait] Running Loop=1
2019-03-14T22:34:18.113Z,1552602858.113 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:34:31.445Z,1552602871.445 [Default:A.Wait](INFO): Done Waiting.
2019-03-14T22:34:31.445Z,1552602871.445 [Default:A.Wait] Stopped
2019-03-14T22:34:31.446Z,1552602871.446 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:34:31.857Z,1552602871.857 [Default:CheckIn] Running Loop=1
2019-03-14T22:34:31.857Z,1552602871.857 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-14T22:34:31.857Z,1552602871.857 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-14T22:34:37.139Z,1552602877.139 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:34:37.139Z,1552602877.139 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:34:37.207Z,1552602877.207 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-03-14T22:34:37.209Z,1552602877.209 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-03-14T22:34:37.215Z,1552602877.215 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-03-14T22:34:37.217Z,1552602877.217 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-03-14T22:34:37.232Z,1552602877.232 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = 1.000000 bool
2019-03-14T22:34:37.233Z,1552602877.233 [DUSBL:A.Pitch](DEBUG): Construct.
2019-03-14T22:34:37.242Z,1552602877.242 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-03-14T22:34:37.284Z,1552602877.284 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-03-14T22:34:37.313Z,1552602877.313 [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><Science: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>
        <While>
            <Arg Name="EnabledDUSBL"/>
        </While>
        <Sensor:DUSBL_Hydroid.range/>
        <Sensor:DUSBL_Hydroid.direction/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

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


2019-03-14T22:34:37.314Z,1552602877.314 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-03-14T22:34:37.525Z,1552602877.525 [Default] Stopped
2019-03-14T22:34:37.525Z,1552602877.525 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-14T22:34:37.525Z,1552602877.525 [Default:B.GoToSurface] Stopped
2019-03-14T22:34:37.525Z,1552602877.525 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-14T22:34:37.525Z,1552602877.525 [Default:CheckIn] Stopped
2019-03-14T22:34:37.525Z,1552602877.525 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-14T22:34:37.526Z,1552602877.526 [Default:CheckIn:Read_GPS] Stopped
2019-03-14T22:34:37.526Z,1552602877.526 [MissionManager](IMPORTANT): Started mission DUSBL
2019-03-14T22:34:37.530Z,1552602877.530 [DUSBL] Running Loop=1
2019-03-14T22:34:37.530Z,1552602877.530 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-03-14T22:34:37.531Z,1552602877.531 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:34:37.531Z,1552602877.531 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-03-14T22:34:37.531Z,1552602877.531 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:34:37.531Z,1552602877.531 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-03-14T22:34:37.531Z,1552602877.531 [DUSBL:C] Running Loop=1
2019-03-14T22:34:37.531Z,1552602877.531 [DUSBL:RequestRepeater] Running Loop=1
2019-03-14T22:34:37.531Z,1552602877.531 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:34:37.532Z,1552602877.532 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:34:37.532Z,1552602877.532 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:34:37.532Z,1552602877.532 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:34:37.532Z,1552602877.532 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:34:37.532Z,1552602877.532 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:34:37.532Z,1552602877.532 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:34:37.533Z,1552602877.533 [DUSBL:C] Running Loop=1
2019-03-14T22:34:37.533Z,1552602877.533 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.range
2019-03-14T22:34:37.534Z,1552602877.534 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.direction
2019-03-14T22:34:37.534Z,1552602877.534 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-14T22:34:37.538Z,1552602877.538 [DUSBL:A.Pitch] Running Loop=1
2019-03-14T22:34:39.092Z,1552602879.092 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:39.096Z,1552602879.096 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:34:43.124Z,1552602883.124 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:43.129Z,1552602883.129 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:34:47.172Z,1552602887.172 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:47.176Z,1552602887.176 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:34:47.605Z,1552602887.605 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:34:47.605Z,1552602887.605 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:34:47.605Z,1552602887.605 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:34:47.606Z,1552602887.606 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:34:47.606Z,1552602887.606 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:34:47.606Z,1552602887.606 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:34:47.606Z,1552602887.606 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:34:47.606Z,1552602887.606 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:34:47.607Z,1552602887.607 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-03-14T22:34:47.607Z,1552602887.607 [DUSBL:RequestRepeater] Running Loop=2
2019-03-14T22:34:47.607Z,1552602887.607 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:34:47.607Z,1552602887.607 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:34:47.607Z,1552602887.607 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:34:47.607Z,1552602887.607 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:34:47.607Z,1552602887.607 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:34:51.208Z,1552602891.208 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:51.212Z,1552602891.212 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:34:55.245Z,1552602895.245 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:55.249Z,1552602895.249 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:34:58.105Z,1552602898.105 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:34:58.105Z,1552602898.105 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:34:58.105Z,1552602898.105 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:34:58.106Z,1552602898.106 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:34:58.106Z,1552602898.106 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:34:58.106Z,1552602898.106 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater] Running Loop=3
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:34:58.107Z,1552602898.107 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:34:59.285Z,1552602899.285 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:34:59.289Z,1552602899.289 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:03.332Z,1552602903.332 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:03.336Z,1552602903.336 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:07.368Z,1552602907.368 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:07.373Z,1552602907.373 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:07.819Z,1552602907.819 [Reporter](INFO): DUSBL_Hydroid.range 4.199998 m
2019-03-14T22:35:07.820Z,1552602907.820 [Reporter](INFO): DUSBL_Hydroid.xAngle 25.350000 arcdeg
2019-03-14T22:35:08.617Z,1552602908.617 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:35:08.617Z,1552602908.617 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:35:08.617Z,1552602908.617 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:35:08.617Z,1552602908.617 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:35:08.618Z,1552602908.618 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:35:08.618Z,1552602908.618 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:35:08.618Z,1552602908.618 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:35:08.618Z,1552602908.618 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:35:08.618Z,1552602908.618 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-03-14T22:35:08.618Z,1552602908.618 [DUSBL:RequestRepeater] Running Loop=4
2019-03-14T22:35:08.618Z,1552602908.618 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:35:08.619Z,1552602908.619 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:35:08.619Z,1552602908.619 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:35:08.619Z,1552602908.619 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:35:08.619Z,1552602908.619 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:35:11.404Z,1552602911.404 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:11.405Z,1552602911.405 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:12.263Z,1552602912.263 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:35:12.263Z,1552602912.263 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 5
2019-03-14T22:35:12.263Z,1552602912.263 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:35:12.279Z,1552602912.279 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:35:12.682Z,1552602912.682 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:35:12.682Z,1552602912.682 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 5
2019-03-14T22:35:15.445Z,1552602915.445 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:15.448Z,1552602915.448 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:19.124Z,1552602919.124 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:35:19.124Z,1552602919.124 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:35:19.124Z,1552602919.124 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:35:19.125Z,1552602919.125 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:35:19.125Z,1552602919.125 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:35:19.125Z,1552602919.125 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater] Running Loop=5
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:35:19.126Z,1552602919.126 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:35:19.492Z,1552602919.492 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:19.497Z,1552602919.497 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:23.531Z,1552602923.531 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:23.535Z,1552602923.535 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:23.989Z,1552602923.989 [Reporter](INFO): DUSBL_Hydroid.range 4.380000 m
2019-03-14T22:35:23.989Z,1552602923.989 [Reporter](INFO): DUSBL_Hydroid.xAngle 8.150000 arcdeg
2019-03-14T22:35:27.568Z,1552602927.568 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:27.572Z,1552602927.572 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:28.019Z,1552602928.019 [Reporter](INFO): DUSBL_Hydroid.range 4.500001 m
2019-03-14T22:35:28.019Z,1552602928.019 [Reporter](INFO): DUSBL_Hydroid.xAngle -6.400000 arcdeg
2019-03-14T22:35:29.629Z,1552602929.629 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:35:29.629Z,1552602929.629 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:35:29.629Z,1552602929.629 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:35:29.630Z,1552602929.630 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:35:29.630Z,1552602929.630 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:35:29.630Z,1552602929.630 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:35:29.630Z,1552602929.630 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:35:29.630Z,1552602929.630 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:35:29.630Z,1552602929.630 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-03-14T22:35:29.631Z,1552602929.631 [DUSBL:RequestRepeater] Running Loop=6
2019-03-14T22:35:29.631Z,1552602929.631 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:35:29.631Z,1552602929.631 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:35:29.631Z,1552602929.631 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:35:29.631Z,1552602929.631 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:35:29.631Z,1552602929.631 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:35:31.604Z,1552602931.604 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:31.609Z,1552602931.609 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:32.108Z,1552602932.108 [Reporter](INFO): DUSBL_Hydroid.range 90.299995 m
2019-03-14T22:35:32.109Z,1552602932.109 [Reporter](INFO): DUSBL_Hydroid.xAngle 58.149997 arcdeg
2019-03-14T22:35:35.652Z,1552602935.652 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:35.656Z,1552602935.656 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:39.685Z,1552602939.685 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:39.689Z,1552602939.689 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:40.132Z,1552602940.132 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:35:40.132Z,1552602940.132 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:35:40.133Z,1552602940.133 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:35:40.133Z,1552602940.133 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:35:40.133Z,1552602940.133 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:35:40.133Z,1552602940.133 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:35:40.133Z,1552602940.133 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:35:40.133Z,1552602940.133 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:35:40.134Z,1552602940.134 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-03-14T22:35:40.134Z,1552602940.134 [DUSBL:RequestRepeater] Running Loop=7
2019-03-14T22:35:40.134Z,1552602940.134 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:35:40.134Z,1552602940.134 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:35:40.134Z,1552602940.134 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:35:40.134Z,1552602940.134 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:35:40.134Z,1552602940.134 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:35:40.144Z,1552602940.144 [Reporter](INFO): DUSBL_Hydroid.range 90.420006 m
2019-03-14T22:35:40.144Z,1552602940.144 [Reporter](INFO): DUSBL_Hydroid.xAngle 55.150000 arcdeg
2019-03-14T22:35:43.725Z,1552602943.725 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:43.729Z,1552602943.729 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:47.764Z,1552602947.764 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:47.765Z,1552602947.765 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:48.288Z,1552602948.288 [Reporter](INFO): DUSBL_Hydroid.range 90.420006 m
2019-03-14T22:35:48.289Z,1552602948.289 [Reporter](INFO): DUSBL_Hydroid.xAngle 59.049997 arcdeg
2019-03-14T22:35:50.629Z,1552602950.629 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:35:50.629Z,1552602950.629 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:35:50.629Z,1552602950.629 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:35:50.630Z,1552602950.630 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:35:50.630Z,1552602950.630 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:35:50.630Z,1552602950.630 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:35:50.630Z,1552602950.630 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:35:50.630Z,1552602950.630 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:35:50.630Z,1552602950.630 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-03-14T22:35:50.631Z,1552602950.631 [DUSBL:RequestRepeater] Running Loop=8
2019-03-14T22:35:50.631Z,1552602950.631 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:35:50.631Z,1552602950.631 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:35:50.631Z,1552602950.631 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:35:50.631Z,1552602950.631 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:35:50.631Z,1552602950.631 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:35:51.811Z,1552602951.811 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:51.819Z,1552602951.819 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:52.296Z,1552602952.296 [Reporter](INFO): DUSBL_Hydroid.range 4.380000 m
2019-03-14T22:35:52.296Z,1552602952.296 [Reporter](INFO): DUSBL_Hydroid.xAngle 10.050000 arcdeg
2019-03-14T22:35:55.854Z,1552602955.854 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:55.859Z,1552602955.859 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:35:55.870Z,1552602955.870 [NAL9602](INFO): SBD MO Status=0, MOMSN=2282, MT Status=0, MTMSN=0
2019-03-14T22:35:55.871Z,1552602955.871 [NAL9602](INFO): No messages in MT queue
2019-03-14T22:35:59.888Z,1552602959.888 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:35:59.892Z,1552602959.892 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:36:01.141Z,1552602961.141 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:36:01.141Z,1552602961.141 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:36:01.141Z,1552602961.141 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:36:01.142Z,1552602961.142 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:36:01.142Z,1552602961.142 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater] Running Loop=9
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:36:01.143Z,1552602961.143 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:36:03.926Z,1552602963.926 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:36:03.930Z,1552602963.930 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:36:07.975Z,1552602967.975 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:36:07.981Z,1552602967.981 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:36:11.641Z,1552602971.641 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:36:11.641Z,1552602971.641 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:36:11.641Z,1552602971.641 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:36:11.641Z,1552602971.641 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:36:11.641Z,1552602971.641 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:36:11.642Z,1552602971.642 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:36:11.642Z,1552602971.642 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:36:11.642Z,1552602971.642 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:36:11.642Z,1552602971.642 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-03-14T22:36:11.642Z,1552602971.642 [DUSBL:RequestRepeater] Running Loop=10
2019-03-14T22:36:11.642Z,1552602971.642 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-14T22:36:11.642Z,1552602971.642 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-14T22:36:11.643Z,1552602971.643 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-14T22:36:11.643Z,1552602971.643 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-14T22:36:11.643Z,1552602971.643 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:36:12.004Z,1552602972.004 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:36:12.005Z,1552602972.005 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:36:12.081Z,1552602972.081 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:36:12.081Z,1552602972.081 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-03-14T22:36:12.081Z,1552602972.081 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:36:12.087Z,1552602972.087 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:36:12.087Z,1552602972.087 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 5
2019-03-14T22:36:12.087Z,1552602972.087 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:36:12.111Z,1552602972.111 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:36:12.112Z,1552602972.112 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:36:12.451Z,1552602972.451 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:36:12.451Z,1552602972.451 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-03-14T22:36:12.451Z,1552602972.451 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:36:12.452Z,1552602972.452 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 5
2019-03-14T22:36:12.453Z,1552602972.453 [Reporter](INFO): DUSBL_Hydroid.range 90.240005 m
2019-03-14T22:36:12.453Z,1552602972.453 [Reporter](INFO): DUSBL_Hydroid.xAngle 56.249999 arcdeg
2019-03-14T22:36:12.849Z,1552602972.849 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:36:16.044Z,1552602976.044 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:36:16.048Z,1552602976.048 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:36:20.084Z,1552602980.084 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-14T22:36:20.090Z,1552602980.090 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-14T22:36:20.494Z,1552602980.494 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190314223619.201969,06,489,14,0093,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,186,0.00,-999,9760,4000*51

2019-03-14T22:36:22.159Z,1552602982.159 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-14T22:36:22.159Z,1552602982.159 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-14T22:36:22.159Z,1552602982.159 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:36:22.159Z,1552602982.159 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-14T22:36:22.159Z,1552602982.159 [DUSBL:RequestRepeater] Stopped
2019-03-14T22:36:22.160Z,1552602982.160 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-14T22:36:22.160Z,1552602982.160 [DUSBL:RequestRepeater:A] Stopped
2019-03-14T22:36:22.160Z,1552602982.160 [DUSBL:RequestRepeater:B] Stopped
2019-03-14T22:36:22.160Z,1552602982.160 [DUSBL](INFO): Completed DUSBL
2019-03-14T22:36:22.160Z,1552602982.160 [MissionManager](INFO): DUSBL is completed.
2019-03-14T22:36:22.161Z,1552602982.161 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-03-14T22:36:22.161Z,1552602982.161 [DUSBL] Stopped
2019-03-14T22:36:22.161Z,1552602982.161 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-03-14T22:36:22.161Z,1552602982.161 [DUSBL:A.Pitch] Stopped
2019-03-14T22:36:22.161Z,1552602982.161 [DUSBL:B.SetSpeed] Stopped
2019-03-14T22:36:22.161Z,1552602982.161 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-03-14T22:36:22.161Z,1552602982.161 [DUSBL:C] Stopped
2019-03-14T22:36:22.542Z,1552602982.542 [MissionManager](IMPORTANT): Started mission Default
2019-03-14T22:36:22.542Z,1552602982.542 [Default] Running Loop=1
2019-03-14T22:36:22.543Z,1552602982.543 [Default](DEBUG): Aggregate::initialize Default
2019-03-14T22:36:22.543Z,1552602982.543 [Default:B.GoToSurface] Running Loop=1
2019-03-14T22:36:22.543Z,1552602982.543 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-14T22:36:22.543Z,1552602982.543 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-14T22:36:22.544Z,1552602982.544 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-14T22:36:22.544Z,1552602982.544 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-14T22:36:22.544Z,1552602982.544 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-14T22:36:22.545Z,1552602982.545 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-14T22:36:22.545Z,1552602982.545 [Default:A.Wait] Running Loop=1
2019-03-14T22:36:22.545Z,1552602982.545 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:36:26.544Z,1552602986.544 [NAL9602](INFO): Powering down
2019-03-14T22:36:35.885Z,1552602995.885 [Default:A.Wait](INFO): Done Waiting.
2019-03-14T22:36:35.885Z,1552602995.885 [Default:A.Wait] Stopped
2019-03-14T22:36:35.885Z,1552602995.885 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:36:36.273Z,1552602996.273 [Default:CheckIn] Running Loop=1
2019-03-14T22:36:36.273Z,1552602996.273 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-14T22:36:36.274Z,1552602996.274 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-14T22:36:37.056Z,1552602997.056 [NAL9602](INFO): Powering up
2019-03-14T22:36:47.973Z,1552603007.973 [NAL9602](INFO): NAL9602 initialized
2019-03-14T22:36:48.782Z,1552603008.782 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:02.102Z,1552603022.102 [NAL9602](INFO): SBD MO Status=0, MOMSN=2283, MT Status=0, MTMSN=0
2019-03-14T22:37:02.102Z,1552603022.102 [NAL9602](INFO): No messages in MT queue
2019-03-14T22:37:02.922Z,1552603022.922 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:06.158Z,1552603026.158 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:08.982Z,1552603028.982 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:12.218Z,1552603032.218 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:13.447Z,1552603033.447 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:37:13.447Z,1552603033.447 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 6
2019-03-14T22:37:13.447Z,1552603033.447 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:37:13.459Z,1552603033.459 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:37:13.865Z,1552603033.865 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:37:13.866Z,1552603033.866 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 6
2019-03-14T22:37:15.046Z,1552603035.046 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:17.870Z,1552603037.870 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:20.702Z,1552603040.702 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:23.930Z,1552603043.930 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:26.758Z,1552603046.758 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:29.990Z,1552603049.990 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:32.830Z,1552603052.830 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:36.054Z,1552603056.054 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:38.882Z,1552603058.882 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:42.118Z,1552603062.118 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:44.938Z,1552603064.938 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:48.170Z,1552603068.170 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:50.998Z,1552603070.998 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:53.834Z,1552603073.834 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:37:57.058Z,1552603077.058 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:00.290Z,1552603080.290 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:03.122Z,1552603083.122 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:05.946Z,1552603085.946 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:08.782Z,1552603088.782 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:12.006Z,1552603092.006 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:12.861Z,1552603092.861 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:38:12.861Z,1552603092.861 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-03-14T22:38:12.861Z,1552603092.861 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:38:12.863Z,1552603092.863 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:38:12.864Z,1552603092.864 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 6
2019-03-14T22:38:12.864Z,1552603092.864 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:38:12.875Z,1552603092.875 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:38:12.876Z,1552603092.876 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:38:13.257Z,1552603093.257 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:38:13.258Z,1552603093.258 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-03-14T22:38:13.258Z,1552603093.258 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:38:13.259Z,1552603093.259 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 6
2019-03-14T22:38:13.634Z,1552603093.634 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:38:14.842Z,1552603094.842 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:18.070Z,1552603098.070 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:20.894Z,1552603100.894 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:24.126Z,1552603104.126 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:26.954Z,1552603106.954 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:30.186Z,1552603110.186 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:33.014Z,1552603113.014 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:35.850Z,1552603115.850 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:39.078Z,1552603119.078 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:41.902Z,1552603121.902 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:45.158Z,1552603125.158 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:47.962Z,1552603127.962 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:51.194Z,1552603131.194 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:54.022Z,1552603134.022 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:38:56.854Z,1552603136.854 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:39:00.082Z,1552603140.082 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:39:02.910Z,1552603142.910 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:39:03.310Z,1552603143.310 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223333.00,A,3648.15728,N,12147.28626,W,0.233,223.89,140319,,,A*7B
2019-03-14T22:39:03.312Z,1552603143.312 [NAL9602](INFO): GPS fix at 20190314T223333: (36.802621, -121.788104)
2019-03-14T22:39:03.344Z,1552603143.344 [Default:CheckIn:Read_GPS] Stopped
2019-03-14T22:39:03.344Z,1552603143.344 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-03-14T22:39:08.742Z,1552603148.742 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20190314T222355/Courier0007.lzma
2019-03-14T22:39:09.548Z,1552603149.548 [DataOverHttps](INFO): Moved sent file to Logs/20190314T222355/Courier0007.lzma.bak
2019-03-14T22:39:09.548Z,1552603149.548 [DataOverHttps](INFO): SBD MOMSN=10140702
2019-03-14T22:39:14.289Z,1552603154.289 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:39:14.289Z,1552603154.289 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-14T22:39:14.289Z,1552603154.289 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:39:14.301Z,1552603154.301 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:39:14.692Z,1552603154.692 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:39:14.692Z,1552603154.692 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-14T22:39:20.335Z,1552603160.335 [DataOverHttps](INFO): Sending 671 bytes from file Logs/20190314T222355/Express0008.lzma
2019-03-14T22:39:21.140Z,1552603161.140 [DataOverHttps](INFO): Moved sent file to Logs/20190314T222355/Express0008.lzma.bak
2019-03-14T22:39:21.140Z,1552603161.140 [DataOverHttps](INFO): SBD MOMSN=10140705
2019-03-14T22:39:22.337Z,1552603162.337 [Default:CheckIn:Read_Iridium] Stopped
2019-03-14T22:39:22.337Z,1552603162.337 [Default:CheckIn:C.Wait] Running Loop=1
2019-03-14T22:39:22.337Z,1552603162.337 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-03-14T22:39:36.052Z,1552603176.052 [NAL9602](INFO): Powering down
2019-03-14T22:40:13.653Z,1552603213.653 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:40:13.653Z,1552603213.653 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-03-14T22:40:13.653Z,1552603213.653 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:40:13.655Z,1552603213.655 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:40:13.656Z,1552603213.656 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-03-14T22:40:13.656Z,1552603213.656 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:40:13.668Z,1552603213.668 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:40:13.668Z,1552603213.668 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:40:14.075Z,1552603214.075 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:40:14.075Z,1552603214.075 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-03-14T22:40:14.076Z,1552603214.076 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:40:14.076Z,1552603214.076 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-03-14T22:40:14.455Z,1552603214.455 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:41:15.071Z,1552603275.071 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:41:15.071Z,1552603275.071 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 2
2019-03-14T22:41:15.071Z,1552603275.071 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:41:15.091Z,1552603275.091 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:41:15.479Z,1552603275.479 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:41:15.479Z,1552603275.479 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 2
2019-03-14T22:42:14.858Z,1552603334.858 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:42:14.858Z,1552603334.858 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-03-14T22:42:14.858Z,1552603334.858 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:42:14.861Z,1552603334.861 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:42:14.861Z,1552603334.861 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2019-03-14T22:42:14.861Z,1552603334.861 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:42:14.898Z,1552603334.898 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:42:14.902Z,1552603334.902 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:42:15.263Z,1552603335.263 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:42:15.263Z,1552603335.263 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-03-14T22:42:15.264Z,1552603335.264 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:42:15.264Z,1552603335.264 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2019-03-14T22:42:15.647Z,1552603335.647 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:43:16.245Z,1552603396.245 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:43:16.245Z,1552603396.245 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 3
2019-03-14T22:43:16.245Z,1552603396.245 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:43:16.265Z,1552603396.265 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:43:16.691Z,1552603396.691 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:43:16.691Z,1552603396.691 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 3
2019-03-14T22:44:16.049Z,1552603456.049 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:44:16.049Z,1552603456.049 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-03-14T22:44:16.050Z,1552603456.050 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:44:16.052Z,1552603456.052 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:44:16.052Z,1552603456.052 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2019-03-14T22:44:16.052Z,1552603456.052 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:44:16.064Z,1552603456.064 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:44:16.064Z,1552603456.064 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:44:16.467Z,1552603456.467 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:44:16.467Z,1552603456.467 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-03-14T22:44:16.468Z,1552603456.468 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:44:16.468Z,1552603456.468 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2019-03-14T22:44:16.873Z,1552603456.873 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:44:22.918Z,1552603462.918 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-03-14T22:44:22.918Z,1552603462.918 [Default:CheckIn:C.Wait] Stopped
2019-03-14T22:44:22.918Z,1552603462.918 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-14T22:44:22.919Z,1552603462.919 [Default:CheckIn:D] Running Loop=1
2019-03-14T22:44:23.325Z,1552603463.325 [Default:CheckIn:D] Stopped
2019-03-14T22:44:23.325Z,1552603463.325 [Default:CheckIn:E] Running Loop=1
2019-03-14T22:44:23.731Z,1552603463.731 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.013042 min 
2019-03-14T22:44:23.731Z,1552603463.731 [Default:CheckIn:E] Stopped
2019-03-14T22:44:23.731Z,1552603463.731 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-03-14T22:44:23.731Z,1552603463.731 [Default:CheckIn] Stopped
2019-03-14T22:44:23.731Z,1552603463.731 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-14T22:44:23.731Z,1552603463.731 [Default:CheckIn](INFO): Running loop #2
2019-03-14T22:44:23.731Z,1552603463.731 [Default:CheckIn] Running Loop=2
2019-03-14T22:44:23.732Z,1552603463.732 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-14T22:44:23.732Z,1552603463.732 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-14T22:44:24.504Z,1552603464.504 [NAL9602](INFO): Powering up
2019-03-14T22:44:35.412Z,1552603475.412 [NAL9602](INFO): NAL9602 initialized
2019-03-14T22:44:36.238Z,1552603476.238 [NAL9602](DEBUG): Fix Requested
2019-03-14T22:45:17.449Z,1552603517.449 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:45:17.449Z,1552603517.449 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 4
2019-03-14T22:45:17.450Z,1552603517.450 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:45:17.462Z,1552603517.462 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:45:17.877Z,1552603517.877 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:45:17.877Z,1552603517.877 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 4
2019-03-14T22:45:39.245Z,1552603539.245 [NAL9602](INFO): SBD MO Status=2, MOMSN=2284, MT Status=2, MTMSN=0
2019-03-14T22:45:39.246Z,1552603539.246 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-14T22:45:57.046Z,1552603557.046 [NAL9602](INFO): SBD MO Status=2, MOMSN=2284, MT Status=2, MTMSN=0
2019-03-14T22:45:57.046Z,1552603557.046 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-14T22:46:14.402Z,1552603574.402 [NAL9602](INFO): SBD MO Status=2, MOMSN=2284, MT Status=2, MTMSN=0
2019-03-14T22:46:14.402Z,1552603574.402 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-14T22:46:17.250Z,1552603577.250 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:46:17.250Z,1552603577.250 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-03-14T22:46:17.250Z,1552603577.250 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-14T22:46:17.252Z,1552603577.252 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:46:17.252Z,1552603577.252 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2019-03-14T22:46:17.252Z,1552603577.252 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-14T22:46:17.284Z,1552603577.284 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-14T22:46:17.285Z,1552603577.285 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-14T22:46:17.672Z,1552603577.672 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-14T22:46:17.672Z,1552603577.672 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-03-14T22:46:17.673Z,1552603577.673 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-14T22:46:17.673Z,1552603577.673 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2019-03-14T22:46:18.067Z,1552603578.067 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-14T22:47:00.460Z,1552603620.460 [NAL9602](INFO): SBD MO Status=2, MOMSN=2284, MT Status=2, MTMSN=0
2019-03-14T22:47:00.460Z,1552603620.460 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-14T22:47:16.629Z,1552603636.629 [NAL9602](INFO): SBD MO Status=2, MOMSN=2284, MT Status=2, MTMSN=0
2019-03-14T22:47:16.629Z,1552603636.629 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-14T22:47:18.664Z,1552603638.664 [DeadReckonWithRespectToSeafloor](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-03-14T22:47:18.664Z,1552603638.664 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 5
2019-03-14T22:47:18.664Z,1552603638.664 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-14T22:47:18.675Z,1552603638.675 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-14T22:47:19.086Z,1552603639.086 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-14T22:47:19.087Z,1552603639.087 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 5
2019-03-14T22:47:36.624Z,1552603656.624 [CommandLine](IMPORTANT): got command quit
2019-03-14T22:47:37.631Z,1552603657.631 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-03-14T22:47:37.632Z,1552603657.632 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:37.632Z,1552603657.632 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:37.698Z,1552603657.698 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-03-14T22:47:37.698Z,1552603657.698 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:37.699Z,1552603657.699 [CommandLine](INFO): Join timeout helper Thread ID is 1800
2019-03-14T22:47:37.700Z,1552603657.700 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-03-14T22:47:37.700Z,1552603657.700 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:37.700Z,1552603657.700 [NavChartDb](INFO): Join timeout helper Thread ID is 1801
2019-03-14T22:47:37.898Z,1552603657.898 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:37.899Z,1552603657.899 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:37.910Z,1552603657.910 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-03-14T22:47:37.910Z,1552603657.910 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:37.911Z,1552603657.911 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1802
2019-03-14T22:47:37.994Z,1552603657.994 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:37.994Z,1552603657.994 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-03-14T22:47:37.995Z,1552603657.995 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.010Z,1552603658.010 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-03-14T22:47:38.010Z,1552603658.010 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.011Z,1552603658.011 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1803
2019-03-14T22:47:38.098Z,1552603658.098 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:38.099Z,1552603658.099 [CTD_NeilBrown](INFO): Powering down
2019-03-14T22:47:38.110Z,1552603658.110 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.114Z,1552603658.114 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-03-14T22:47:38.114Z,1552603658.114 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.115Z,1552603658.115 [Radio_Surface](INFO): Join timeout helper Thread ID is 1804
2019-03-14T22:47:38.326Z,1552603658.326 [Radio_Surface](INFO): Powering down
2019-03-14T22:47:38.327Z,1552603658.327 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:38.327Z,1552603658.327 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.343Z,1552603658.343 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-03-14T22:47:38.343Z,1552603658.343 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.344Z,1552603658.344 [DataOverHttps](INFO): Join timeout helper Thread ID is 1805
2019-03-14T22:47:38.370Z,1552603658.370 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:38.371Z,1552603658.371 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.387Z,1552603658.387 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-03-14T22:47:38.387Z,1552603658.387 [logger ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.387Z,1552603658.387 [logger](INFO): Join timeout helper Thread ID is 1806
2019-03-14T22:47:38.399Z,1552603658.399 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:38.399Z,1552603658.399 [logger ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.415Z,1552603658.415 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-03-14T22:47:38.415Z,1552603658.415 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.415Z,1552603658.415 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-03-14T22:47:38.415Z,1552603658.415 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.416Z,1552603658.416 [controlThread](INFO): Join timeout helper Thread ID is 1807
2019-03-14T22:47:38.422Z,1552603658.422 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-14T22:47:38.423Z,1552603658.423 [controlThread](DEBUG): Uninitializing ControlThread
2019-03-14T22:47:38.423Z,1552603658.423 [DUSBL_Hydroid](INFO): Powering down
2019-03-14T22:47:38.494Z,1552603658.494 [Micromodem](INFO): Powering down
2019-03-14T22:47:38.590Z,1552603658.590 [NAL9602](INFO): Powering down
2019-03-14T22:47:38.662Z,1552603658.662 [RDI_Pathfinder](INFO): Powering down
2019-03-14T22:47:38.663Z,1552603658.663 [RDI_PathfinderUp](INFO): Powering down
2019-03-14T22:47:38.664Z,1552603658.664 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-03-14T22:47:38.665Z,1552603658.665 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-03-14T22:47:38.666Z,1552603658.666 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-03-14T22:47:38.667Z,1552603658.667 [MissionManager](INFO): Uninitializing Mission Default
2019-03-14T22:47:38.667Z,1552603658.667 [Default] Stopped
2019-03-14T22:47:38.667Z,1552603658.667 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-14T22:47:38.667Z,1552603658.667 [Default:B.GoToSurface] Stopped
2019-03-14T22:47:38.667Z,1552603658.667 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-14T22:47:38.667Z,1552603658.667 [Default:CheckIn] Stopped
2019-03-14T22:47:38.667Z,1552603658.667 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-14T22:47:38.667Z,1552603658.667 [Default:CheckIn:Read_GPS] Stopped
2019-03-14T22:47:38.669Z,1552603658.669 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-03-14T22:47:38.670Z,1552603658.670 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-03-14T22:47:38.670Z,1552603658.670 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-03-14T22:47:38.670Z,1552603658.670 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-03-14T22:47:38.671Z,1552603658.671 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-03-14T22:47:38.671Z,1552603658.671 [BuoyancyServo](INFO): Powering down
2019-03-14T22:47:38.682Z,1552603658.682 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-03-14T22:47:38.682Z,1552603658.682 [ElevatorServo](INFO): Powering down
2019-03-14T22:47:38.683Z,1552603658.683 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-03-14T22:47:38.683Z,1552603658.683 [MassServo](INFO): Powering down
2019-03-14T22:47:38.684Z,1552603658.684 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-03-14T22:47:38.684Z,1552603658.684 [RudderServo](INFO): Powering down
2019-03-14T22:47:38.685Z,1552603658.685 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-03-14T22:47:38.685Z,1552603658.685 [ThrusterServo](INFO): Powering down
2019-03-14T22:47:38.686Z,1552603658.686 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-03-14T22:47:38.686Z,1552603658.686 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-03-14T22:47:38.686Z,1552603658.686 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-03-14T22:47:38.686Z,1552603658.686 [CBIT](DEBUG): Powering off loads.
2019-03-14T22:47:38.698Z,1552603658.698 [CBIT](DEBUG): Disabling WDT.
2019-03-14T22:47:38.710Z,1552603658.710 [CBIT](DEBUG): Opening all GF detection circuits.
2019-03-14T22:47:38.711Z,1552603658.711 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.763Z,1552603658.763 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.772Z,1552603658.772 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.811Z,1552603658.811 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.813Z,1552603658.813 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.866Z,1552603658.866 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-14T22:47:38.934Z,1552603658.934 [logger ThreadHandler](INFO): Thread cancelled.