2019-03-27T18:53:34.219Z,1553712814.219 [Supervisor](DEBUG): Initializing supervisor.
2019-03-27T18:53:34.222Z,1553712814.222 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-03-27T18:53:34.222Z,1553712814.222 [SyncHandler](INFO): Protected caller Thread ID is 8357
2019-03-27T18:53:34.223Z,1553712814.223 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-03-27T18:53:34.224Z,1553712814.224 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-03-27T18:53:34.224Z,1553712814.224 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 8358
2019-03-27T18:53:34.227Z,1553712814.227 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-03-27T18:53:34.239Z,1553712814.239 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-03-27T18:53:34.240Z,1553712814.240 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-03-27T18:53:34.241Z,1553712814.241 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 8359
2019-03-27T18:53:34.241Z,1553712814.241 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-03-27T18:53:34.242Z,1553712814.242 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-03-27T18:53:34.243Z,1553712814.243 [logger ThreadHandler](INFO): Protected caller Thread ID is 8360
2019-03-27T18:53:34.245Z,1553712814.245 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-03-27T18:53:34.245Z,1553712814.245 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-03-27T18:53:34.247Z,1553712814.247 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-03-27T18:53:34.663Z,1553712814.663 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-03-27T18:53:34.664Z,1553712814.664 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-03-27T18:53:34.761Z,1553712814.761 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-03-27T18:53:34.762Z,1553712814.762 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-03-27T18:53:35.084Z,1553712815.084 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-03-27T18:53:35.084Z,1553712815.084 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-03-27T18:53:35.232Z,1553712815.232 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-03-27T18:53:35.232Z,1553712815.232 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-03-27T18:53:35.561Z,1553712815.561 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-03-27T18:53:35.562Z,1553712815.562 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-03-27T18:53:36.015Z,1553712816.015 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-03-27T18:53:36.015Z,1553712816.015 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-03-27T18:53:36.224Z,1553712816.224 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-03-27T18:53:36.224Z,1553712816.224 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-03-27T18:53:36.368Z,1553712816.368 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-03-27T18:53:36.369Z,1553712816.369 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-03-27T18:53:36.561Z,1553712816.561 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-03-27T18:53:36.562Z,1553712816.562 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-03-27T18:53:36.657Z,1553712816.657 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-03-27T18:53:36.657Z,1553712816.657 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-03-27T18:53:36.978Z,1553712816.978 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-03-27T18:53:36.978Z,1553712816.978 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-03-27T18:53:37.058Z,1553712817.058 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-03-27T18:53:37.160Z,1553712817.160 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-03-27T18:53:37.161Z,1553712817.161 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-03-27T18:53:37.658Z,1553712817.658 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-03-27T18:53:37.658Z,1553712817.658 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-03-27T18:53:38.051Z,1553712818.051 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-03-27T18:53:38.053Z,1553712818.053 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-03-27T18:53:38.053Z,1553712818.053 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-03-27T18:53:38.260Z,1553712818.260 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-03-27T18:53:38.359Z,1553712818.359 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-03-27T18:53:38.456Z,1553712818.456 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-03-27T18:53:38.681Z,1553712818.681 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-03-27T18:53:38.682Z,1553712818.682 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-03-27T18:53:38.766Z,1553712818.766 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-03-27T18:53:38.858Z,1553712818.858 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-03-27T18:53:38.954Z,1553712818.954 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-03-27T18:53:39.035Z,1553712819.035 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-03-27T18:53:39.146Z,1553712819.146 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-03-27T18:53:39.326Z,1553712819.326 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-03-27T18:53:39.457Z,1553712819.457 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-03-27T18:53:39.458Z,1553712819.458 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-03-27T18:53:39.464Z,1553712819.464 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-03-27T18:53:39.848Z,1553712819.848 [AHRS_M2] Loaded
2019-03-27T18:53:39.848Z,1553712819.848 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-03-27T18:53:39.921Z,1553712819.921 [DataOverHttps] Loaded
2019-03-27T18:53:39.921Z,1553712819.921 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-03-27T18:53:39.922Z,1553712819.922 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2019-03-27T18:53:39.923Z,1553712819.923 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 8439
2019-03-27T18:53:39.936Z,1553712819.936 [Depth_Keller] Loaded
2019-03-27T18:53:39.936Z,1553712819.936 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-03-27T18:53:39.941Z,1553712819.941 [DropWeight] Loaded
2019-03-27T18:53:39.942Z,1553712819.942 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-03-27T18:53:39.993Z,1553712819.993 [DUSBL_Hydroid] Loaded
2019-03-27T18:53:39.993Z,1553712819.993 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-03-27T18:53:40.032Z,1553712820.032 [Micromodem] Loaded
2019-03-27T18:53:40.032Z,1553712820.032 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-03-27T18:53:40.129Z,1553712820.129 [NAL9602] Loaded
2019-03-27T18:53:40.129Z,1553712820.129 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-03-27T18:53:40.144Z,1553712820.144 [Onboard] Loaded
2019-03-27T18:53:40.145Z,1553712820.145 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-03-27T18:53:40.150Z,1553712820.150 [PowerOnly] Loaded
2019-03-27T18:53:40.151Z,1553712820.151 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-03-27T18:53:40.157Z,1553712820.157 [Radio_Surface] Loaded
2019-03-27T18:53:40.157Z,1553712820.157 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-03-27T18:53:40.158Z,1553712820.158 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2019-03-27T18:53:40.159Z,1553712820.159 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 8440
2019-03-27T18:53:40.217Z,1553712820.217 [RDI_Pathfinder] Loaded
2019-03-27T18:53:40.217Z,1553712820.217 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-03-27T18:53:40.238Z,1553712820.238 [RDI_PathfinderUp] Loaded
2019-03-27T18:53:40.239Z,1553712820.239 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2019-03-27T18:53:42.052Z,1553712822.052 [BPC1] Loaded
2019-03-27T18:53:42.052Z,1553712822.052 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-03-27T18:53:42.052Z,1553712822.052 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-03-27T18:53:42.053Z,1553712822.053 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-03-27T18:53:42.066Z,1553712822.066 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-03-27T18:53:42.067Z,1553712822.067 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-03-27T18:53:42.172Z,1553712822.172 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-03-27T18:53:42.172Z,1553712822.172 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-03-27T18:53:42.231Z,1553712822.231 [DeadReckonUsingSpeedCalculator] Loaded
2019-03-27T18:53:42.231Z,1553712822.231 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2019-03-27T18:53:42.289Z,1553712822.289 [DeadReckonWithRespectToSeafloor] Loaded
2019-03-27T18:53:42.289Z,1553712822.289 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2019-03-27T18:53:42.309Z,1553712822.309 [NavChart] Loaded
2019-03-27T18:53:42.309Z,1553712822.309 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-03-27T18:53:42.313Z,1553712822.313 [UniversalFixResidualReporter] Loaded
2019-03-27T18:53:42.313Z,1553712822.313 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-03-27T18:53:42.314Z,1553712822.314 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-03-27T18:53:42.314Z,1553712822.314 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-03-27T18:53:42.415Z,1553712822.415 [BuoyancyServo] Loaded
2019-03-27T18:53:42.415Z,1553712822.415 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-03-27T18:53:42.430Z,1553712822.430 [ElevatorServo] Loaded
2019-03-27T18:53:42.430Z,1553712822.430 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-03-27T18:53:42.445Z,1553712822.445 [MassServo] Loaded
2019-03-27T18:53:42.445Z,1553712822.445 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-03-27T18:53:42.460Z,1553712822.460 [RudderServo] Loaded
2019-03-27T18:53:42.460Z,1553712822.460 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-03-27T18:53:42.475Z,1553712822.475 [ThrusterServo] Loaded
2019-03-27T18:53:42.475Z,1553712822.475 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-03-27T18:53:42.476Z,1553712822.476 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-03-27T18:53:42.476Z,1553712822.476 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-03-27T18:53:42.723Z,1553712822.723 [CTD_NeilBrown] Loaded
2019-03-27T18:53:42.723Z,1553712822.723 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-03-27T18:53:42.724Z,1553712822.724 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D04E0
2019-03-27T18:53:42.725Z,1553712822.725 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 8441
2019-03-27T18:53:42.769Z,1553712822.769 [WetLabsSeaOWL_UV_A] Loaded
2019-03-27T18:53:42.770Z,1553712822.770 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-03-27T18:53:42.771Z,1553712822.771 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409004E0
2019-03-27T18:53:42.771Z,1553712822.771 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 8442
2019-03-27T18:53:42.772Z,1553712822.772 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-03-27T18:53:42.772Z,1553712822.772 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-03-27T18:53:43.039Z,1553712823.039 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-03-27T18:53:43.040Z,1553712823.040 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-03-27T18:53:43.079Z,1553712823.079 [DepthRateCalculator] Loaded
2019-03-27T18:53:43.080Z,1553712823.080 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-03-27T18:53:43.085Z,1553712823.085 [PitchRateCalculator] Loaded
2019-03-27T18:53:43.086Z,1553712823.086 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-03-27T18:53:43.098Z,1553712823.098 [SpeedCalculator] Loaded
2019-03-27T18:53:43.099Z,1553712823.099 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-03-27T18:53:43.119Z,1553712823.119 [TempGradientCalculator] Loaded
2019-03-27T18:53:43.119Z,1553712823.119 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-03-27T18:53:43.125Z,1553712823.125 [YawRateCalculator] Loaded
2019-03-27T18:53:43.125Z,1553712823.125 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-03-27T18:53:43.164Z,1553712823.164 [ElevatorOffsetCalculator] Loaded
2019-03-27T18:53:43.164Z,1553712823.164 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-03-27T18:53:43.165Z,1553712823.165 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-03-27T18:53:43.165Z,1553712823.165 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-03-27T18:53:43.298Z,1553712823.298 [SBIT](DEBUG): Construct Startup Built In Test.
2019-03-27T18:53:43.319Z,1553712823.319 [SBIT] Loaded
2019-03-27T18:53:43.320Z,1553712823.320 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-03-27T18:53:43.320Z,1553712823.320 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-03-27T18:53:43.332Z,1553712823.332 [IBIT] Loaded
2019-03-27T18:53:43.332Z,1553712823.332 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-03-27T18:53:43.335Z,1553712823.335 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-03-27T18:53:43.473Z,1553712823.473 [CBIT] Loaded
2019-03-27T18:53:43.473Z,1553712823.473 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-03-27T18:53:43.473Z,1553712823.473 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-03-27T18:53:43.474Z,1553712823.474 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-03-27T18:53:43.543Z,1553712823.543 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-03-27T18:53:43.544Z,1553712823.544 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-03-27T18:53:43.640Z,1553712823.640 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-03-27T18:53:43.641Z,1553712823.641 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-03-27T18:53:43.707Z,1553712823.707 [VerticalControl](DEBUG): Construct VerticalControl.
2019-03-27T18:53:43.790Z,1553712823.790 [VerticalControl] Loaded
2019-03-27T18:53:43.790Z,1553712823.790 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-03-27T18:53:43.791Z,1553712823.791 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-03-27T18:53:43.848Z,1553712823.848 [HorizontalControl] Loaded
2019-03-27T18:53:43.848Z,1553712823.848 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-03-27T18:53:43.849Z,1553712823.849 [SpeedControl](DEBUG): Construct SpeedControl.
2019-03-27T18:53:43.851Z,1553712823.851 [SpeedControl] Loaded
2019-03-27T18:53:43.851Z,1553712823.851 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-03-27T18:53:43.852Z,1553712823.852 [LoopControl](DEBUG): Construct LoopControl.
2019-03-27T18:53:43.852Z,1553712823.852 [LoopControl] Loaded
2019-03-27T18:53:43.852Z,1553712823.852 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-03-27T18:53:43.853Z,1553712823.853 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-03-27T18:53:43.853Z,1553712823.853 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-03-27T18:53:43.880Z,1553712823.880 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-03-27T18:53:43.884Z,1553712823.884 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-03-27T18:53:43.885Z,1553712823.885 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-03-27T18:53:43.891Z,1553712823.891 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-03-27T18:53:43.892Z,1553712823.892 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2019-03-27T18:53:43.893Z,1553712823.893 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 8443
2019-03-27T18:53:43.897Z,1553712823.897 [Supervisor](INFO): Main Thread ID is 7788
2019-03-27T18:53:43.898Z,1553712823.898 [Supervisor](DEBUG): Running supervisor.
2019-03-27T18:53:43.898Z,1553712823.898 [CommandLine ThreadHandler](INFO): Handler Thread ID is 8444
2019-03-27T18:53:43.901Z,1553712823.901 [controlThread ThreadHandler](INFO): Handler Thread ID is 8445
2019-03-27T18:53:43.901Z,1553712823.901 [controlThread](DEBUG): Initializing ControlThread
2019-03-27T18:53:43.908Z,1553712823.908 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-27T18:53:43.909Z,1553712823.909 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-03-27T18:53:43.909Z,1553712823.909 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-03-27T18:53:43.910Z,1553712823.910 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-03-27T18:53:43.911Z,1553712823.911 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-03-27T18:53:43.911Z,1553712823.911 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-03-27T18:53:43.911Z,1553712823.911 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-03-27T18:53:43.912Z,1553712823.912 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-03-27T18:53:43.912Z,1553712823.912 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-03-27T18:53:43.912Z,1553712823.912 [SBIT](INFO): Initialize SBIT Component.
2019-03-27T18:53:43.913Z,1553712823.913 [SBIT](IMPORTANT): git: 2019-03-18-26-gc8399b8
2019-03-27T18:53:43.913Z,1553712823.913 [SBIT](INFO): git hash: c8399b8e53db2b8366337064c7df5542bc2caf88
2019-03-27T18:53:43.914Z,1553712823.914 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-03-27T18:53:43.914Z,1553712823.914 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-03-27T18:53:43.915Z,1553712823.915 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-03-27T18:53:43.916Z,1553712823.916 [IBIT](INFO): Initialize IBIT Component.
2019-03-27T18:53:43.916Z,1553712823.916 [CBIT](DEBUG): Initialize CBIT Component.
2019-03-27T18:53:43.917Z,1553712823.917 [logger ThreadHandler](INFO): Handler Thread ID is 8446
2019-03-27T18:53:43.929Z,1553712823.929 [CBIT](DEBUG): Initialized mux pins.
2019-03-27T18:53:43.929Z,1553712823.929 [CBIT](DEBUG): Initializing the watchdog timer.
2019-03-27T18:53:43.937Z,1553712823.937 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 8447
2019-03-27T18:53:43.938Z,1553712823.938 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-03-27T18:53:43.949Z,1553712823.949 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 8448
2019-03-27T18:53:43.953Z,1553712823.953 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-03-27T18:53:43.953Z,1553712823.953 [CBIT](DEBUG): Initializing heartbeat.
2019-03-27T18:53:43.961Z,1553712823.961 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 8449
2019-03-27T18:53:43.962Z,1553712823.962 [CTD_NeilBrown](INFO): Powering down
2019-03-27T18:53:43.990Z,1553712823.990 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 8450
2019-03-27T18:53:43.990Z,1553712823.990 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-03-27T18:53:44.019Z,1553712824.019 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 8451
2019-03-27T18:53:44.023Z,1553712824.023 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-03-27T18:53:44.023Z,1553712824.023 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-03-27T18:53:44.023Z,1553712824.023 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-03-27T18:53:44.023Z,1553712824.023 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-03-27T18:53:44.023Z,1553712824.023 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-03-27T18:53:44.024Z,1553712824.024 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-03-27T18:53:44.024Z,1553712824.024 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-03-27T18:53:44.024Z,1553712824.024 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-03-27T18:53:44.024Z,1553712824.024 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-03-27T18:53:44.024Z,1553712824.024 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-03-27T18:53:44.025Z,1553712824.025 [CBIT](DEBUG): Deactivating GF circuits.
2019-03-27T18:53:44.025Z,1553712824.025 [CBIT](DEBUG): Deactivating emergency mode.
2019-03-27T18:53:44.024Z,1553712824.024 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-03-27T18:53:44.025Z,1553712824.025 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-03-27T18:53:44.025Z,1553712824.025 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-03-27T18:53:44.026Z,1553712824.026 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-03-27T18:53:44.026Z,1553712824.026 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-03-27T18:53:44.026Z,1553712824.026 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-03-27T18:53:44.061Z,1553712824.061 [CBIT](DEBUG): Backplane powered.
2019-03-27T18:53:44.061Z,1553712824.061 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-03-27T18:53:44.063Z,1553712824.063 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-03-27T18:53:44.064Z,1553712824.064 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-03-27T18:53:44.064Z,1553712824.064 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-03-27T18:53:44.065Z,1553712824.065 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-03-27T18:53:44.075Z,1553712824.075 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-03-27T18:53:44.098Z,1553712824.098 [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-27T18:53:44.105Z,1553712824.105 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-03-27T18:53:44.160Z,1553712824.160 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-03-27T18:53:44.181Z,1553712824.181 [Default:A.Wait](DEBUG): Construct Wait.
2019-03-27T18:53:44.183Z,1553712824.183 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-03-27T18:53:44.209Z,1553712824.209 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-03-27T18:53:44.212Z,1553712824.212 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-03-27T18:53:44.234Z,1553712824.234 [Default:E.Execute](DEBUG): Construct Execute.
2019-03-27T18:53:44.253Z,1553712824.253 [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-27T18:53:44.258Z,1553712824.258 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,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-27T18:53:44.263Z,1553712824.263 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-03-27T18:53:44.353Z,1553712824.353 [Radio_Surface](INFO): Powering up
2019-03-27T18:53:44.396Z,1553712824.396 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T18:53:44.396Z,1553712824.396 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T18:53:44.491Z,1553712824.491 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:53:44.497Z,1553712824.497 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-03-27T18:53:44.498Z,1553712824.498 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:53:44.509Z,1553712824.509 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-03-27T18:53:44.510Z,1553712824.510 [MassServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:53:44.517Z,1553712824.517 [MassServo](DEBUG): Initializing MassServo.
2019-03-27T18:53:44.518Z,1553712824.518 [RudderServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:53:44.525Z,1553712824.525 [RudderServo](DEBUG): Initializing RudderServo.
2019-03-27T18:53:44.526Z,1553712824.526 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:53:44.533Z,1553712824.533 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-03-27T18:53:44.684Z,1553712824.684 [Micromodem](INFO): Powering up
2019-03-27T18:53:44.684Z,1553712824.684 [Micromodem](DEBUG): Initializing Micromodem.
2019-03-27T18:53:44.789Z,1553712824.789 [RDI_PathfinderUp](INFO): Powering down
2019-03-27T18:53:45.421Z,1553712825.421 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-03-27T18:53:45.421Z,1553712825.421 [RudderServo](FAULT): Rudder failed to initialize
2019-03-27T18:53:45.421Z,1553712825.421 [RudderServo] Communications Fault, FailCount= 1
2019-03-27T18:53:45.421Z,1553712825.421 [RudderServo](ERROR): Communications Fault
2019-03-27T18:53:45.532Z,1553712825.532 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-03-27T18:53:45.706Z,1553712825.706 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-03-27T18:53:45.706Z,1553712825.706 [RudderServo](INFO): Powering down
2019-03-27T18:53:46.378Z,1553712826.378 [RudderServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:53:46.498Z,1553712826.498 [RudderServo](DEBUG): Initializing RudderServo.
2019-03-27T18:53:46.502Z,1553712826.502 [CBIT](INFO): Clearing failed state for component RudderServo
2019-03-27T18:53:46.502Z,1553712826.502 [RudderServo] No Fault, FailCount= 1
2019-03-27T18:53:49.620Z,1553712829.620 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-03-27T18:53:57.769Z,1553712837.769 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-03-27T18:53:58.565Z,1553712838.565 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-03-27T18:53:58.596Z,1553712838.596 [RDI_Pathfinder](ERROR): only read 3 of 5 data items
2019-03-27T18:53:58.596Z,1553712838.596 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,    -5,   +53,   +12, 

2019-03-27T18:53:59.359Z,1553712839.359 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV8535,COPRC,0.0.0.46*42

2019-03-27T18:54:02.595Z,1553712842.595 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T18:54:08.651Z,1553712848.651 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-03-27T18:54:10.271Z,1553712850.271 [NAL9602](INFO): Powering up NAL9602
2019-03-27T18:54:12.325Z,1553712852.325 [SBIT](IMPORTANT): Beginning Startup BIT
2019-03-27T18:54:12.334Z,1553712852.334 [CBIT](IMPORTANT): Beginning ground fault scan
2019-03-27T18:54:18.603Z,1553712858.603 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-03-27T18:54:21.391Z,1553712861.391 [NAL9602](INFO): NAL9602 initialized
2019-03-27T18:54:22.213Z,1553712862.213 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:54:23.113Z,1553712863.113 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.009645
CHAN A1 (24V): -0.027327
CHAN A2 (12V): -0.006947
CHAN A3 (5V): -0.001837
CHAN B0 (3.3V): -0.000019
CHAN B1 (3.15aV): 0.000637
CHAN B2 (3.15bV): 0.000089
CHAN B3 (GND): 0.002022
OPEN: 0.007425
Full Scale Calc: 4.765 mA, -1.589 mA
2019-03-27T18:54:28.831Z,1553712868.831 [Micromodem](INFO): Nmea out: $CCTMS,2019-03-27T18:54:29Z,0*7B

2019-03-27T18:55:05.768Z,1553712905.768 [SBIT](IMPORTANT): SBIT PASSED
2019-03-27T18:55:05.785Z,1553712905.785 [CommandLine](IMPORTANT): got command configSet list
2019-03-27T18:55:05.785Z,1553712905.785 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-03-27T18:55:05.786Z,1553712905.786 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-03-27T18:55:05.786Z,1553712905.786 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-03-27T18:55:05.786Z,1553712905.786 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-03-27T18:55:05.786Z,1553712905.786 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-03-27T18:55:06.144Z,1553712906.144 [MissionManager](IMPORTANT): Started mission Startup
2019-03-27T18:55:06.145Z,1553712906.145 [Startup] Running Loop=1
2019-03-27T18:55:06.145Z,1553712906.145 [Startup](DEBUG): Aggregate::initialize Startup
2019-03-27T18:55:06.145Z,1553712906.145 [Startup:A.GoToSurface] Running Loop=1
2019-03-27T18:55:06.145Z,1553712906.145 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-27T18:55:06.146Z,1553712906.146 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-27T18:55:06.146Z,1553712906.146 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-27T18:55:06.147Z,1553712906.147 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-27T18:55:06.147Z,1553712906.147 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-27T18:55:06.147Z,1553712906.147 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-27T18:55:06.149Z,1553712906.149 [Startup:StartupSatComms] Running Loop=1
2019-03-27T18:55:06.149Z,1553712906.149 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-03-27T18:55:06.149Z,1553712906.149 [Startup:StartupSatComms:A] Running Loop=1
2019-03-27T18:55:06.568Z,1553712906.568 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-03-27T18:55:29.588Z,1553712929.588 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-03-27T18:55:29.589Z,1553712929.589 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +     +2.79,        +0.79,   8.54,  0.00
2019-03-27T18:56:06.320Z,1553712966.320 [Startup:StartupSatComms:A](INFO): Timed out from 2019-03-27T18:55:06.1Z
2019-03-27T18:56:06.320Z,1553712966.320 [Startup:StartupSatComms:A] Stopped
2019-03-27T18:56:06.320Z,1553712966.320 [Startup:StartupSatComms:B] Running Loop=1
2019-03-27T18:56:06.736Z,1553712966.736 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-03-27T18:56:12.191Z,1553712972.191 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005318
2019-03-27T18:56:14.854Z,1553712974.854 [CommandLine](IMPORTANT): got command show stack
2019-03-27T18:56:14.854Z,1553712974.854 [CommandLine](IMPORTANT): Behavior Stack:

2019-03-27T18:56:14.854Z,1553712974.854 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-03-27T18:56:14.854Z,1553712974.854 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B
2019-03-27T18:56:17.464Z,1553712977.464 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190327T183721/Courier0013.lzma
2019-03-27T18:56:18.271Z,1553712978.271 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Courier0013.lzma.bak
2019-03-27T18:56:18.271Z,1553712978.271 [DataOverHttps](INFO): SBD MOMSN=10257478
2019-03-27T18:56:21.918Z,1553712981.918 [CommandLine](IMPORTANT): got command show variable range
2019-03-27T18:56:21.920Z,1553712981.920 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-03-27T18:56:22.172Z,1553712982.172 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-03-27T18:56:22.177Z,1553712982.177 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-03-27T18:56:22.177Z,1553712982.177 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-03-27T18:56:22.180Z,1553712982.180 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-03-27T18:56:22.185Z,1553712982.185 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-03-27T18:56:22.185Z,1553712982.185 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-03-27T18:56:22.186Z,1553712982.186 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-03-27T18:56:27.907Z,1553712987.907 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-03-27T18:56:31.184Z,1553712991.184 [DataOverHttps](INFO): Sending 100 bytes from file Logs/20190327T183721/Express0014.lzma
2019-03-27T18:56:31.342Z,1553712991.342 [CommandLine](IMPORTANT): got command show stack
2019-03-27T18:56:31.342Z,1553712991.342 [CommandLine](IMPORTANT): Behavior Stack:

2019-03-27T18:56:31.342Z,1553712991.342 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-03-27T18:56:31.342Z,1553712991.342 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B
2019-03-27T18:56:31.990Z,1553712991.990 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Express0014.lzma.bak
2019-03-27T18:56:31.990Z,1553712991.990 [DataOverHttps](INFO): SBD MOMSN=10257480
2019-03-27T18:56:43.912Z,1553713003.912 [DataOverHttps](INFO): Sending 775 bytes from file Logs/20190327T185334/Express0001.lzma
2019-03-27T18:56:43.923Z,1553713003.923 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-03-27T18:56:43.923Z,1553713003.923 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-27T18:56:43.924Z,1553713003.924 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-03-27T18:56:43.924Z,1553713003.924 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-27T18:56:43.929Z,1553713003.929 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-27T18:56:43.929Z,1553713003.929 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-27T18:56:43.948Z,1553713003.948 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-27T18:56:43.948Z,1553713003.948 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-27T18:56:43.948Z,1553713003.948 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-27T18:56:44.322Z,1553713004.322 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-27T18:56:44.322Z,1553713004.322 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-03-27T18:56:44.322Z,1553713004.322 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-27T18:56:44.322Z,1553713004.322 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-03-27T18:56:44.323Z,1553713004.323 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-27T18:56:44.323Z,1553713004.323 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-27T18:56:44.714Z,1553713004.714 [DataOverHttps](INFO): Moved sent file to Logs/20190327T185334/Express0001.lzma.bak
2019-03-27T18:56:44.715Z,1553713004.715 [DataOverHttps](INFO): SBD MOMSN=10257493
2019-03-27T18:56:44.740Z,1553713004.740 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-27T18:56:45.932Z,1553713005.932 [Startup:StartupSatComms:B] Stopped
2019-03-27T18:56:45.932Z,1553713005.932 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-03-27T18:56:45.932Z,1553713005.932 [Startup:StartupSatComms] Stopped
2019-03-27T18:56:45.932Z,1553713005.932 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-03-27T18:56:45.937Z,1553713005.937 [Startup](INFO): Completed Startup
2019-03-27T18:56:45.937Z,1553713005.937 [MissionManager](INFO): Startup is completed.
2019-03-27T18:56:45.937Z,1553713005.937 [MissionManager](INFO): Uninitializing Mission Startup
2019-03-27T18:56:45.937Z,1553713005.937 [Startup] Stopped
2019-03-27T18:56:45.938Z,1553713005.938 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-03-27T18:56:45.938Z,1553713005.938 [Startup:A.GoToSurface] Stopped
2019-03-27T18:56:45.938Z,1553713005.938 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-27T18:56:46.311Z,1553713006.311 [MissionManager](IMPORTANT): Started mission Default
2019-03-27T18:56:46.312Z,1553713006.312 [Default] Running Loop=1
2019-03-27T18:56:46.312Z,1553713006.312 [Default](DEBUG): Aggregate::initialize Default
2019-03-27T18:56:46.312Z,1553713006.312 [Default:B.GoToSurface] Running Loop=1
2019-03-27T18:56:46.312Z,1553713006.312 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-27T18:56:46.312Z,1553713006.312 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-27T18:56:46.312Z,1553713006.312 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-27T18:56:46.313Z,1553713006.313 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-27T18:56:46.313Z,1553713006.313 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-27T18:56:46.314Z,1553713006.314 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-27T18:56:46.314Z,1553713006.314 [Default:A.Wait] Running Loop=1
2019-03-27T18:56:46.314Z,1553713006.314 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:56:51.966Z,1553713011.966 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-03-27T18:56:51.966Z,1553713011.966 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19032711581796,35,   0.0,1448.9,  0
2019-03-27T18:56:59.648Z,1553713019.648 [Default:A.Wait](INFO): Done Waiting.
2019-03-27T18:56:59.648Z,1553713019.648 [Default:A.Wait] Stopped
2019-03-27T18:56:59.648Z,1553713019.648 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:57:00.052Z,1553713020.052 [Default:CheckIn] Running Loop=1
2019-03-27T18:57:00.052Z,1553713020.052 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-27T18:57:00.052Z,1553713020.052 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-27T18:57:00.459Z,1553713020.459 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-03-27T18:57:27.651Z,1553713047.651 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:57:27.651Z,1553713047.651 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:57:27.678Z,1553713047.678 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-03-27T18:57:27.682Z,1553713047.682 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-03-27T18:57:27.685Z,1553713047.685 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-03-27T18:57:27.690Z,1553713047.690 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-03-27T18:57:27.694Z,1553713047.694 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = 1.000000 bool
2019-03-27T18:57:27.695Z,1553713047.695 [DUSBL:A.Pitch](DEBUG): Construct.
2019-03-27T18:57:27.701Z,1553713047.701 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-03-27T18:57:27.710Z,1553713047.710 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-03-27T18:57:27.714Z,1553713047.714 [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.acoustic_contact_range/>
        <Sensor:DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

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


2019-03-27T18:57:27.716Z,1553713047.716 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:57:27.901Z,1553713047.901 [NAL9602](INFO): SBD MO Status=0, MOMSN=2458, MT Status=0, MTMSN=0
2019-03-27T18:57:27.902Z,1553713047.902 [NAL9602](INFO): No messages in MT queue
2019-03-27T18:57:27.935Z,1553713047.935 [Default] Stopped
2019-03-27T18:57:27.935Z,1553713047.935 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-27T18:57:27.936Z,1553713047.936 [Default:B.GoToSurface] Stopped
2019-03-27T18:57:27.936Z,1553713047.936 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-27T18:57:27.936Z,1553713047.936 [Default:CheckIn] Stopped
2019-03-27T18:57:27.936Z,1553713047.936 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-27T18:57:27.936Z,1553713047.936 [Default:CheckIn:Read_GPS] Stopped
2019-03-27T18:57:27.936Z,1553713047.936 [MissionManager](IMPORTANT): Started mission DUSBL
2019-03-27T18:57:27.936Z,1553713047.936 [DUSBL] Running Loop=1
2019-03-27T18:57:27.936Z,1553713047.936 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-03-27T18:57:27.936Z,1553713047.936 [DUSBL:A.Pitch] Running Loop=1
2019-03-27T18:57:27.968Z,1553713047.968 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-03-27T18:57:27.968Z,1553713047.968 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-27T18:57:27.968Z,1553713047.968 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-03-27T18:57:27.968Z,1553713047.968 [DUSBL:C] Running Loop=1
2019-03-27T18:57:27.969Z,1553713047.969 [DUSBL:RequestRepeater] Running Loop=1
2019-03-27T18:57:27.969Z,1553713047.969 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:57:27.969Z,1553713047.969 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:57:27.969Z,1553713047.969 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:57:27.969Z,1553713047.969 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:57:27.969Z,1553713047.969 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:57:27.970Z,1553713047.970 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:57:27.970Z,1553713047.970 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:57:27.970Z,1553713047.970 [DUSBL:C] Running Loop=1
2019-03-27T18:57:27.971Z,1553713047.971 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.acoustic_contact_range
2019-03-27T18:57:27.971Z,1553713047.971 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame
2019-03-27T18:57:27.972Z,1553713047.972 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-27T18:57:27.972Z,1553713047.972 [DUSBL:A.Pitch] Running Loop=1
2019-03-27T18:57:28.721Z,1553713048.721 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:57:29.109Z,1553713049.109 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185021.00,A,3648.16622,N,12147.28274,W,0.136,0.00,270319,,,A*7B
2019-03-27T18:57:29.112Z,1553713049.112 [NAL9602](INFO): GPS fix at 20190327T185021: (36.802770, -121.788046)
2019-03-27T18:57:29.526Z,1553713049.526 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:29.530Z,1553713049.530 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:33.597Z,1553713053.597 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:33.598Z,1553713053.598 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:37.599Z,1553713057.599 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:37.604Z,1553713057.604 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:38.056Z,1553713058.056 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:57:38.056Z,1553713058.056 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:57:38.056Z,1553713058.056 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:57:38.057Z,1553713058.057 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:57:38.057Z,1553713058.057 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:57:38.057Z,1553713058.057 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:57:38.057Z,1553713058.057 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:57:38.057Z,1553713058.057 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:57:38.057Z,1553713058.057 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-03-27T18:57:38.058Z,1553713058.058 [DUSBL:RequestRepeater] Running Loop=2
2019-03-27T18:57:38.058Z,1553713058.058 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:57:38.058Z,1553713058.058 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:57:38.058Z,1553713058.058 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:57:38.058Z,1553713058.058 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:57:38.058Z,1553713058.058 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:57:41.642Z,1553713061.642 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:41.643Z,1553713061.643 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:45.683Z,1553713065.683 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:45.687Z,1553713065.687 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:48.599Z,1553713068.599 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:57:48.599Z,1553713068.599 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:57:48.599Z,1553713068.599 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:57:48.599Z,1553713068.599 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater] Running Loop=3
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:57:48.600Z,1553713068.600 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:57:49.723Z,1553713069.723 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:49.724Z,1553713069.724 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:53.780Z,1553713073.780 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:53.784Z,1553713073.784 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:57.811Z,1553713077.811 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:57:57.815Z,1553713077.815 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:57:59.086Z,1553713079.086 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:57:59.086Z,1553713079.086 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:57:59.086Z,1553713079.086 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:57:59.086Z,1553713079.086 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater] Running Loop=4
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:57:59.087Z,1553713079.087 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:57:59.088Z,1553713079.088 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:58:01.050Z,1553713081.050 [NAL9602](INFO): Not Powering down - fast GPS
2019-03-27T18:58:01.843Z,1553713081.843 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:58:01.852Z,1553713081.852 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:58:02.254Z,1553713082.254 [DUSBL_Hydroid](FAULT): unknown deviceResponse_: FF
2019-03-27T18:58:02.254Z,1553713082.254 [DUSBL_Hydroid] Communications Fault, FailCount= 1
2019-03-27T18:58:02.254Z,1553713082.254 [DUSBL_Hydroid](ERROR): Communications Fault
2019-03-27T18:58:02.358Z,1553713082.358 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-03-27T18:58:02.658Z,1553713082.658 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T18:58:03.564Z,1553713083.564 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-03-27T18:58:03.564Z,1553713083.564 [DUSBL_Hydroid] No Fault, FailCount= 1
2019-03-27T18:58:05.882Z,1553713085.882 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T18:58:05.882Z,1553713085.882 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T18:58:09.599Z,1553713089.599 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:58:09.599Z,1553713089.599 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:58:09.599Z,1553713089.599 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:58:09.607Z,1553713089.607 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater] Running Loop=5
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:58:09.608Z,1553713089.608 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:58:09.613Z,1553713089.613 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:58:09.613Z,1553713089.613 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:58:09.613Z,1553713089.613 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:58:20.056Z,1553713100.056 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:58:20.056Z,1553713100.056 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:58:20.057Z,1553713100.057 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:58:20.057Z,1553713100.057 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:58:20.057Z,1553713100.057 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater] Running Loop=6
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:58:20.058Z,1553713100.058 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:58:24.074Z,1553713104.074 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T18:58:24.486Z,1553713104.486 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:58:24.487Z,1553713104.487 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:58:28.507Z,1553713108.507 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:58:28.514Z,1553713108.514 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:58:30.600Z,1553713110.600 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:58:30.600Z,1553713110.600 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:58:30.600Z,1553713110.600 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:58:30.600Z,1553713110.600 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:58:30.600Z,1553713110.600 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:58:30.601Z,1553713110.601 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:58:30.601Z,1553713110.601 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:58:30.601Z,1553713110.601 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:58:30.601Z,1553713110.601 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-03-27T18:58:30.601Z,1553713110.601 [DUSBL:RequestRepeater] Running Loop=7
2019-03-27T18:58:30.601Z,1553713110.601 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:58:30.601Z,1553713110.601 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:58:30.602Z,1553713110.602 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:58:30.602Z,1553713110.602 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:58:30.602Z,1553713110.602 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:58:32.566Z,1553713112.566 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:58:32.571Z,1553713112.571 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:58:36.594Z,1553713116.594 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:58:36.598Z,1553713116.598 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:58:40.626Z,1553713120.626 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:58:40.632Z,1553713120.632 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:58:41.102Z,1553713121.102 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:58:41.102Z,1553713121.102 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:58:41.102Z,1553713121.102 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:58:41.103Z,1553713121.103 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:58:41.103Z,1553713121.103 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:58:41.103Z,1553713121.103 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:58:41.103Z,1553713121.103 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:58:41.103Z,1553713121.103 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:58:41.103Z,1553713121.103 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-03-27T18:58:41.104Z,1553713121.104 [DUSBL:RequestRepeater] Running Loop=8
2019-03-27T18:58:41.104Z,1553713121.104 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:58:41.104Z,1553713121.104 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:58:41.104Z,1553713121.104 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:58:41.104Z,1553713121.104 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:58:41.104Z,1553713121.104 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:58:41.418Z,1553713121.418 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-03-27T18:58:41.614Z,1553713121.614 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-03-27T18:58:41.614Z,1553713121.614 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-03-27T18:58:41.615Z,1553713121.615 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-03-27T18:58:41.615Z,1553713121.615 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-03-27T18:58:41.615Z,1553713121.615 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-03-27T18:58:41.616Z,1553713121.616 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-03-27T18:58:41.616Z,1553713121.616 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-03-27T18:58:41.621Z,1553713121.621 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-03-27T18:58:41.621Z,1553713121.621 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-03-27T18:58:41.622Z,1553713121.622 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-03-27T18:58:41.622Z,1553713121.622 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-03-27T18:58:41.622Z,1553713121.622 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-03-27T18:58:41.659Z,1553713121.659 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-03-27T18:58:41.659Z,1553713121.659 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-03-27T18:58:41.659Z,1553713121.659 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-03-27T18:58:41.672Z,1553713121.672 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-03-27T18:58:41.672Z,1553713121.672 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-03-27T18:58:41.672Z,1553713121.672 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-03-27T18:58:41.681Z,1553713121.681 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-03-27T18:58:41.681Z,1553713121.681 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-03-27T18:58:41.682Z,1553713121.682 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-03-27T18:58:41.682Z,1553713121.682 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-03-27T18:58:41.682Z,1553713121.682 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-03-27T18:58:41.683Z,1553713121.683 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-03-27T18:58:41.683Z,1553713121.683 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-03-27T18:58:41.683Z,1553713121.683 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-03-27T18:58:41.790Z,1553713121.790 [CommandLine](IMPORTANT): DUSBL.MissionTimeout (minute)
2019-03-27T18:58:41.791Z,1553713121.791 [CommandLine](IMPORTANT): DUSBL.NumberOfRequests (count)
2019-03-27T18:58:41.791Z,1553713121.791 [CommandLine](IMPORTANT): DUSBL.TransponderCode (count)
2019-03-27T18:58:41.791Z,1553713121.791 [CommandLine](IMPORTANT): DUSBL.NumberOfPings (count)
2019-03-27T18:58:41.792Z,1553713121.792 [CommandLine](IMPORTANT): DUSBL.EnabledDUSBL (bool)
2019-03-27T18:58:41.792Z,1553713121.792 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_voltage (volt)
2019-03-27T18:58:41.805Z,1553713121.805 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgVoltage (volt)
2019-03-27T18:58:41.805Z,1553713121.805 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_current (milliampere)
2019-03-27T18:58:41.806Z,1553713121.806 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgCurrent (milliampere)
2019-03-27T18:58:44.675Z,1553713124.675 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:58:44.725Z,1553713124.725 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:58:45.886Z,1553713125.886 [DUSBL_Hydroid](FAULT): unknown deviceResponse_: ,80,80,9D,FF
2019-03-27T18:58:45.886Z,1553713125.886 [DUSBL_Hydroid] Communications Fault, FailCount= 2
2019-03-27T18:58:45.886Z,1553713125.886 [DUSBL_Hydroid](ERROR): Communications Fault
2019-03-27T18:58:45.998Z,1553713125.998 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-03-27T18:58:46.290Z,1553713126.290 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T18:58:47.159Z,1553713127.159 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-03-27T18:58:47.159Z,1553713127.159 [DUSBL_Hydroid] No Fault, FailCount= 2
2019-03-27T18:58:49.518Z,1553713129.518 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T18:58:49.518Z,1553713129.518 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T18:58:51.605Z,1553713131.605 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:58:51.605Z,1553713131.605 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:58:51.605Z,1553713131.605 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:58:51.606Z,1553713131.606 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:58:51.606Z,1553713131.606 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:58:51.606Z,1553713131.606 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:58:51.606Z,1553713131.606 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:58:51.606Z,1553713131.606 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:58:51.606Z,1553713131.606 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-03-27T18:58:51.606Z,1553713131.606 [DUSBL:RequestRepeater] Running Loop=9
2019-03-27T18:58:51.607Z,1553713131.607 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:58:51.607Z,1553713131.607 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:58:51.607Z,1553713131.607 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:58:51.607Z,1553713131.607 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:58:51.607Z,1553713131.607 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:58:55.366Z,1553713135.366 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-03-27T18:59:02.095Z,1553713142.095 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:59:02.095Z,1553713142.095 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:59:02.095Z,1553713142.095 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:59:02.096Z,1553713142.096 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:59:02.096Z,1553713142.096 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:59:02.096Z,1553713142.096 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:59:02.096Z,1553713142.096 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:59:02.096Z,1553713142.096 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:59:02.096Z,1553713142.096 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-03-27T18:59:02.096Z,1553713142.096 [DUSBL:RequestRepeater] Running Loop=10
2019-03-27T18:59:02.101Z,1553713142.101 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:59:02.101Z,1553713142.101 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:59:02.101Z,1553713142.101 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:59:02.101Z,1553713142.101 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:59:02.101Z,1553713142.101 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:59:07.702Z,1553713147.702 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T18:59:08.109Z,1553713148.109 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:59:08.114Z,1553713148.114 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:59:12.143Z,1553713152.143 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:59:12.148Z,1553713152.148 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:59:12.561Z,1553713152.561 [DUSBL_Hydroid](FAULT): unknown deviceResponse_: 80,63,E4
2019-03-27T18:59:12.561Z,1553713152.561 [DUSBL_Hydroid] Communications Fault, FailCount= 3
2019-03-27T18:59:12.561Z,1553713152.561 [DUSBL_Hydroid](ERROR): Communications Fault
2019-03-27T18:59:12.723Z,1553713152.723 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:59:12.723Z,1553713152.723 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:59:12.723Z,1553713152.723 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:59:12.724Z,1553713152.724 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:59:12.724Z,1553713152.724 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:59:12.724Z,1553713152.724 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:59:12.724Z,1553713152.724 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:59:12.724Z,1553713152.724 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:59:12.725Z,1553713152.725 [DUSBL](INFO): Completed DUSBL
2019-03-27T18:59:12.725Z,1553713152.725 [MissionManager](INFO): DUSBL is completed.
2019-03-27T18:59:12.725Z,1553713152.725 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-03-27T18:59:12.725Z,1553713152.725 [DUSBL] Stopped
2019-03-27T18:59:12.726Z,1553713152.726 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-03-27T18:59:12.726Z,1553713152.726 [DUSBL:A.Pitch] Stopped
2019-03-27T18:59:12.726Z,1553713152.726 [DUSBL:B.SetSpeed] Stopped
2019-03-27T18:59:12.726Z,1553713152.726 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-03-27T18:59:12.726Z,1553713152.726 [DUSBL:C] Stopped
2019-03-27T18:59:12.738Z,1553713152.738 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-03-27T18:59:12.950Z,1553713152.950 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T18:59:13.062Z,1553713153.062 [MissionManager](IMPORTANT): Started mission Default
2019-03-27T18:59:13.062Z,1553713153.062 [Default] Running Loop=1
2019-03-27T18:59:13.062Z,1553713153.062 [Default](DEBUG): Aggregate::initialize Default
2019-03-27T18:59:13.062Z,1553713153.062 [Default:B.GoToSurface] Running Loop=1
2019-03-27T18:59:13.062Z,1553713153.062 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-27T18:59:13.062Z,1553713153.062 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-27T18:59:13.063Z,1553713153.063 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-27T18:59:13.063Z,1553713153.063 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-27T18:59:13.063Z,1553713153.063 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-27T18:59:13.064Z,1553713153.064 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-27T18:59:13.064Z,1553713153.064 [Default:A.Wait] Running Loop=1
2019-03-27T18:59:13.064Z,1553713153.064 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:59:13.841Z,1553713153.841 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-03-27T18:59:13.841Z,1553713153.841 [DUSBL_Hydroid] No Fault, FailCount= 3
2019-03-27T18:59:16.186Z,1553713156.186 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T18:59:16.186Z,1553713156.186 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T18:59:26.311Z,1553713166.311 [Default:A.Wait](INFO): Done Waiting.
2019-03-27T18:59:26.311Z,1553713166.311 [Default:A.Wait] Stopped
2019-03-27T18:59:26.311Z,1553713166.311 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:59:26.726Z,1553713166.726 [Default:CheckIn] Running Loop=1
2019-03-27T18:59:26.726Z,1553713166.726 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-27T18:59:26.726Z,1553713166.726 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-27T18:59:28.321Z,1553713168.321 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:59:28.712Z,1553713168.712 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185221.00,A,3648.16744,N,12147.28427,W,0.039,0.00,270319,,,A*76
2019-03-27T18:59:28.714Z,1553713168.714 [NAL9602](INFO): GPS fix at 20190327T185221: (36.802791, -121.788071)
2019-03-27T18:59:28.783Z,1553713168.783 [Default:CheckIn:Read_GPS] Stopped
2019-03-27T18:59:28.783Z,1553713168.783 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-03-27T18:59:29.185Z,1553713169.185 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-03-27T18:59:34.118Z,1553713174.118 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T18:59:35.532Z,1553713175.532 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190327T185334/Courier0004.lzma
2019-03-27T18:59:36.335Z,1553713176.335 [DataOverHttps](INFO): Moved sent file to Logs/20190327T185334/Courier0004.lzma.bak
2019-03-27T18:59:36.335Z,1553713176.335 [DataOverHttps](INFO): SBD MOMSN=10257744
2019-03-27T18:59:40.990Z,1553713180.990 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:59:40.991Z,1553713180.991 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:59:41.099Z,1553713181.099 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-03-27T18:59:41.109Z,1553713181.109 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-03-27T18:59:41.111Z,1553713181.111 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-03-27T18:59:41.142Z,1553713181.142 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-03-27T18:59:41.144Z,1553713181.144 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = 1.000000 bool
2019-03-27T18:59:41.153Z,1553713181.153 [DUSBL:A.Pitch](DEBUG): Construct.
2019-03-27T18:59:41.170Z,1553713181.170 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-03-27T18:59:41.193Z,1553713181.193 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-03-27T18:59:41.213Z,1553713181.213 [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.acoustic_contact_range/>
        <Sensor:DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

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


2019-03-27T18:59:41.215Z,1553713181.215 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:59:41.432Z,1553713181.432 [Default] Stopped
2019-03-27T18:59:41.432Z,1553713181.432 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-27T18:59:41.432Z,1553713181.432 [Default:B.GoToSurface] Stopped
2019-03-27T18:59:41.432Z,1553713181.432 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-27T18:59:41.432Z,1553713181.432 [Default:CheckIn] Stopped
2019-03-27T18:59:41.432Z,1553713181.432 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-27T18:59:41.432Z,1553713181.432 [Default:CheckIn:Read_Iridium] Stopped
2019-03-27T18:59:41.453Z,1553713181.453 [MissionManager](IMPORTANT): Started mission DUSBL
2019-03-27T18:59:41.453Z,1553713181.453 [DUSBL] Running Loop=1
2019-03-27T18:59:41.453Z,1553713181.453 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-03-27T18:59:41.453Z,1553713181.453 [DUSBL:A.Pitch] Running Loop=1
2019-03-27T18:59:41.453Z,1553713181.453 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:C] Running Loop=1
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:RequestRepeater] Running Loop=1
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:59:41.454Z,1553713181.454 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:59:41.455Z,1553713181.455 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:59:41.455Z,1553713181.455 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:59:41.455Z,1553713181.455 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:59:41.455Z,1553713181.455 [DUSBL:C] Running Loop=1
2019-03-27T18:59:41.456Z,1553713181.456 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.acoustic_contact_range
2019-03-27T18:59:41.456Z,1553713181.456 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame
2019-03-27T18:59:41.465Z,1553713181.465 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-27T18:59:41.465Z,1553713181.465 [DUSBL:A.Pitch] Running Loop=1
2019-03-27T18:59:43.011Z,1553713183.011 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:59:43.021Z,1553713183.021 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:59:47.046Z,1553713187.046 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:59:47.047Z,1553713187.047 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:59:50.131Z,1553713190.131 [DataOverHttps](INFO): Sending 1160 bytes from file Logs/20190327T185334/Express0005.lzma
2019-03-27T18:59:50.934Z,1553713190.934 [DataOverHttps](INFO): Moved sent file to Logs/20190327T185334/Express0005.lzma.bak
2019-03-27T18:59:50.934Z,1553713190.934 [DataOverHttps](INFO): SBD MOMSN=10257747
2019-03-27T18:59:51.091Z,1553713191.091 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:59:51.096Z,1553713191.096 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:59:51.507Z,1553713191.507 [DUSBL_Hydroid](FAULT): unknown deviceResponse_: 6,80,81,0E,FF
2019-03-27T18:59:51.507Z,1553713191.507 [DUSBL_Hydroid] Communications Fault, FailCount= 4
2019-03-27T18:59:51.507Z,1553713191.507 [DUSBL_Hydroid](ERROR): Communications Fault
2019-03-27T18:59:51.596Z,1553713191.596 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:59:51.601Z,1553713191.601 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:59:51.601Z,1553713191.601 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:59:51.601Z,1553713191.601 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater] Running Loop=2
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:59:51.602Z,1553713191.602 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:59:51.628Z,1553713191.628 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-03-27T18:59:51.894Z,1553713191.894 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T18:59:52.773Z,1553713192.773 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-03-27T18:59:52.773Z,1553713192.773 [DUSBL_Hydroid] No Fault, FailCount= 4
2019-03-27T18:59:55.126Z,1553713195.126 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T18:59:55.126Z,1553713195.126 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T19:00:02.064Z,1553713202.064 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:00:02.064Z,1553713202.064 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:00:02.064Z,1553713202.064 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:00:02.069Z,1553713202.069 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:00:02.069Z,1553713202.069 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:00:02.069Z,1553713202.069 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:00:02.069Z,1553713202.069 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:00:02.069Z,1553713202.069 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:00:02.070Z,1553713202.070 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-03-27T19:00:02.070Z,1553713202.070 [DUSBL:RequestRepeater] Running Loop=3
2019-03-27T19:00:02.070Z,1553713202.070 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:00:02.070Z,1553713202.070 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:00:02.070Z,1553713202.070 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:00:02.070Z,1553713202.070 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:00:02.070Z,1553713202.070 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:00:12.548Z,1553713212.548 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:00:12.549Z,1553713212.549 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:00:12.549Z,1553713212.549 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:00:12.551Z,1553713212.551 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:00:12.552Z,1553713212.552 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:00:12.552Z,1553713212.552 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:00:12.552Z,1553713212.552 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:00:12.569Z,1553713212.569 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:00:12.569Z,1553713212.569 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-03-27T19:00:12.570Z,1553713212.570 [DUSBL:RequestRepeater] Running Loop=4
2019-03-27T19:00:12.570Z,1553713212.570 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:00:12.570Z,1553713212.570 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:00:12.571Z,1553713212.571 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:00:12.571Z,1553713212.571 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:00:12.571Z,1553713212.571 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:00:13.306Z,1553713213.306 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T19:00:13.715Z,1553713213.715 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T19:00:13.719Z,1553713213.719 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T19:00:17.755Z,1553713217.755 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T19:00:17.760Z,1553713217.760 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T19:00:18.155Z,1553713218.155 [DUSBL_Hydroid](FAULT): unknown deviceResponse_: ,80,63,E4
2019-03-27T19:00:18.155Z,1553713218.155 [DUSBL_Hydroid] Communications Fault, FailCount= 5
2019-03-27T19:00:18.155Z,1553713218.155 [DUSBL_Hydroid](ERROR): Communications Fault
2019-03-27T19:00:18.254Z,1553713218.254 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-03-27T19:00:18.584Z,1553713218.584 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T19:00:19.413Z,1553713219.413 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-03-27T19:00:19.413Z,1553713219.413 [DUSBL_Hydroid] No Fault, FailCount= 5
2019-03-27T19:00:21.790Z,1553713221.790 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T19:00:21.790Z,1553713221.790 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T19:00:23.036Z,1553713223.036 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:00:23.036Z,1553713223.036 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:00:23.036Z,1553713223.036 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:00:23.041Z,1553713223.041 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:00:23.041Z,1553713223.041 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:00:23.041Z,1553713223.041 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:00:23.041Z,1553713223.041 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:00:23.041Z,1553713223.041 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:00:23.042Z,1553713223.042 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-03-27T19:00:23.042Z,1553713223.042 [DUSBL:RequestRepeater] Running Loop=5
2019-03-27T19:00:23.042Z,1553713223.042 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:00:23.042Z,1553713223.042 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:00:23.042Z,1553713223.042 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:00:23.042Z,1553713223.042 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:00:23.042Z,1553713223.042 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:00:33.542Z,1553713233.542 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:00:33.543Z,1553713233.543 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:00:33.543Z,1553713233.543 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:00:33.545Z,1553713233.545 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:00:33.545Z,1553713233.545 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:00:33.545Z,1553713233.545 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:00:33.546Z,1553713233.546 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:00:33.546Z,1553713233.546 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:00:33.546Z,1553713233.546 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-03-27T19:00:33.547Z,1553713233.547 [DUSBL:RequestRepeater] Running Loop=6
2019-03-27T19:00:33.547Z,1553713233.547 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:00:33.547Z,1553713233.547 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:00:33.548Z,1553713233.548 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:00:33.548Z,1553713233.548 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:00:33.548Z,1553713233.548 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:00:39.970Z,1553713239.970 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T19:00:40.379Z,1553713240.379 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T19:00:40.383Z,1553713240.383 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T19:00:44.042Z,1553713244.042 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:00:44.042Z,1553713244.042 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:00:44.043Z,1553713244.043 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:00:44.043Z,1553713244.043 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:00:44.043Z,1553713244.043 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater] Running Loop=7
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:00:44.044Z,1553713244.044 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:00:44.415Z,1553713244.415 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T19:00:44.420Z,1553713244.420 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T19:00:44.818Z,1553713244.818 [DUSBL_Hydroid](FAULT): unknown deviceResponse_: 80,63,F4
2019-03-27T19:00:44.819Z,1553713244.819 [DUSBL_Hydroid] Communications Fault, FailCount= 6
2019-03-27T19:00:44.819Z,1553713244.819 [DUSBL_Hydroid](ERROR): Communications Fault
2019-03-27T19:00:44.942Z,1553713244.942 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-03-27T19:00:45.226Z,1553713245.226 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T19:00:46.072Z,1553713246.072 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-03-27T19:00:46.072Z,1553713246.072 [DUSBL_Hydroid] No Fault, FailCount= 6
2019-03-27T19:00:48.458Z,1553713248.458 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T19:00:48.458Z,1553713248.458 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T19:00:54.600Z,1553713254.600 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:00:54.601Z,1553713254.601 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:00:54.601Z,1553713254.601 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:00:54.602Z,1553713254.602 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:00:54.602Z,1553713254.602 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:00:54.602Z,1553713254.602 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:00:54.602Z,1553713254.602 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:00:54.602Z,1553713254.602 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:00:54.602Z,1553713254.602 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-03-27T19:00:54.603Z,1553713254.603 [DUSBL:RequestRepeater] Running Loop=8
2019-03-27T19:00:54.603Z,1553713254.603 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:00:54.603Z,1553713254.603 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:00:54.603Z,1553713254.603 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:00:54.603Z,1553713254.603 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:00:54.603Z,1553713254.603 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:01:05.118Z,1553713265.118 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:01:05.118Z,1553713265.118 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:01:05.118Z,1553713265.118 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater] Running Loop=9
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:01:05.119Z,1553713265.119 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:01:05.120Z,1553713265.120 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:01:06.634Z,1553713266.634 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T19:01:07.043Z,1553713267.043 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T19:01:07.047Z,1553713267.047 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T19:01:08.697Z,1553713268.697 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-03-27T19:01:08.700Z,1553713268.700 [BPC1](INFO): Received data from all battery sticks.
2019-03-27T19:01:11.083Z,1553713271.083 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T19:01:11.088Z,1553713271.088 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T19:01:11.504Z,1553713271.504 [DUSBL_Hydroid](FAULT): unknown deviceResponse_: 0,80,63,E4
2019-03-27T19:01:11.505Z,1553713271.505 [DUSBL_Hydroid] Communications Fault, FailCount= 7
2019-03-27T19:01:11.505Z,1553713271.505 [DUSBL_Hydroid](ERROR): Communications Fault
2019-03-27T19:01:11.593Z,1553713271.593 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-03-27T19:01:11.886Z,1553713271.886 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T19:01:12.780Z,1553713272.780 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-03-27T19:01:12.781Z,1553713272.781 [DUSBL_Hydroid] No Fault, FailCount= 7
2019-03-27T19:01:15.118Z,1553713275.118 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T19:01:15.118Z,1553713275.118 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T19:01:15.608Z,1553713275.608 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:01:15.608Z,1553713275.608 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:01:15.608Z,1553713275.608 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater] Running Loop=10
2019-03-27T19:01:15.613Z,1553713275.613 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T19:01:15.614Z,1553713275.614 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T19:01:15.614Z,1553713275.614 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T19:01:15.614Z,1553713275.614 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T19:01:15.614Z,1553713275.614 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:01:26.060Z,1553713286.060 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T19:01:26.060Z,1553713286.060 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T19:01:26.060Z,1553713286.060 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:01:26.061Z,1553713286.061 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T19:01:26.061Z,1553713286.061 [DUSBL:RequestRepeater] Stopped
2019-03-27T19:01:26.061Z,1553713286.061 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T19:01:26.061Z,1553713286.061 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T19:01:26.061Z,1553713286.061 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T19:01:26.062Z,1553713286.062 [DUSBL](INFO): Completed DUSBL
2019-03-27T19:01:26.062Z,1553713286.062 [MissionManager](INFO): DUSBL is completed.
2019-03-27T19:01:26.062Z,1553713286.062 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-03-27T19:01:26.062Z,1553713286.062 [DUSBL] Stopped
2019-03-27T19:01:26.062Z,1553713286.062 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-03-27T19:01:26.063Z,1553713286.063 [DUSBL:A.Pitch] Stopped
2019-03-27T19:01:26.063Z,1553713286.063 [DUSBL:B.SetSpeed] Stopped
2019-03-27T19:01:26.063Z,1553713286.063 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-03-27T19:01:26.063Z,1553713286.063 [DUSBL:C] Stopped
2019-03-27T19:01:26.464Z,1553713286.464 [MissionManager](IMPORTANT): Started mission Default
2019-03-27T19:01:26.464Z,1553713286.464 [Default] Running Loop=1
2019-03-27T19:01:26.464Z,1553713286.464 [Default](DEBUG): Aggregate::initialize Default
2019-03-27T19:01:26.464Z,1553713286.464 [Default:B.GoToSurface] Running Loop=1
2019-03-27T19:01:26.464Z,1553713286.464 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-27T19:01:26.465Z,1553713286.465 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-27T19:01:26.465Z,1553713286.465 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-27T19:01:26.465Z,1553713286.465 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-27T19:01:26.466Z,1553713286.466 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-27T19:01:26.466Z,1553713286.466 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-27T19:01:26.466Z,1553713286.466 [Default:A.Wait] Running Loop=1
2019-03-27T19:01:26.466Z,1553713286.466 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-27T19:01:33.298Z,1553713293.298 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T19:01:36.580Z,1553713296.580 [RDI_Pathfinder](ERROR): only read 4 of 5 data items
2019-03-27T19:01:36.580Z,1553713296.580 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,    +0,    -2,    -4,    +0    -1,    -2,    -4,A
2019-03-27T19:01:36.591Z,1553713296.591 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-27T19:01:36.591Z,1553713296.591 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-27T19:01:36.603Z,1553713296.603 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-27T19:01:36.983Z,1553713296.983 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-27T19:01:36.983Z,1553713296.983 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-27T19:01:39.800Z,1553713299.800 [Default:A.Wait](INFO): Done Waiting.
2019-03-27T19:01:39.800Z,1553713299.800 [Default:A.Wait] Stopped
2019-03-27T19:01:39.800Z,1553713299.800 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T19:01:40.204Z,1553713300.204 [Default:CheckIn] Running Loop=1
2019-03-27T19:01:40.204Z,1553713300.204 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-27T19:01:40.205Z,1553713300.205 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-27T19:02:54.986Z,1553713374.986 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-03-27T19:02:54.987Z,1553713374.987 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19032712042096,35.   0.0,1448.9,  0
2019-03-27T19:03:06.374Z,1553713386.374 [CommandLine](IMPORTANT): got command restart application
2019-03-27T19:03:07.381Z,1553713387.381 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-03-27T19:03:07.381Z,1553713387.381 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:07.381Z,1553713387.381 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:07.409Z,1553713387.409 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-03-27T19:03:07.409Z,1553713387.409 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:07.410Z,1553713387.410 [CommandLine](INFO): Join timeout helper Thread ID is 8494
2019-03-27T19:03:07.410Z,1553713387.410 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-03-27T19:03:07.410Z,1553713387.410 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:07.411Z,1553713387.411 [NavChartDb](INFO): Join timeout helper Thread ID is 8495
2019-03-27T19:03:07.717Z,1553713387.717 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:07.717Z,1553713387.717 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:07.737Z,1553713387.737 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-03-27T19:03:07.737Z,1553713387.737 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:07.737Z,1553713387.737 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 8496
2019-03-27T19:03:08.005Z,1553713388.005 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:08.005Z,1553713388.005 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-03-27T19:03:08.006Z,1553713388.006 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.025Z,1553713388.025 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-03-27T19:03:08.025Z,1553713388.025 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.025Z,1553713388.025 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 8497
2019-03-27T19:03:08.149Z,1553713388.149 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:08.149Z,1553713388.149 [CTD_NeilBrown](INFO): Powering down
2019-03-27T19:03:08.161Z,1553713388.161 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.165Z,1553713388.165 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-03-27T19:03:08.165Z,1553713388.165 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.165Z,1553713388.165 [Radio_Surface](INFO): Join timeout helper Thread ID is 8498
2019-03-27T19:03:08.421Z,1553713388.421 [Radio_Surface](INFO): Powering down
2019-03-27T19:03:08.422Z,1553713388.422 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:08.422Z,1553713388.422 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.430Z,1553713388.430 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-03-27T19:03:08.430Z,1553713388.430 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.430Z,1553713388.430 [DataOverHttps](INFO): Join timeout helper Thread ID is 8499
2019-03-27T19:03:08.625Z,1553713388.625 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:08.625Z,1553713388.625 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.630Z,1553713388.630 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-03-27T19:03:08.630Z,1553713388.630 [logger ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.630Z,1553713388.630 [logger](INFO): Join timeout helper Thread ID is 8500
2019-03-27T19:03:08.702Z,1553713388.702 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:08.702Z,1553713388.702 [logger ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.714Z,1553713388.714 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-03-27T19:03:08.714Z,1553713388.714 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.714Z,1553713388.714 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-03-27T19:03:08.714Z,1553713388.714 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:08.714Z,1553713388.714 [controlThread](INFO): Join timeout helper Thread ID is 8501
2019-03-27T19:03:08.742Z,1553713388.742 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T19:03:08.742Z,1553713388.742 [controlThread](DEBUG): Uninitializing ControlThread
2019-03-27T19:03:08.743Z,1553713388.743 [AHRS_M2](INFO): Powering down
2019-03-27T19:03:08.814Z,1553713388.814 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T19:03:08.885Z,1553713388.885 [Micromodem](INFO): Powering down
2019-03-27T19:03:08.981Z,1553713388.981 [NAL9602](INFO): Powering down
2019-03-27T19:03:09.053Z,1553713389.053 [RDI_Pathfinder](INFO): Powering down
2019-03-27T19:03:09.054Z,1553713389.054 [RDI_PathfinderUp](INFO): Powering down
2019-03-27T19:03:09.055Z,1553713389.055 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-03-27T19:03:09.056Z,1553713389.056 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-03-27T19:03:09.057Z,1553713389.057 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-03-27T19:03:09.057Z,1553713389.057 [MissionManager](INFO): Uninitializing Mission Default
2019-03-27T19:03:09.057Z,1553713389.057 [Default] Stopped
2019-03-27T19:03:09.057Z,1553713389.057 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-27T19:03:09.058Z,1553713389.058 [Default:B.GoToSurface] Stopped
2019-03-27T19:03:09.058Z,1553713389.058 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-27T19:03:09.058Z,1553713389.058 [Default:CheckIn] Stopped
2019-03-27T19:03:09.058Z,1553713389.058 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-27T19:03:09.058Z,1553713389.058 [Default:CheckIn:Read_GPS] Stopped
2019-03-27T19:03:09.060Z,1553713389.060 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-03-27T19:03:09.060Z,1553713389.060 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-03-27T19:03:09.061Z,1553713389.061 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-03-27T19:03:09.061Z,1553713389.061 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-03-27T19:03:09.062Z,1553713389.062 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-03-27T19:03:09.062Z,1553713389.062 [BuoyancyServo](INFO): Powering down
2019-03-27T19:03:09.073Z,1553713389.073 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-03-27T19:03:09.073Z,1553713389.073 [ElevatorServo](INFO): Powering down
2019-03-27T19:03:09.074Z,1553713389.074 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-03-27T19:03:09.074Z,1553713389.074 [MassServo](INFO): Powering down
2019-03-27T19:03:09.075Z,1553713389.075 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-03-27T19:03:09.075Z,1553713389.075 [RudderServo](INFO): Powering down
2019-03-27T19:03:09.075Z,1553713389.076 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-03-27T19:03:09.076Z,1553713389.076 [ThrusterServo](INFO): Powering down
2019-03-27T19:03:09.076Z,1553713389.076 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-03-27T19:03:09.077Z,1553713389.077 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-03-27T19:03:09.077Z,1553713389.077 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-03-27T19:03:09.077Z,1553713389.077 [CBIT](DEBUG): Powering off loads.
2019-03-27T19:03:09.089Z,1553713389.089 [CBIT](DEBUG): Disabling WDT.
2019-03-27T19:03:09.101Z,1553713389.101 [CBIT](DEBUG): Opening all GF detection circuits.
2019-03-27T19:03:09.102Z,1553713389.102 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:09.160Z,1553713389.160 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:09.170Z,1553713389.170 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:09.216Z,1553713389.216 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:09.219Z,1553713389.219 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:09.273Z,1553713389.273 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-27T19:03:09.344Z,1553713389.344 [logger ThreadHandler](INFO): Thread cancelled.