2019-04-10T00:31:54.779Z,1554856314.779 [Supervisor](DEBUG): Initializing supervisor.
2019-04-10T00:31:54.782Z,1554856314.782 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-10T00:31:54.783Z,1554856314.783 [SyncHandler](INFO): Protected caller Thread ID is 2020
2019-04-10T00:31:54.783Z,1554856314.783 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-10T00:31:54.785Z,1554856314.785 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-10T00:31:54.785Z,1554856314.785 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2021
2019-04-10T00:31:54.788Z,1554856314.788 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-10T00:31:54.800Z,1554856314.800 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-10T00:31:54.801Z,1554856314.801 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-10T00:31:54.802Z,1554856314.802 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2022
2019-04-10T00:31:54.803Z,1554856314.803 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-10T00:31:54.804Z,1554856314.804 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-10T00:31:54.804Z,1554856314.804 [logger ThreadHandler](INFO): Protected caller Thread ID is 2023
2019-04-10T00:31:54.806Z,1554856314.806 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-10T00:31:54.806Z,1554856314.806 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-10T00:31:54.808Z,1554856314.808 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-10T00:31:55.268Z,1554856315.268 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-10T00:31:55.268Z,1554856315.268 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-10T00:31:55.370Z,1554856315.370 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-10T00:31:55.370Z,1554856315.370 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-10T00:31:55.726Z,1554856315.726 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-10T00:31:55.726Z,1554856315.726 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-10T00:31:55.876Z,1554856315.876 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-10T00:31:55.876Z,1554856315.876 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-10T00:31:56.082Z,1554856316.082 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-10T00:31:56.083Z,1554856316.083 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-10T00:31:56.578Z,1554856316.578 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-10T00:31:56.579Z,1554856316.579 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-10T00:31:56.805Z,1554856316.805 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-10T00:31:56.805Z,1554856316.805 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-10T00:31:56.960Z,1554856316.960 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-10T00:31:56.961Z,1554856316.961 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-10T00:31:57.172Z,1554856317.172 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-10T00:31:57.173Z,1554856317.173 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-10T00:31:57.272Z,1554856317.272 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-10T00:31:57.273Z,1554856317.273 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-10T00:31:57.634Z,1554856317.634 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-10T00:31:57.635Z,1554856317.635 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-10T00:31:57.878Z,1554856317.878 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-10T00:31:58.028Z,1554856318.028 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-10T00:31:58.029Z,1554856318.029 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-10T00:31:58.865Z,1554856318.865 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-10T00:31:58.866Z,1554856318.866 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-10T00:31:59.293Z,1554856319.293 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-10T00:31:59.295Z,1554856319.295 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-10T00:31:59.296Z,1554856319.296 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-10T00:31:59.522Z,1554856319.522 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-10T00:31:59.627Z,1554856319.627 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-10T00:31:59.731Z,1554856319.731 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-10T00:31:59.972Z,1554856319.972 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-10T00:31:59.973Z,1554856319.973 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-10T00:32:00.060Z,1554856320.060 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-10T00:32:00.156Z,1554856320.156 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-10T00:32:00.258Z,1554856320.258 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-10T00:32:00.342Z,1554856320.342 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-10T00:32:00.458Z,1554856320.458 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-10T00:32:00.646Z,1554856320.646 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-10T00:32:00.788Z,1554856320.788 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-04-10T00:32:00.789Z,1554856320.789 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-10T00:32:00.800Z,1554856320.800 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-10T00:32:01.202Z,1554856321.202 [AHRS_M2] Loaded
2019-04-10T00:32:01.202Z,1554856321.202 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-10T00:32:01.285Z,1554856321.285 [DataOverHttps] Loaded
2019-04-10T00:32:01.285Z,1554856321.285 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-10T00:32:01.286Z,1554856321.286 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-04-10T00:32:01.287Z,1554856321.287 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2102
2019-04-10T00:32:01.301Z,1554856321.301 [Depth_Keller] Loaded
2019-04-10T00:32:01.301Z,1554856321.301 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-10T00:32:01.306Z,1554856321.306 [DropWeight] Loaded
2019-04-10T00:32:01.306Z,1554856321.306 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-10T00:32:01.365Z,1554856321.365 [DUSBL_Hydroid] Loaded
2019-04-10T00:32:01.365Z,1554856321.365 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-10T00:32:01.407Z,1554856321.407 [Micromodem] Loaded
2019-04-10T00:32:01.407Z,1554856321.407 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-10T00:32:01.509Z,1554856321.509 [NAL9602] Loaded
2019-04-10T00:32:01.510Z,1554856321.510 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-10T00:32:01.526Z,1554856321.526 [Onboard] Loaded
2019-04-10T00:32:01.526Z,1554856321.526 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-10T00:32:01.532Z,1554856321.532 [PowerOnly] Loaded
2019-04-10T00:32:01.532Z,1554856321.532 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-10T00:32:01.539Z,1554856321.539 [Radio_Surface] Loaded
2019-04-10T00:32:01.540Z,1554856321.540 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-10T00:32:01.541Z,1554856321.541 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-04-10T00:32:01.541Z,1554856321.541 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2103
2019-04-10T00:32:01.588Z,1554856321.588 [RDI_Pathfinder] Loaded
2019-04-10T00:32:01.588Z,1554856321.588 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-10T00:32:03.146Z,1554856323.146 [BPC1] Loaded
2019-04-10T00:32:03.146Z,1554856323.146 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-10T00:32:03.147Z,1554856323.147 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-10T00:32:03.147Z,1554856323.147 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-10T00:32:03.205Z,1554856323.205 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-10T00:32:03.205Z,1554856323.205 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-10T00:32:03.692Z,1554856323.692 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-10T00:32:03.692Z,1554856323.692 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-10T00:32:03.713Z,1554856323.713 [NavChart] Loaded
2019-04-10T00:32:03.714Z,1554856323.714 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-10T00:32:03.718Z,1554856323.718 [UniversalFixResidualReporter] Loaded
2019-04-10T00:32:03.718Z,1554856323.718 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-10T00:32:03.719Z,1554856323.719 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-10T00:32:03.719Z,1554856323.719 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-10T00:32:03.886Z,1554856323.886 [BuoyancyServo] Loaded
2019-04-10T00:32:03.887Z,1554856323.887 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-10T00:32:03.903Z,1554856323.903 [ElevatorServo] Loaded
2019-04-10T00:32:03.903Z,1554856323.903 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-10T00:32:03.918Z,1554856323.918 [MassServo] Loaded
2019-04-10T00:32:03.918Z,1554856323.918 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-10T00:32:03.934Z,1554856323.934 [RudderServo] Loaded
2019-04-10T00:32:03.935Z,1554856323.935 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-10T00:32:03.950Z,1554856323.950 [ThrusterServo] Loaded
2019-04-10T00:32:03.950Z,1554856323.950 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-10T00:32:03.950Z,1554856323.950 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-10T00:32:03.951Z,1554856323.951 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-10T00:32:04.210Z,1554856324.210 [CTD_NeilBrown] Loaded
2019-04-10T00:32:04.211Z,1554856324.211 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-10T00:32:04.212Z,1554856324.212 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CF4E0
2019-04-10T00:32:04.212Z,1554856324.212 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2104
2019-04-10T00:32:04.258Z,1554856324.258 [WetLabsSeaOWL_UV_A] Loaded
2019-04-10T00:32:04.259Z,1554856324.259 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-10T00:32:04.260Z,1554856324.260 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FF4E0
2019-04-10T00:32:04.260Z,1554856324.260 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 2105
2019-04-10T00:32:04.261Z,1554856324.261 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-10T00:32:04.261Z,1554856324.261 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-10T00:32:04.549Z,1554856324.549 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-10T00:32:04.550Z,1554856324.550 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-10T00:32:04.592Z,1554856324.592 [DepthRateCalculator] Loaded
2019-04-10T00:32:04.593Z,1554856324.593 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-10T00:32:04.598Z,1554856324.598 [PitchRateCalculator] Loaded
2019-04-10T00:32:04.599Z,1554856324.599 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-10T00:32:04.611Z,1554856324.611 [SpeedCalculator] Loaded
2019-04-10T00:32:04.612Z,1554856324.612 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-10T00:32:04.633Z,1554856324.633 [TempGradientCalculator] Loaded
2019-04-10T00:32:04.634Z,1554856324.634 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-10T00:32:04.639Z,1554856324.639 [YawRateCalculator] Loaded
2019-04-10T00:32:04.640Z,1554856324.640 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-10T00:32:04.682Z,1554856324.682 [ElevatorOffsetCalculator] Loaded
2019-04-10T00:32:04.682Z,1554856324.682 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-10T00:32:04.682Z,1554856324.682 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-10T00:32:04.683Z,1554856324.683 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-10T00:32:04.824Z,1554856324.824 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-10T00:32:04.848Z,1554856324.848 [SBIT] Loaded
2019-04-10T00:32:04.848Z,1554856324.848 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-10T00:32:04.849Z,1554856324.849 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-10T00:32:04.861Z,1554856324.861 [IBIT] Loaded
2019-04-10T00:32:04.862Z,1554856324.862 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-10T00:32:04.865Z,1554856324.865 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-10T00:32:05.009Z,1554856325.009 [CBIT] Loaded
2019-04-10T00:32:05.009Z,1554856325.009 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-10T00:32:05.010Z,1554856325.010 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-10T00:32:05.010Z,1554856325.010 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-10T00:32:05.082Z,1554856325.082 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-10T00:32:05.082Z,1554856325.082 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-10T00:32:05.187Z,1554856325.187 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-10T00:32:05.188Z,1554856325.188 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-10T00:32:05.256Z,1554856325.256 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-10T00:32:05.344Z,1554856325.344 [VerticalControl] Loaded
2019-04-10T00:32:05.344Z,1554856325.344 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-10T00:32:05.345Z,1554856325.345 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-10T00:32:05.404Z,1554856325.404 [HorizontalControl] Loaded
2019-04-10T00:32:05.404Z,1554856325.404 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-10T00:32:05.405Z,1554856325.405 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-10T00:32:05.407Z,1554856325.407 [SpeedControl] Loaded
2019-04-10T00:32:05.407Z,1554856325.407 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-10T00:32:05.408Z,1554856325.408 [LoopControl](DEBUG): Construct LoopControl.
2019-04-10T00:32:05.408Z,1554856325.408 [LoopControl] Loaded
2019-04-10T00:32:05.409Z,1554856325.409 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-10T00:32:05.409Z,1554856325.409 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-10T00:32:05.410Z,1554856325.410 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-10T00:32:05.438Z,1554856325.438 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-10T00:32:05.441Z,1554856325.441 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-10T00:32:05.442Z,1554856325.442 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-10T00:32:05.449Z,1554856325.449 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-10T00:32:05.450Z,1554856325.450 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2019-04-10T00:32:05.450Z,1554856325.450 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2106
2019-04-10T00:32:05.455Z,1554856325.455 [Supervisor](INFO): Main Thread ID is 802
2019-04-10T00:32:05.455Z,1554856325.455 [Supervisor](DEBUG): Running supervisor.
2019-04-10T00:32:05.456Z,1554856325.456 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2107
2019-04-10T00:32:05.458Z,1554856325.458 [controlThread ThreadHandler](INFO): Handler Thread ID is 2108
2019-04-10T00:32:05.459Z,1554856325.459 [controlThread](DEBUG): Initializing ControlThread
2019-04-10T00:32:05.464Z,1554856325.464 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-10T00:32:05.464Z,1554856325.464 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-10T00:32:05.465Z,1554856325.465 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-10T00:32:05.466Z,1554856325.466 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-10T00:32:05.466Z,1554856325.466 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-10T00:32:05.466Z,1554856325.466 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-10T00:32:05.467Z,1554856325.467 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-10T00:32:05.467Z,1554856325.467 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-10T00:32:05.468Z,1554856325.468 [SBIT](INFO): Initialize SBIT Component.
2019-04-10T00:32:05.468Z,1554856325.468 [SBIT](IMPORTANT): git: 2019-03-18-31-ge98d5dc
2019-04-10T00:32:05.468Z,1554856325.468 [SBIT](INFO): git hash: e98d5dc50cbc39e402f19b9946ff4dc0776c8725
2019-04-10T00:32:05.469Z,1554856325.469 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-10T00:32:05.469Z,1554856325.469 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-10T00:32:05.470Z,1554856325.470 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-04-10T00:32:05.471Z,1554856325.471 [IBIT](INFO): Initialize IBIT Component.
2019-04-10T00:32:05.471Z,1554856325.471 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-10T00:32:05.472Z,1554856325.472 [logger ThreadHandler](INFO): Handler Thread ID is 2109
2019-04-10T00:32:05.485Z,1554856325.485 [CBIT](DEBUG): Initialized mux pins.
2019-04-10T00:32:05.485Z,1554856325.485 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-10T00:32:05.489Z,1554856325.489 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2110
2019-04-10T00:32:05.490Z,1554856325.490 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-10T00:32:05.497Z,1554856325.497 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2111
2019-04-10T00:32:05.505Z,1554856325.505 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2112
2019-04-10T00:32:05.506Z,1554856325.506 [CTD_NeilBrown](INFO): Powering down
2019-04-10T00:32:05.509Z,1554856325.509 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-10T00:32:05.509Z,1554856325.509 [CBIT](DEBUG): Initializing heartbeat.
2019-04-10T00:32:05.537Z,1554856325.537 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 2113
2019-04-10T00:32:05.538Z,1554856325.538 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-10T00:32:05.565Z,1554856325.565 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2114
2019-04-10T00:32:05.568Z,1554856325.568 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-10T00:32:05.568Z,1554856325.568 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-10T00:32:05.568Z,1554856325.568 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-10T00:32:05.569Z,1554856325.569 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-10T00:32:05.569Z,1554856325.569 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-10T00:32:05.569Z,1554856325.569 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-10T00:32:05.569Z,1554856325.569 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-10T00:32:05.569Z,1554856325.569 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-10T00:32:05.570Z,1554856325.570 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-10T00:32:05.570Z,1554856325.570 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-10T00:32:05.570Z,1554856325.570 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-10T00:32:05.570Z,1554856325.570 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-10T00:32:05.570Z,1554856325.570 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-10T00:32:05.570Z,1554856325.570 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-10T00:32:05.571Z,1554856325.571 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-10T00:32:05.571Z,1554856325.571 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-10T00:32:05.581Z,1554856325.581 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-10T00:32:05.581Z,1554856325.581 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-10T00:32:05.617Z,1554856325.617 [CBIT](DEBUG): Backplane powered.
2019-04-10T00:32:05.617Z,1554856325.617 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-10T00:32:05.619Z,1554856325.619 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-10T00:32:05.619Z,1554856325.619 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-10T00:32:05.620Z,1554856325.620 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-10T00:32:05.621Z,1554856325.621 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-10T00:32:05.631Z,1554856325.631 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-10T00:32:05.658Z,1554856325.658 [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-04-10T00:32:05.659Z,1554856325.659 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-10T00:32:05.722Z,1554856325.722 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-10T00:32:05.723Z,1554856325.723 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-10T00:32:05.741Z,1554856325.741 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-10T00:32:05.768Z,1554856325.768 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-10T00:32:05.770Z,1554856325.770 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-10T00:32:05.796Z,1554856325.796 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-10T00:32:05.799Z,1554856325.799 [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-04-10T00:32:05.807Z,1554856325.807 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-04-10T00:32:05.821Z,1554856325.821 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-10T00:32:05.877Z,1554856325.877 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-10T00:32:05.878Z,1554856325.878 [DUSBL_Hydroid](INFO): Powering up
2019-04-10T00:32:05.879Z,1554856325.879 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-10T00:32:05.901Z,1554856325.901 [Radio_Surface](INFO): Powering up
2019-04-10T00:32:05.953Z,1554856325.953 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-10T00:32:05.970Z,1554856325.970 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-10T00:32:05.977Z,1554856325.977 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-10T00:32:05.978Z,1554856325.978 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-10T00:32:05.985Z,1554856325.985 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-10T00:32:05.986Z,1554856325.986 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-10T00:32:05.993Z,1554856325.993 [MassServo](DEBUG): Initializing MassServo.
2019-04-10T00:32:05.994Z,1554856325.994 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-10T00:32:06.001Z,1554856326.001 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-10T00:32:06.002Z,1554856326.002 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-10T00:32:06.009Z,1554856326.009 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-10T00:32:06.235Z,1554856326.235 [Micromodem](INFO): Powering up
2019-04-10T00:32:06.235Z,1554856326.235 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-10T00:32:06.269Z,1554856326.269 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-10T00:32:06.949Z,1554856326.949 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-10T00:32:06.949Z,1554856326.949 [RudderServo](FAULT): Rudder failed to initialize
2019-04-10T00:32:06.949Z,1554856326.949 [RudderServo] Communications Fault, FailCount= 1
2019-04-10T00:32:06.949Z,1554856326.949 [RudderServo](ERROR): Communications Fault
2019-04-10T00:32:07.061Z,1554856327.061 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-10T00:32:07.230Z,1554856327.230 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-10T00:32:07.230Z,1554856327.230 [RudderServo](INFO): Powering down
2019-04-10T00:32:07.904Z,1554856327.904 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-10T00:32:08.026Z,1554856328.026 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-10T00:32:08.030Z,1554856328.030 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-10T00:32:08.030Z,1554856328.030 [RudderServo] No Fault, FailCount= 1
2019-04-10T00:32:19.249Z,1554856339.249 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-10T00:32:21.283Z,1554856341.283 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-04-10T00:32:24.075Z,1554856344.075 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-10T00:32:31.747Z,1554856351.747 [NAL9602](INFO): Powering up NAL9602
2019-04-10T00:32:42.655Z,1554856362.655 [NAL9602](INFO): NAL9602 initialized
2019-04-10T00:32:43.477Z,1554856363.477 [NAL9602](DEBUG): Fix Requested
2019-04-10T00:32:49.983Z,1554856369.983 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-10T00:32:49.991Z,1554856369.991 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-10T00:33:01.026Z,1554856381.026 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.011854
CHAN A1 (24V): -0.026075
CHAN A2 (12V): -0.006783
CHAN A3 (5V): -0.002413
CHAN B0 (3.3V): -0.000162
CHAN B1 (3.15aV): -0.000107
CHAN B2 (3.15bV): 0.000208
CHAN B3 (GND): 0.001816
OPEN: 0.006238
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-10T00:33:11.618Z,1554856391.618 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:33:18.468Z,1554856398.468 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-04-10T00:33:21.691Z,1554856401.691 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:33:31.798Z,1554856411.798 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:33:41.989Z,1554856421.989 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:33:43.233Z,1554856423.233 [SBIT](IMPORTANT): SBIT PASSED
2019-04-10T00:33:43.266Z,1554856423.266 [CommandLine](IMPORTANT): got command configSet list
2019-04-10T00:33:43.267Z,1554856423.267 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-10T00:33:43.267Z,1554856423.267 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-04-10T00:33:43.268Z,1554856423.268 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-04-10T00:33:43.268Z,1554856423.268 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-04-10T00:33:43.268Z,1554856423.268 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-04-10T00:33:43.268Z,1554856423.268 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-04-10T00:33:43.268Z,1554856423.268 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-04-10T00:33:43.268Z,1554856423.268 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-04-10T00:33:43.268Z,1554856423.268 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-04-10T00:33:43.269Z,1554856423.269 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-04-10T00:33:43.269Z,1554856423.269 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-04-10T00:33:43.269Z,1554856423.269 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-04-10T00:33:43.611Z,1554856423.611 [MissionManager](IMPORTANT): Started mission Startup
2019-04-10T00:33:43.611Z,1554856423.611 [Startup] Running Loop=1
2019-04-10T00:33:43.611Z,1554856423.611 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-10T00:33:43.611Z,1554856423.611 [Startup:A.GoToSurface] Running Loop=1
2019-04-10T00:33:43.611Z,1554856423.611 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-10T00:33:43.612Z,1554856423.612 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-10T00:33:43.613Z,1554856423.613 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-10T00:33:43.613Z,1554856423.613 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-10T00:33:43.614Z,1554856423.614 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-10T00:33:43.614Z,1554856423.614 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-10T00:33:43.616Z,1554856423.616 [Startup:StartupSatComms] Running Loop=1
2019-04-10T00:33:43.616Z,1554856423.616 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-10T00:33:43.616Z,1554856423.616 [Startup:StartupSatComms:A] Running Loop=1
2019-04-10T00:33:44.041Z,1554856424.041 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-10T00:33:51.677Z,1554856431.677 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:34:01.380Z,1554856441.380 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:34:11.462Z,1554856451.462 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:34:21.580Z,1554856461.580 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:34:31.667Z,1554856471.667 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:34:31.811Z,1554856471.811 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005003
2019-04-10T00:34:41.767Z,1554856481.767 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:34:43.810Z,1554856483.810 [Startup:StartupSatComms:A](INFO): Timed out from 2019-04-10T00:33:43.6Z
2019-04-10T00:34:43.810Z,1554856483.810 [Startup:StartupSatComms:A] Stopped
2019-04-10T00:34:43.810Z,1554856483.810 [Startup:StartupSatComms:B] Running Loop=1
2019-04-10T00:34:44.211Z,1554856484.211 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-10T00:34:48.964Z,1554856488.964 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190410T001348/Courier0016.lzma
2019-04-10T00:34:49.775Z,1554856489.775 [DataOverHttps](INFO): Moved sent file to Logs/20190410T001348/Courier0016.lzma.bak
2019-04-10T00:34:49.775Z,1554856489.775 [DataOverHttps](INFO): SBD MOMSN=10522100
2019-04-10T00:34:51.459Z,1554856491.459 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:35:00.790Z,1554856500.790 [DataOverHttps](INFO): Sending 507 bytes from file Logs/20190410T001348/Express0017.lzma
2019-04-10T00:35:01.562Z,1554856501.562 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:35:01.590Z,1554856501.590 [DataOverHttps](INFO): Moved sent file to Logs/20190410T001348/Express0017.lzma.bak
2019-04-10T00:35:01.591Z,1554856501.591 [DataOverHttps](INFO): SBD MOMSN=10522102
2019-04-10T00:35:05.605Z,1554856505.605 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-04-10T00:35:05.605Z,1554856505.605 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-04-10T00:35:05.619Z,1554856505.619 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-04-10T00:35:06.018Z,1554856506.018 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-04-10T00:35:06.018Z,1554856506.018 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-04-10T00:35:12.710Z,1554856512.710 [DataOverHttps](INFO): Sending 1404 bytes from file Logs/20190410T003154/Express0001.lzma
2019-04-10T00:35:13.514Z,1554856513.514 [DataOverHttps](INFO): Moved sent file to Logs/20190410T003154/Express0001.lzma.bak
2019-04-10T00:35:13.514Z,1554856513.514 [DataOverHttps](INFO): SBD MOMSN=10522105
2019-04-10T00:35:14.914Z,1554856514.914 [Startup:StartupSatComms:B] Stopped
2019-04-10T00:35:14.914Z,1554856514.914 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-10T00:35:14.914Z,1554856514.914 [Startup:StartupSatComms] Stopped
2019-04-10T00:35:14.914Z,1554856514.914 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-10T00:35:14.915Z,1554856514.915 [Startup](INFO): Completed Startup
2019-04-10T00:35:14.915Z,1554856514.915 [MissionManager](INFO): Startup is completed.
2019-04-10T00:35:14.915Z,1554856514.915 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-10T00:35:14.915Z,1554856514.915 [Startup] Stopped
2019-04-10T00:35:14.915Z,1554856514.915 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-10T00:35:14.915Z,1554856514.915 [Startup:A.GoToSurface] Stopped
2019-04-10T00:35:14.915Z,1554856514.915 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-10T00:35:15.329Z,1554856515.329 [MissionManager](IMPORTANT): Started mission Default
2019-04-10T00:35:15.330Z,1554856515.330 [Default] Running Loop=1
2019-04-10T00:35:15.330Z,1554856515.330 [Default](DEBUG): Aggregate::initialize Default
2019-04-10T00:35:15.330Z,1554856515.330 [Default:B.GoToSurface] Running Loop=1
2019-04-10T00:35:15.330Z,1554856515.330 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-10T00:35:15.330Z,1554856515.330 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-10T00:35:15.331Z,1554856515.331 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-10T00:35:15.331Z,1554856515.331 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-10T00:35:15.331Z,1554856515.331 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-10T00:35:15.332Z,1554856515.332 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-10T00:35:15.332Z,1554856515.332 [Default:A.Wait] Running Loop=1
2019-04-10T00:35:15.332Z,1554856515.332 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:35:28.647Z,1554856528.647 [Default:A.Wait](INFO): Done Waiting.
2019-04-10T00:35:28.647Z,1554856528.647 [Default:A.Wait] Stopped
2019-04-10T00:35:28.647Z,1554856528.647 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:35:29.079Z,1554856529.079 [Default:CheckIn] Running Loop=1
2019-04-10T00:35:29.079Z,1554856529.079 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-10T00:35:29.079Z,1554856529.079 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-10T00:35:29.450Z,1554856529.450 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-10T00:37:18.508Z,1554856638.508 [NAL9602](INFO): SBD MO Status=2, MOMSN=3162, MT Status=2, MTMSN=0
2019-04-10T00:37:18.508Z,1554856638.508 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-10T00:37:33.054Z,1554856653.054 [NAL9602](INFO): SBD MO Status=2, MOMSN=3162, MT Status=2, MTMSN=0
2019-04-10T00:37:33.054Z,1554856653.054 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-10T00:37:36.305Z,1554856656.305 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:37:46.409Z,1554856666.409 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:37:56.499Z,1554856676.499 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:38:02.944Z,1554856682.944 [NAL9602](INFO): SBD MO Status=2, MOMSN=3162, MT Status=2, MTMSN=0
2019-04-10T00:38:02.945Z,1554856682.945 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-10T00:38:03.346Z,1554856683.346 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-10T00:38:04.177Z,1554856684.177 [NAL9602](DEBUG): Fix Requested
2019-04-10T00:38:04.561Z,1554856684.561 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,003709.00,A,3648.16630,N,12147.28400,W,0.428,188.93,100419,,,A*7D
2019-04-10T00:38:04.564Z,1554856684.564 [NAL9602](INFO): GPS fix at 20190410T003709: (36.802772, -121.788067)
2019-04-10T00:38:04.600Z,1554856684.600 [Default:CheckIn:Read_GPS] Stopped
2019-04-10T00:38:04.600Z,1554856684.600 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-10T00:38:05.027Z,1554856685.027 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-10T00:38:06.699Z,1554856686.699 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:38:12.657Z,1554856692.657 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20190410T003154/Courier0004.lzma
2019-04-10T00:38:13.462Z,1554856693.462 [DataOverHttps](INFO): Moved sent file to Logs/20190410T003154/Courier0004.lzma.bak
2019-04-10T00:38:13.462Z,1554856693.462 [DataOverHttps](INFO): SBD MOMSN=10522146
2019-04-10T00:38:16.798Z,1554856696.798 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:38:26.898Z,1554856706.898 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:38:27.382Z,1554856707.382 [DataOverHttps](INFO): Sending 787 bytes from file Logs/20190410T003154/Express0005.lzma
2019-04-10T00:38:28.170Z,1554856708.170 [DataOverHttps](INFO): Moved sent file to Logs/20190410T003154/Express0005.lzma.bak
2019-04-10T00:38:28.170Z,1554856708.170 [DataOverHttps](INFO): SBD MOMSN=10522149
2019-04-10T00:38:28.936Z,1554856708.936 [Default:CheckIn:Read_Iridium] Stopped
2019-04-10T00:38:28.936Z,1554856708.936 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-10T00:38:28.936Z,1554856708.936 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:38:36.583Z,1554856716.583 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-10T00:38:36.998Z,1554856716.998 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:38:46.730Z,1554856726.730 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:38:56.424Z,1554856736.424 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:39:06.504Z,1554856746.504 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:39:16.193Z,1554856756.193 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:39:25.478Z,1554856765.478 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:39:35.581Z,1554856775.581 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:39:45.679Z,1554856785.679 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:39:55.780Z,1554856795.780 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:41:09.721Z,1554856869.721 [BPC1](ERROR): BPC1A: No match for serial number FFFF in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-04-10T00:42:06.311Z,1554856926.311 [RDI_Pathfinder](ERROR): Failed to parse:
:B,-32768,-32768,V
2019-04-10T00:42:24.326Z,1554856944.326 [CommandLine](IMPORTANT): got command show stack
2019-04-10T00:42:24.327Z,1554856944.327 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-10T00:42:24.327Z,1554856944.327 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-04-10T00:42:24.327Z,1554856944.327 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-04-10T00:42:26.886Z,1554856946.886 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:42:30.786Z,1554856950.786 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:42:30.787Z,1554856950.787 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:42:30.816Z,1554856950.816 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-10T00:42:30.819Z,1554856950.819 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-10T00:42:30.823Z,1554856950.823 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-10T00:42:30.827Z,1554856950.827 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-10T00:42:30.830Z,1554856950.830 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-10T00:42:30.831Z,1554856950.831 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-10T00:42:30.837Z,1554856950.837 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-10T00:42:30.846Z,1554856950.846 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-10T00:42:30.851Z,1554856950.851 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

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

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-04-10T00:42:30.853Z,1554856950.853 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:42:30.931Z,1554856950.931 [Default] Stopped
2019-04-10T00:42:30.932Z,1554856950.932 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-10T00:42:30.932Z,1554856950.932 [Default:B.GoToSurface] Stopped
2019-04-10T00:42:30.932Z,1554856950.932 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-10T00:42:30.932Z,1554856950.932 [Default:CheckIn] Stopped
2019-04-10T00:42:30.932Z,1554856950.932 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-10T00:42:30.932Z,1554856950.932 [Default:CheckIn:C.Wait] Stopped
2019-04-10T00:42:30.932Z,1554856950.932 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:42:30.932Z,1554856950.932 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-10T00:42:30.933Z,1554856950.933 [DUSBL] Running Loop=1
2019-04-10T00:42:30.933Z,1554856950.933 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-10T00:42:30.933Z,1554856950.933 [DUSBL:A.Pitch] Running Loop=1
2019-04-10T00:42:30.933Z,1554856950.933 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-10T00:42:30.933Z,1554856950.933 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-10T00:42:30.933Z,1554856950.933 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-10T00:42:30.933Z,1554856950.933 [DUSBL:C] Running Loop=1
2019-04-10T00:42:30.934Z,1554856950.934 [DUSBL:RequestRepeater] Running Loop=1
2019-04-10T00:42:30.934Z,1554856950.934 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:42:30.934Z,1554856950.934 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:42:30.934Z,1554856950.934 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:42:30.934Z,1554856950.934 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:42:30.934Z,1554856950.934 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:42:30.934Z,1554856950.934 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:42:30.935Z,1554856950.935 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:42:30.936Z,1554856950.936 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-10T00:42:30.936Z,1554856950.936 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-10T00:42:30.953Z,1554856950.953 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-10T00:42:30.953Z,1554856950.953 [DUSBL:A.Pitch] Running Loop=1
2019-04-10T00:42:32.523Z,1554856952.523 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:36.562Z,1554856956.562 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:42:36.562Z,1554856956.562 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:36.967Z,1554856956.967 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:42:36.969Z,1554856956.969 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:42:36.970Z,1554856956.970 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:37.002Z,1554856957.002 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:42:41.024Z,1554856961.024 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:42:41.026Z,1554856961.026 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:41.132Z,1554856961.132 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:42:41.132Z,1554856961.132 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:42:41.137Z,1554856961.137 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:42:41.137Z,1554856961.137 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:42:41.137Z,1554856961.137 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater] Running Loop=2
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:42:41.138Z,1554856961.138 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:42:41.411Z,1554856961.411 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:42:41.412Z,1554856961.412 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:42:41.413Z,1554856961.413 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:42.223Z,1554856962.223 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CATRC,RECV,IDEM, 523,Missed start of FSK packet

2019-04-10T00:42:45.450Z,1554856965.450 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:42:45.450Z,1554856965.450 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:45.859Z,1554856965.859 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:42:45.860Z,1554856965.860 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:42:45.861Z,1554856965.861 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:46.701Z,1554856966.701 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:42:49.910Z,1554856969.910 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:42:49.913Z,1554856969.913 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:50.299Z,1554856970.299 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:42:50.300Z,1554856970.300 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:42:50.301Z,1554856970.301 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:51.544Z,1554856971.544 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:42:51.544Z,1554856971.544 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:42:51.544Z,1554856971.544 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater] Running Loop=3
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:42:51.545Z,1554856971.545 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:42:51.546Z,1554856971.546 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:42:51.546Z,1554856971.546 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:42:54.335Z,1554856974.335 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:42:54.337Z,1554856974.337 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:54.741Z,1554856974.741 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:42:54.742Z,1554856974.742 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:42:54.743Z,1554856974.743 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:56.416Z,1554856976.416 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:42:58.782Z,1554856978.782 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:42:58.783Z,1554856978.783 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:42:59.191Z,1554856979.191 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:42:59.192Z,1554856979.192 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:42:59.209Z,1554856979.209 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:02.074Z,1554856982.074 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:43:02.074Z,1554856982.074 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:43:02.074Z,1554856982.074 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:43:02.074Z,1554856982.074 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:43:02.074Z,1554856982.074 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater] Running Loop=4
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:43:02.075Z,1554856982.075 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:43:03.226Z,1554856983.226 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:43:03.227Z,1554856983.227 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:03.635Z,1554856983.635 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:43:03.636Z,1554856983.636 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:43:03.637Z,1554856983.637 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:06.484Z,1554856986.484 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:43:07.674Z,1554856987.674 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:43:07.675Z,1554856987.675 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:08.079Z,1554856988.079 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:43:08.080Z,1554856988.080 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:43:08.081Z,1554856988.081 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:12.117Z,1554856992.117 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:43:12.119Z,1554856992.119 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:12.519Z,1554856992.519 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:43:12.520Z,1554856992.520 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:43:12.541Z,1554856992.541 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:12.559Z,1554856992.559 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190410004311.068756,06,100,13,0096,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,202,-0.10,-999,9760,4000*71

2019-04-10T00:43:12.600Z,1554856992.600 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:43:12.600Z,1554856992.600 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:43:12.600Z,1554856992.600 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:43:12.605Z,1554856992.605 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:43:12.605Z,1554856992.605 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:43:12.605Z,1554856992.605 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:43:12.605Z,1554856992.605 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:43:12.605Z,1554856992.605 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:43:12.606Z,1554856992.606 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-10T00:43:12.606Z,1554856992.606 [DUSBL:RequestRepeater] Running Loop=5
2019-04-10T00:43:12.606Z,1554856992.606 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:43:12.606Z,1554856992.606 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:43:12.606Z,1554856992.606 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:43:12.606Z,1554856992.606 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:43:12.606Z,1554856992.606 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:43:13.731Z,1554856993.731 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CATRC,RECV,IDEM, 523,Missed start of FSK packet

2019-04-10T00:43:16.182Z,1554856996.182 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:43:16.558Z,1554856996.558 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:43:16.559Z,1554856996.559 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:16.967Z,1554856996.967 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:43:16.968Z,1554856996.968 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:43:16.969Z,1554856996.969 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:21.002Z,1554857001.002 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:43:21.003Z,1554857001.003 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:21.411Z,1554857001.411 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:43:21.412Z,1554857001.412 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:43:21.413Z,1554857001.413 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:23.094Z,1554857003.094 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:43:23.094Z,1554857003.094 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:43:23.094Z,1554857003.094 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater] Running Loop=6
2019-04-10T00:43:23.095Z,1554857003.095 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:43:23.096Z,1554857003.096 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:43:23.096Z,1554857003.096 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:43:23.096Z,1554857003.096 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:43:23.096Z,1554857003.096 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:43:25.464Z,1554857005.464 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:43:25.467Z,1554857005.467 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:25.626Z,1554857005.626 [CommandLine](IMPORTANT): got command stop
2019-04-10T00:43:25.626Z,1554857005.626 [CommandLine](IMPORTANT): Scheduling is paused
2019-04-10T00:43:25.627Z,1554857005.627 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-10T00:43:25.855Z,1554857005.855 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:43:25.856Z,1554857005.856 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:43:25.857Z,1554857005.857 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:43:25.883Z,1554857005.883 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:43:25.896Z,1554857005.896 [MissionManager](INFO): MissionManager is completed.
2019-04-10T00:43:25.897Z,1554857005.897 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL] Stopped
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL:A.Pitch] Stopped
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL:B.SetSpeed] Stopped
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL:C] Stopped
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:43:25.897Z,1554857005.897 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:43:25.898Z,1554857005.898 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:43:25.898Z,1554857005.898 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:43:25.898Z,1554857005.898 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:43:26.316Z,1554857006.316 [MissionManager](IMPORTANT): Started mission Default
2019-04-10T00:43:26.316Z,1554857006.316 [Default] Running Loop=1
2019-04-10T00:43:26.317Z,1554857006.317 [Default](DEBUG): Aggregate::initialize Default
2019-04-10T00:43:26.317Z,1554857006.317 [Default:B.GoToSurface] Running Loop=1
2019-04-10T00:43:26.317Z,1554857006.317 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-10T00:43:26.317Z,1554857006.317 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-10T00:43:26.317Z,1554857006.317 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-10T00:43:26.318Z,1554857006.318 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-10T00:43:26.318Z,1554857006.318 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-10T00:43:26.318Z,1554857006.318 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-10T00:43:26.319Z,1554857006.319 [Default:A.Wait] Running Loop=1
2019-04-10T00:43:26.319Z,1554857006.319 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:43:35.981Z,1554857015.981 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:43:39.615Z,1554857019.615 [Default:A.Wait](INFO): Done Waiting.
2019-04-10T00:43:39.615Z,1554857019.615 [Default:A.Wait] Stopped
2019-04-10T00:43:39.615Z,1554857019.615 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:43:40.022Z,1554857020.022 [Default:CheckIn] Running Loop=1
2019-04-10T00:43:40.022Z,1554857020.022 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-10T00:43:40.022Z,1554857020.022 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-10T00:43:41.625Z,1554857021.625 [NAL9602](DEBUG): Fix Requested
2019-04-10T00:43:42.020Z,1554857022.020 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004248.00,A,3648.16312,N,12147.28351,W,0.505,14.17,100419,,,A*4A
2019-04-10T00:43:42.023Z,1554857022.023 [NAL9602](INFO): GPS fix at 20190410T004248: (36.802719, -121.788059)
2019-04-10T00:43:42.159Z,1554857022.159 [Default:CheckIn:Read_GPS] Stopped
2019-04-10T00:43:42.159Z,1554857022.159 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-10T00:43:45.795Z,1554857025.795 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:43:47.736Z,1554857027.736 [DataOverHttps](INFO): Sending 60 bytes from file Logs/20190410T003154/Courier0007.lzma
2019-04-10T00:43:48.542Z,1554857028.542 [DataOverHttps](INFO): Moved sent file to Logs/20190410T003154/Courier0007.lzma.bak
2019-04-10T00:43:48.542Z,1554857028.542 [DataOverHttps](INFO): SBD MOMSN=10522159
2019-04-10T00:43:52.271Z,1554857032.271 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-10T00:43:52.272Z,1554857032.272 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-327680
2019-04-10T00:43:55.519Z,1554857035.519 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:44:00.706Z,1554857040.706 [DataOverHttps](INFO): Sending 1197 bytes from file Logs/20190410T003154/Express0008.lzma
2019-04-10T00:44:01.510Z,1554857041.510 [DataOverHttps](INFO): Moved sent file to Logs/20190410T003154/Express0008.lzma.bak
2019-04-10T00:44:01.510Z,1554857041.510 [DataOverHttps](INFO): SBD MOMSN=10522162
2019-04-10T00:44:02.402Z,1554857042.402 [Default:CheckIn:Read_Iridium] Stopped
2019-04-10T00:44:02.402Z,1554857042.402 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-10T00:44:02.402Z,1554857042.402 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:44:05.214Z,1554857045.214 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:44:13.793Z,1554857053.793 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:44:13.794Z,1554857053.794 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:44:13.824Z,1554857053.824 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-10T00:44:13.827Z,1554857053.827 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-10T00:44:13.829Z,1554857053.829 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-10T00:44:13.831Z,1554857053.831 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-10T00:44:13.833Z,1554857053.833 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-10T00:44:13.834Z,1554857053.834 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-10T00:44:13.839Z,1554857053.839 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-10T00:44:13.879Z,1554857053.879 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-10T00:44:13.888Z,1554857053.888 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

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

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-04-10T00:44:13.894Z,1554857053.894 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:44:14.169Z,1554857054.169 [Default] Stopped
2019-04-10T00:44:14.169Z,1554857054.169 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-10T00:44:14.169Z,1554857054.169 [Default:B.GoToSurface] Stopped
2019-04-10T00:44:14.169Z,1554857054.169 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-10T00:44:14.169Z,1554857054.169 [Default:CheckIn] Stopped
2019-04-10T00:44:14.169Z,1554857054.169 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-10T00:44:14.169Z,1554857054.169 [Default:CheckIn:C.Wait] Stopped
2019-04-10T00:44:14.169Z,1554857054.169 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:44:14.170Z,1554857054.170 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-10T00:44:14.170Z,1554857054.170 [DUSBL] Running Loop=1
2019-04-10T00:44:14.170Z,1554857054.170 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-10T00:44:14.170Z,1554857054.170 [DUSBL:A.Pitch] Running Loop=1
2019-04-10T00:44:14.170Z,1554857054.170 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-10T00:44:14.170Z,1554857054.170 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-10T00:44:14.170Z,1554857054.170 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-10T00:44:14.171Z,1554857054.171 [DUSBL:C] Running Loop=1
2019-04-10T00:44:14.171Z,1554857054.171 [DUSBL:RequestRepeater] Running Loop=1
2019-04-10T00:44:14.171Z,1554857054.171 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:44:14.171Z,1554857054.171 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:44:14.171Z,1554857054.171 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:44:14.171Z,1554857054.171 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:44:14.171Z,1554857054.171 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:44:14.172Z,1554857054.172 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:44:14.172Z,1554857054.172 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:44:14.177Z,1554857054.177 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-10T00:44:14.177Z,1554857054.177 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-10T00:44:14.178Z,1554857054.178 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-10T00:44:14.178Z,1554857054.178 [DUSBL:A.Pitch] Running Loop=1
2019-04-10T00:44:14.885Z,1554857054.885 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:44:15.678Z,1554857055.678 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:15.679Z,1554857055.679 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:16.082Z,1554857056.082 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-10T00:44:16.082Z,1554857056.082 [DUSBL_Hydroid](INFO): NOT WAITING. NO RANGE
2019-04-10T00:44:16.083Z,1554857056.083 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:20.126Z,1554857060.126 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:20.127Z,1554857060.127 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:20.523Z,1554857060.523 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:20.524Z,1554857060.524 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:20.525Z,1554857060.525 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:24.247Z,1554857064.247 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:44:24.247Z,1554857064.247 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:44:24.247Z,1554857064.247 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:44:24.248Z,1554857064.248 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:44:24.248Z,1554857064.248 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:44:24.248Z,1554857064.248 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:44:24.248Z,1554857064.248 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:44:24.248Z,1554857064.248 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:44:24.249Z,1554857064.249 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-10T00:44:24.249Z,1554857064.249 [DUSBL:RequestRepeater] Running Loop=2
2019-04-10T00:44:24.249Z,1554857064.249 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:44:24.249Z,1554857064.249 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:44:24.249Z,1554857064.249 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:44:24.249Z,1554857064.249 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:44:24.249Z,1554857064.249 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:44:24.562Z,1554857064.562 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:24.563Z,1554857064.563 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:24.607Z,1554857064.607 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:44:24.979Z,1554857064.979 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:24.983Z,1554857064.983 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:24.986Z,1554857064.986 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:29.012Z,1554857069.012 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:29.015Z,1554857069.015 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:29.415Z,1554857069.415 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:29.416Z,1554857069.416 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:29.417Z,1554857069.417 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:33.454Z,1554857073.454 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:33.455Z,1554857073.455 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:33.859Z,1554857073.859 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:33.860Z,1554857073.860 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:33.861Z,1554857073.861 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:34.284Z,1554857074.284 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:44:34.722Z,1554857074.722 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:44:34.722Z,1554857074.722 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:44:34.723Z,1554857074.723 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:44:34.723Z,1554857074.723 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:44:34.723Z,1554857074.723 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater] Running Loop=3
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:44:34.724Z,1554857074.724 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:44:37.894Z,1554857077.894 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:37.895Z,1554857077.895 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:38.303Z,1554857078.303 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:38.304Z,1554857078.304 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:38.305Z,1554857078.305 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:42.342Z,1554857082.342 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:42.343Z,1554857082.343 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:42.743Z,1554857082.743 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:42.744Z,1554857082.744 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:42.745Z,1554857082.745 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:44.384Z,1554857084.384 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-10T00:44:45.269Z,1554857085.269 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:44:45.269Z,1554857085.269 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:44:45.269Z,1554857085.269 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater] Running Loop=4
2019-04-10T00:44:45.270Z,1554857085.270 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:44:45.271Z,1554857085.271 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:44:45.271Z,1554857085.271 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:44:45.271Z,1554857085.271 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:44:45.271Z,1554857085.271 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:44:46.782Z,1554857086.782 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:46.782Z,1554857086.782 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:47.187Z,1554857087.187 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:47.188Z,1554857087.188 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:47.188Z,1554857087.188 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:51.230Z,1554857091.230 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:51.231Z,1554857091.231 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:51.635Z,1554857091.635 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:51.636Z,1554857091.636 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:51.637Z,1554857091.637 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:51.648Z,1554857091.648 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190410004450.238149,06,356,13,0094,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,201,0.05,-999,9760,4000*56

2019-04-10T00:44:55.674Z,1554857095.674 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:44:55.675Z,1554857095.675 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:44:55.731Z,1554857095.731 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:44:55.732Z,1554857095.732 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:44:55.732Z,1554857095.732 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:44:55.749Z,1554857095.749 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:44:55.749Z,1554857095.749 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:44:55.749Z,1554857095.749 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:44:55.749Z,1554857095.749 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:44:55.749Z,1554857095.749 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:44:55.750Z,1554857095.750 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-10T00:44:55.750Z,1554857095.750 [DUSBL:RequestRepeater] Running Loop=5
2019-04-10T00:44:55.750Z,1554857095.750 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:44:55.750Z,1554857095.750 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:44:55.750Z,1554857095.750 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:44:55.750Z,1554857095.750 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:44:55.750Z,1554857095.750 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:44:56.078Z,1554857096.078 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:44:56.079Z,1554857096.079 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:44:56.080Z,1554857096.080 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:00.118Z,1554857100.118 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:00.119Z,1554857100.119 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:00.533Z,1554857100.533 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:45:00.537Z,1554857100.537 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:45:00.538Z,1554857100.538 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:04.558Z,1554857104.558 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:04.559Z,1554857104.559 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:04.966Z,1554857104.966 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,0,188,80,81,08,FF
2019-04-10T00:45:04.966Z,1554857104.966 [DUSBL_Hydroid] Communications Fault, FailCount= 1
2019-04-10T00:45:04.966Z,1554857104.966 [DUSBL_Hydroid](ERROR): Communications Fault
2019-04-10T00:45:05.025Z,1554857105.025 [CBIT](ERROR): Communications Fault in component: DUSBL_Hydroid
2019-04-10T00:45:05.366Z,1554857105.366 [DUSBL_Hydroid](INFO): Powering down
2019-04-10T00:45:06.235Z,1554857106.235 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:45:06.235Z,1554857106.235 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:45:06.235Z,1554857106.235 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:45:06.236Z,1554857106.236 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:45:06.236Z,1554857106.236 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:45:06.236Z,1554857106.236 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:45:06.236Z,1554857106.236 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:45:06.236Z,1554857106.236 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:45:06.237Z,1554857106.237 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-10T00:45:06.237Z,1554857106.237 [DUSBL:RequestRepeater] Running Loop=6
2019-04-10T00:45:06.237Z,1554857106.237 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:45:06.237Z,1554857106.237 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:45:06.237Z,1554857106.237 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:45:06.237Z,1554857106.237 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:45:06.237Z,1554857106.237 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:45:06.249Z,1554857106.249 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-04-10T00:45:06.249Z,1554857106.249 [DUSBL_Hydroid] No Fault, FailCount= 1
2019-04-10T00:45:08.602Z,1554857108.602 [DUSBL_Hydroid](INFO): Powering up
2019-04-10T00:45:08.602Z,1554857108.602 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-10T00:45:10.235Z,1554857110.235 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-04-10T00:45:16.720Z,1554857116.720 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:45:16.720Z,1554857116.720 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:45:16.720Z,1554857116.720 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:45:16.725Z,1554857116.725 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:45:16.725Z,1554857116.725 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater] Running Loop=7
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:45:16.726Z,1554857116.726 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:45:26.778Z,1554857126.778 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-10T00:45:27.186Z,1554857127.186 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:27.187Z,1554857127.187 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:27.286Z,1554857127.286 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:45:27.286Z,1554857127.286 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:45:27.286Z,1554857127.286 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:45:27.287Z,1554857127.287 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:45:27.287Z,1554857127.287 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:45:27.287Z,1554857127.287 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:45:27.287Z,1554857127.287 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:45:27.287Z,1554857127.287 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:45:27.288Z,1554857127.288 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-04-10T00:45:27.288Z,1554857127.288 [DUSBL:RequestRepeater] Running Loop=8
2019-04-10T00:45:27.288Z,1554857127.288 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:45:27.288Z,1554857127.288 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:45:27.288Z,1554857127.288 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:45:27.288Z,1554857127.288 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:45:27.288Z,1554857127.288 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:45:31.219Z,1554857131.219 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:31.221Z,1554857131.221 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:31.630Z,1554857131.630 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-10T00:45:31.630Z,1554857131.630 [DUSBL_Hydroid](INFO): NOT WAITING. NO RANGE
2019-04-10T00:45:31.631Z,1554857131.631 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:35.666Z,1554857135.666 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:35.667Z,1554857135.667 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:36.089Z,1554857136.089 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:45:36.090Z,1554857136.090 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:45:36.091Z,1554857136.091 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:37.748Z,1554857137.748 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:45:37.748Z,1554857137.748 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:45:37.748Z,1554857137.748 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:45:37.748Z,1554857137.748 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater] Running Loop=9
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:45:37.749Z,1554857137.749 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:45:37.750Z,1554857137.750 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:45:37.750Z,1554857137.750 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:45:40.110Z,1554857140.110 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:40.111Z,1554857140.111 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:40.519Z,1554857140.519 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:45:40.520Z,1554857140.520 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:45:40.521Z,1554857140.521 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:43.387Z,1554857143.387 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-04-10T00:45:44.558Z,1554857144.558 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:44.559Z,1554857144.559 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:44.963Z,1554857144.963 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:45:44.964Z,1554857144.964 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:45:44.965Z,1554857144.965 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:48.232Z,1554857148.232 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:45:48.232Z,1554857148.232 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:45:48.232Z,1554857148.232 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:45:48.233Z,1554857148.233 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:45:48.233Z,1554857148.233 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:45:48.233Z,1554857148.233 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:45:48.233Z,1554857148.233 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:45:48.233Z,1554857148.233 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:45:48.234Z,1554857148.234 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-04-10T00:45:48.234Z,1554857148.234 [DUSBL:RequestRepeater] Running Loop=10
2019-04-10T00:45:48.234Z,1554857148.234 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:45:48.234Z,1554857148.234 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:45:48.234Z,1554857148.234 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:45:48.234Z,1554857148.234 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:45:48.234Z,1554857148.234 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:45:48.000Z,1554857149.000 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:49.001Z,1554857149.001 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:49.403Z,1554857149.403 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:45:49.404Z,1554857149.404 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:45:49.405Z,1554857149.405 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:53.442Z,1554857153.442 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:53.443Z,1554857153.443 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:53.851Z,1554857153.851 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:45:53.852Z,1554857153.852 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:45:53.853Z,1554857153.853 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:57.886Z,1554857157.886 [DUSBL_Hydroid](INFO): NOT WAITING. Timed out
2019-04-10T00:45:57.886Z,1554857157.886 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:58.291Z,1554857158.291 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:45:58.292Z,1554857158.292 [DUSBL_Hydroid](INFO): NOT WAITING.
2019-04-10T00:45:58.292Z,1554857158.292 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:45:58.744Z,1554857158.744 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:45:58.744Z,1554857158.744 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:45:58.744Z,1554857158.744 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:45:58.753Z,1554857158.753 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:45:58.753Z,1554857158.753 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:45:58.753Z,1554857158.753 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:45:58.753Z,1554857158.753 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:45:58.753Z,1554857158.753 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:45:58.754Z,1554857158.754 [DUSBL](INFO): Completed DUSBL
2019-04-10T00:45:58.754Z,1554857158.754 [MissionManager](INFO): DUSBL is completed.
2019-04-10T00:45:58.754Z,1554857158.754 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-10T00:45:58.754Z,1554857158.754 [DUSBL] Stopped
2019-04-10T00:45:58.754Z,1554857158.754 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-10T00:45:58.755Z,1554857158.755 [DUSBL:A.Pitch] Stopped
2019-04-10T00:45:58.755Z,1554857158.755 [DUSBL:B.SetSpeed] Stopped
2019-04-10T00:45:58.755Z,1554857158.755 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-10T00:45:58.755Z,1554857158.755 [DUSBL:C] Stopped
2019-04-10T00:45:59.141Z,1554857159.141 [MissionManager](IMPORTANT): Started mission Default
2019-04-10T00:45:59.142Z,1554857159.142 [Default] Running Loop=1
2019-04-10T00:45:59.142Z,1554857159.142 [Default](DEBUG): Aggregate::initialize Default
2019-04-10T00:45:59.142Z,1554857159.142 [Default:B.GoToSurface] Running Loop=1
2019-04-10T00:45:59.142Z,1554857159.142 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-10T00:45:59.142Z,1554857159.142 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-10T00:45:59.143Z,1554857159.143 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-10T00:45:59.143Z,1554857159.143 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-10T00:45:59.143Z,1554857159.143 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-10T00:45:59.144Z,1554857159.144 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-10T00:45:59.144Z,1554857159.144 [Default:A.Wait] Running Loop=1
2019-04-10T00:45:59.144Z,1554857159.144 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:46:12.471Z,1554857172.471 [Default:A.Wait](INFO): Done Waiting.
2019-04-10T00:46:12.471Z,1554857172.471 [Default:A.Wait] Stopped
2019-04-10T00:46:12.471Z,1554857172.471 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:46:12.879Z,1554857172.879 [Default:CheckIn] Running Loop=1
2019-04-10T00:46:12.879Z,1554857172.879 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-10T00:46:12.879Z,1554857172.879 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-10T00:46:28.232Z,1554857188.232 [NAL9602](INFO): SBD MO Status=0, MOMSN=3162, MT Status=0, MTMSN=0
2019-04-10T00:46:28.232Z,1554857188.232 [NAL9602](INFO): No messages in MT queue
2019-04-10T00:46:29.029Z,1554857189.029 [NAL9602](DEBUG): Fix Requested
2019-04-10T00:46:29.424Z,1554857189.424 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004535.00,A,3648.17169,N,12147.28806,W,0.603,14.17,100419,,,A*44
2019-04-10T00:46:29.426Z,1554857189.426 [NAL9602](INFO): GPS fix at 20190410T004535: (36.802861, -121.788134)
2019-04-10T00:46:29.484Z,1554857189.484 [Default:CheckIn:Read_GPS] Stopped
2019-04-10T00:46:29.484Z,1554857189.484 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-10T00:46:38.676Z,1554857198.676 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190410T003154/Courier0010.lzma
2019-04-10T00:46:39.482Z,1554857199.482 [DataOverHttps](INFO): Moved sent file to Logs/20190410T003154/Courier0010.lzma.bak
2019-04-10T00:46:39.482Z,1554857199.482 [DataOverHttps](INFO): SBD MOMSN=10522213
2019-04-10T00:46:49.857Z,1554857209.857 [CommandLine](IMPORTANT): got command restart application
2019-04-10T00:46:50.861Z,1554857210.861 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-04-10T00:46:50.861Z,1554857210.861 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:50.861Z,1554857210.861 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.013Z,1554857211.013 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-04-10T00:46:51.013Z,1554857211.013 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.015Z,1554857211.015 [CommandLine](INFO): Join timeout helper Thread ID is 2155
2019-04-10T00:46:51.017Z,1554857211.017 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-04-10T00:46:51.017Z,1554857211.017 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.018Z,1554857211.018 [NavChartDb](INFO): Join timeout helper Thread ID is 2156
2019-04-10T00:46:51.221Z,1554857211.221 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:51.221Z,1554857211.221 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.229Z,1554857211.229 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-04-10T00:46:51.229Z,1554857211.229 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.229Z,1554857211.229 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 2157
2019-04-10T00:46:51.269Z,1554857211.269 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:51.269Z,1554857211.269 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-10T00:46:51.270Z,1554857211.270 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.277Z,1554857211.277 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-04-10T00:46:51.277Z,1554857211.277 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.277Z,1554857211.277 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2158
2019-04-10T00:46:51.365Z,1554857211.365 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:51.365Z,1554857211.365 [CTD_NeilBrown](INFO): Powering down
2019-04-10T00:46:51.377Z,1554857211.377 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.385Z,1554857211.385 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-04-10T00:46:51.385Z,1554857211.385 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.385Z,1554857211.385 [Radio_Surface](INFO): Join timeout helper Thread ID is 2159
2019-04-10T00:46:51.649Z,1554857211.649 [Radio_Surface](INFO): Powering down
2019-04-10T00:46:51.650Z,1554857211.650 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:51.650Z,1554857211.650 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.662Z,1554857211.662 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-04-10T00:46:51.662Z,1554857211.662 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:51.662Z,1554857211.662 [DataOverHttps](INFO): Join timeout helper Thread ID is 2160
2019-04-10T00:46:55.226Z,1554857215.226 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:55.229Z,1554857215.229 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.237Z,1554857215.237 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-04-10T00:46:55.238Z,1554857215.238 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.238Z,1554857215.238 [logger](INFO): Join timeout helper Thread ID is 2161
2019-04-10T00:46:55.317Z,1554857215.317 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:55.317Z,1554857215.317 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.350Z,1554857215.350 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-04-10T00:46:55.350Z,1554857215.350 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.350Z,1554857215.350 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-04-10T00:46:55.350Z,1554857215.350 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.350Z,1554857215.350 [controlThread](INFO): Join timeout helper Thread ID is 2162
2019-04-10T00:46:55.395Z,1554857215.395 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:46:55.395Z,1554857215.395 [controlThread](DEBUG): Uninitializing ControlThread
2019-04-10T00:46:55.395Z,1554857215.395 [AHRS_M2](INFO): Powering down
2019-04-10T00:46:55.465Z,1554857215.465 [DUSBL_Hydroid](INFO): Powering down
2019-04-10T00:46:55.537Z,1554857215.537 [Micromodem](INFO): Powering down
2019-04-10T00:46:55.633Z,1554857215.633 [NAL9602](INFO): Powering down
2019-04-10T00:46:55.705Z,1554857215.705 [RDI_Pathfinder](INFO): Powering down
2019-04-10T00:46:55.706Z,1554857215.706 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-04-10T00:46:55.707Z,1554857215.707 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-04-10T00:46:55.708Z,1554857215.708 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-04-10T00:46:55.708Z,1554857215.708 [MissionManager](INFO): Uninitializing Mission Default
2019-04-10T00:46:55.708Z,1554857215.708 [Default] Stopped
2019-04-10T00:46:55.709Z,1554857215.709 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-10T00:46:55.709Z,1554857215.709 [Default:B.GoToSurface] Stopped
2019-04-10T00:46:55.709Z,1554857215.709 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-10T00:46:55.709Z,1554857215.709 [Default:CheckIn] Stopped
2019-04-10T00:46:55.709Z,1554857215.709 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-10T00:46:55.709Z,1554857215.709 [Default:CheckIn:Read_Iridium] Stopped
2019-04-10T00:46:55.711Z,1554857215.711 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-04-10T00:46:55.712Z,1554857215.712 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-04-10T00:46:55.712Z,1554857215.712 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-04-10T00:46:55.712Z,1554857215.712 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-04-10T00:46:55.713Z,1554857215.713 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-04-10T00:46:55.713Z,1554857215.713 [BuoyancyServo](INFO): Powering down
2019-04-10T00:46:55.725Z,1554857215.725 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-04-10T00:46:55.725Z,1554857215.725 [ElevatorServo](INFO): Powering down
2019-04-10T00:46:55.726Z,1554857215.726 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-04-10T00:46:55.726Z,1554857215.726 [MassServo](INFO): Powering down
2019-04-10T00:46:55.727Z,1554857215.727 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-10T00:46:55.727Z,1554857215.727 [RudderServo](INFO): Powering down
2019-04-10T00:46:55.727Z,1554857215.727 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-04-10T00:46:55.727Z,1554857215.727 [ThrusterServo](INFO): Powering down
2019-04-10T00:46:55.728Z,1554857215.728 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-04-10T00:46:55.729Z,1554857215.729 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-04-10T00:46:55.729Z,1554857215.729 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-04-10T00:46:55.729Z,1554857215.729 [CBIT](DEBUG): Powering off loads.
2019-04-10T00:46:55.741Z,1554857215.741 [CBIT](DEBUG): Disabling WDT.
2019-04-10T00:46:55.752Z,1554857215.752 [CBIT](DEBUG): Opening all GF detection circuits.
2019-04-10T00:46:55.754Z,1554857215.754 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.812Z,1554857215.812 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.822Z,1554857215.822 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.866Z,1554857215.866 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.868Z,1554857215.868 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.922Z,1554857215.922 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:46:55.994Z,1554857215.994 [logger ThreadHandler](INFO): Thread cancelled.