2019-04-19T20:27:02.837Z,1555705622.837 [Supervisor](DEBUG): Initializing supervisor.
2019-04-19T20:27:02.839Z,1555705622.839 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-19T20:27:02.840Z,1555705622.840 [SyncHandler](INFO): Protected caller Thread ID is 5035
2019-04-19T20:27:02.840Z,1555705622.840 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-19T20:27:02.841Z,1555705622.841 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-19T20:27:02.842Z,1555705622.842 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5036
2019-04-19T20:27:02.844Z,1555705622.844 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-19T20:27:02.856Z,1555705622.856 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-19T20:27:02.857Z,1555705622.857 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-19T20:27:02.857Z,1555705622.857 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5037
2019-04-19T20:27:02.858Z,1555705622.858 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-19T20:27:02.859Z,1555705622.859 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-19T20:27:02.859Z,1555705622.859 [logger ThreadHandler](INFO): Protected caller Thread ID is 5038
2019-04-19T20:27:02.861Z,1555705622.861 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-19T20:27:02.862Z,1555705622.862 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-19T20:27:02.863Z,1555705622.863 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-19T20:27:03.356Z,1555705623.356 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-19T20:27:03.358Z,1555705623.358 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-19T20:27:03.458Z,1555705623.458 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-19T20:27:03.460Z,1555705623.460 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-19T20:27:03.789Z,1555705623.789 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-19T20:27:03.790Z,1555705623.790 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-19T20:27:03.940Z,1555705623.940 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-19T20:27:03.942Z,1555705623.942 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-19T20:27:04.142Z,1555705624.142 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-19T20:27:04.142Z,1555705624.142 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-19T20:27:04.619Z,1555705624.619 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-19T20:27:04.621Z,1555705624.621 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-19T20:27:04.835Z,1555705624.835 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-19T20:27:04.835Z,1555705624.835 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-19T20:27:04.983Z,1555705624.983 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-19T20:27:04.984Z,1555705624.984 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-19T20:27:05.181Z,1555705625.181 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-19T20:27:05.181Z,1555705625.181 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-19T20:27:05.279Z,1555705625.279 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-19T20:27:05.280Z,1555705625.280 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-19T20:27:05.607Z,1555705625.607 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-19T20:27:05.608Z,1555705625.608 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-19T20:27:05.690Z,1555705625.690 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-19T20:27:05.796Z,1555705625.796 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-19T20:27:05.796Z,1555705625.796 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-19T20:27:06.301Z,1555705626.301 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-19T20:27:06.302Z,1555705626.302 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-19T20:27:06.701Z,1555705626.701 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-19T20:27:06.703Z,1555705626.703 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-19T20:27:06.704Z,1555705626.704 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-19T20:27:06.916Z,1555705626.916 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-19T20:27:07.020Z,1555705627.020 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-19T20:27:07.121Z,1555705627.121 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-19T20:27:07.353Z,1555705627.353 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-19T20:27:07.355Z,1555705627.355 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-19T20:27:07.444Z,1555705627.444 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-19T20:27:07.543Z,1555705627.543 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-19T20:27:07.644Z,1555705627.644 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-19T20:27:07.730Z,1555705627.730 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-19T20:27:07.901Z,1555705627.901 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-19T20:27:08.694Z,1555705628.694 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-19T20:27:08.832Z,1555705628.832 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-19T20:27:08.846Z,1555705628.846 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-19T20:27:09.185Z,1555705629.185 [AHRS_M2] Loaded
2019-04-19T20:27:09.185Z,1555705629.185 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-19T20:27:09.260Z,1555705629.260 [DataOverHttps] Loaded
2019-04-19T20:27:09.260Z,1555705629.260 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-19T20:27:09.261Z,1555705629.261 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-04-19T20:27:09.262Z,1555705629.262 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5117
2019-04-19T20:27:09.275Z,1555705629.275 [Depth_Keller] Loaded
2019-04-19T20:27:09.275Z,1555705629.275 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-19T20:27:09.280Z,1555705629.280 [DropWeight] Loaded
2019-04-19T20:27:09.280Z,1555705629.280 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-19T20:27:09.336Z,1555705629.336 [DUSBL_Hydroid] Loaded
2019-04-19T20:27:09.336Z,1555705629.336 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-19T20:27:09.375Z,1555705629.375 [Micromodem] Loaded
2019-04-19T20:27:09.375Z,1555705629.375 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-19T20:27:09.470Z,1555705629.470 [NAL9602] Loaded
2019-04-19T20:27:09.470Z,1555705629.470 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-19T20:27:09.485Z,1555705629.485 [Onboard] Loaded
2019-04-19T20:27:09.486Z,1555705629.486 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-19T20:27:09.492Z,1555705629.492 [PowerOnly] Loaded
2019-04-19T20:27:09.492Z,1555705629.492 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-19T20:27:09.499Z,1555705629.499 [Radio_Surface] Loaded
2019-04-19T20:27:09.499Z,1555705629.499 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-19T20:27:09.500Z,1555705629.500 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-04-19T20:27:09.500Z,1555705629.500 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5118
2019-04-19T20:27:09.544Z,1555705629.544 [RDI_Pathfinder] Loaded
2019-04-19T20:27:09.544Z,1555705629.544 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-19T20:27:10.999Z,1555705630.999 [BPC1] Loaded
2019-04-19T20:27:10.999Z,1555705630.999 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-19T20:27:10.999Z,1555705630.999 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-19T20:27:10.000Z,1555705631.000 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-19T20:27:11.013Z,1555705631.013 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-19T20:27:11.013Z,1555705631.013 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-19T20:27:11.117Z,1555705631.117 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-19T20:27:11.118Z,1555705631.118 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-19T20:27:11.138Z,1555705631.138 [NavChart] Loaded
2019-04-19T20:27:11.138Z,1555705631.138 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-19T20:27:11.142Z,1555705631.142 [UniversalFixResidualReporter] Loaded
2019-04-19T20:27:11.142Z,1555705631.142 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-19T20:27:11.143Z,1555705631.143 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-19T20:27:11.143Z,1555705631.143 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-19T20:27:11.241Z,1555705631.241 [BuoyancyServo] Loaded
2019-04-19T20:27:11.241Z,1555705631.241 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-19T20:27:11.256Z,1555705631.256 [ElevatorServo] Loaded
2019-04-19T20:27:11.256Z,1555705631.256 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-19T20:27:11.271Z,1555705631.271 [MassServo] Loaded
2019-04-19T20:27:11.271Z,1555705631.271 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-19T20:27:11.286Z,1555705631.286 [RudderServo] Loaded
2019-04-19T20:27:11.286Z,1555705631.286 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-19T20:27:11.301Z,1555705631.301 [ThrusterServo] Loaded
2019-04-19T20:27:11.301Z,1555705631.301 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-19T20:27:11.301Z,1555705631.301 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-19T20:27:11.302Z,1555705631.302 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-19T20:27:11.544Z,1555705631.544 [CTD_NeilBrown] Loaded
2019-04-19T20:27:11.544Z,1555705631.544 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-19T20:27:11.545Z,1555705631.545 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408C84E0
2019-04-19T20:27:11.546Z,1555705631.546 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5119
2019-04-19T20:27:11.589Z,1555705631.589 [WetLabsSeaOWL_UV_A] Loaded
2019-04-19T20:27:11.590Z,1555705631.590 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-19T20:27:11.590Z,1555705631.590 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408F84E0
2019-04-19T20:27:11.591Z,1555705631.591 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 5120
2019-04-19T20:27:11.591Z,1555705631.591 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-19T20:27:11.592Z,1555705631.592 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-19T20:27:11.854Z,1555705631.854 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-19T20:27:11.855Z,1555705631.855 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-19T20:27:11.895Z,1555705631.895 [DepthRateCalculator] Loaded
2019-04-19T20:27:11.895Z,1555705631.895 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-19T20:27:11.901Z,1555705631.901 [PitchRateCalculator] Loaded
2019-04-19T20:27:11.901Z,1555705631.901 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-19T20:27:11.914Z,1555705631.914 [SpeedCalculator] Loaded
2019-04-19T20:27:11.914Z,1555705631.914 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-19T20:27:11.934Z,1555705631.934 [TempGradientCalculator] Loaded
2019-04-19T20:27:11.935Z,1555705631.935 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-19T20:27:11.940Z,1555705631.940 [YawRateCalculator] Loaded
2019-04-19T20:27:11.940Z,1555705631.940 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-19T20:27:11.979Z,1555705631.979 [ElevatorOffsetCalculator] Loaded
2019-04-19T20:27:11.980Z,1555705631.980 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-19T20:27:11.980Z,1555705631.980 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-19T20:27:11.981Z,1555705631.981 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-19T20:27:12.106Z,1555705632.106 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-19T20:27:12.128Z,1555705632.128 [SBIT] Loaded
2019-04-19T20:27:12.128Z,1555705632.128 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-19T20:27:12.129Z,1555705632.129 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-19T20:27:12.141Z,1555705632.141 [IBIT] Loaded
2019-04-19T20:27:12.141Z,1555705632.141 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-19T20:27:12.144Z,1555705632.144 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-19T20:27:12.280Z,1555705632.280 [CBIT] Loaded
2019-04-19T20:27:12.280Z,1555705632.280 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-19T20:27:12.281Z,1555705632.281 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-19T20:27:12.281Z,1555705632.281 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-19T20:27:12.350Z,1555705632.350 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-19T20:27:12.351Z,1555705632.351 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-19T20:27:12.447Z,1555705632.447 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-19T20:27:12.447Z,1555705632.447 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-19T20:27:12.510Z,1555705632.510 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-19T20:27:12.593Z,1555705632.593 [VerticalControl] Loaded
2019-04-19T20:27:12.593Z,1555705632.593 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-19T20:27:12.594Z,1555705632.594 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-19T20:27:12.651Z,1555705632.651 [HorizontalControl] Loaded
2019-04-19T20:27:12.651Z,1555705632.651 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-19T20:27:12.652Z,1555705632.652 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-19T20:27:12.653Z,1555705632.653 [SpeedControl] Loaded
2019-04-19T20:27:12.654Z,1555705632.654 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-19T20:27:12.654Z,1555705632.654 [LoopControl](DEBUG): Construct LoopControl.
2019-04-19T20:27:12.655Z,1555705632.655 [LoopControl] Loaded
2019-04-19T20:27:12.655Z,1555705632.655 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-19T20:27:12.655Z,1555705632.655 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-19T20:27:12.656Z,1555705632.656 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-19T20:27:12.683Z,1555705632.683 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-19T20:27:12.687Z,1555705632.687 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-19T20:27:12.688Z,1555705632.688 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-19T20:27:12.695Z,1555705632.695 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-19T20:27:12.696Z,1555705632.696 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AC84E0
2019-04-19T20:27:12.696Z,1555705632.696 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5121
2019-04-19T20:27:12.701Z,1555705632.701 [Supervisor](INFO): Main Thread ID is 5034
2019-04-19T20:27:12.701Z,1555705632.701 [Supervisor](DEBUG): Running supervisor.
2019-04-19T20:27:12.702Z,1555705632.702 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5122
2019-04-19T20:27:12.704Z,1555705632.704 [controlThread ThreadHandler](INFO): Handler Thread ID is 5123
2019-04-19T20:27:12.705Z,1555705632.705 [controlThread](DEBUG): Initializing ControlThread
2019-04-19T20:27:12.711Z,1555705632.711 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-19T20:27:12.711Z,1555705632.711 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-19T20:27:12.712Z,1555705632.712 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-19T20:27:12.713Z,1555705632.713 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-19T20:27:12.713Z,1555705632.713 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-19T20:27:12.713Z,1555705632.713 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-19T20:27:12.714Z,1555705632.714 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-19T20:27:12.714Z,1555705632.714 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-19T20:27:12.715Z,1555705632.715 [SBIT](INFO): Initialize SBIT Component.
2019-04-19T20:27:12.715Z,1555705632.715 [SBIT](IMPORTANT): git: 2019-04-10
2019-04-19T20:27:12.715Z,1555705632.715 [SBIT](INFO): git hash: c014275aafff9d7805d0dcecdf6cd08611644109
2019-04-19T20:27:12.716Z,1555705632.716 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-19T20:27:12.716Z,1555705632.716 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-19T20:27:12.717Z,1555705632.717 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-04-19T20:27:12.717Z,1555705632.717 [IBIT](INFO): Initialize IBIT Component.
2019-04-19T20:27:12.718Z,1555705632.718 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-19T20:27:12.719Z,1555705632.719 [logger ThreadHandler](INFO): Handler Thread ID is 5124
2019-04-19T20:27:12.731Z,1555705632.731 [CBIT](DEBUG): Initialized mux pins.
2019-04-19T20:27:12.731Z,1555705632.731 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-19T20:27:12.740Z,1555705632.740 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5125
2019-04-19T20:27:12.741Z,1555705632.741 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-19T20:27:12.752Z,1555705632.752 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5126
2019-04-19T20:27:12.755Z,1555705632.755 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-19T20:27:12.756Z,1555705632.756 [CBIT](DEBUG): Initializing heartbeat.
2019-04-19T20:27:12.772Z,1555705632.772 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5127
2019-04-19T20:27:12.773Z,1555705632.773 [CTD_NeilBrown](INFO): Powering down
2019-04-19T20:27:12.800Z,1555705632.800 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 5128
2019-04-19T20:27:12.800Z,1555705632.800 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-19T20:27:12.827Z,1555705632.827 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-19T20:27:12.827Z,1555705632.827 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-19T20:27:12.832Z,1555705632.832 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5129
2019-04-19T20:27:12.839Z,1555705632.839 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-19T20:27:12.840Z,1555705632.840 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-19T20:27:12.840Z,1555705632.840 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-19T20:27:12.840Z,1555705632.840 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-19T20:27:12.840Z,1555705632.840 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-19T20:27:12.840Z,1555705632.840 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-19T20:27:12.840Z,1555705632.840 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-19T20:27:12.841Z,1555705632.841 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-19T20:27:12.841Z,1555705632.841 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-19T20:27:12.841Z,1555705632.841 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-19T20:27:12.841Z,1555705632.841 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-19T20:27:12.841Z,1555705632.841 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-19T20:27:12.842Z,1555705632.842 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-19T20:27:12.842Z,1555705632.842 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-19T20:27:12.842Z,1555705632.842 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-19T20:27:12.842Z,1555705632.842 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-19T20:27:12.863Z,1555705632.863 [CBIT](DEBUG): Backplane powered.
2019-04-19T20:27:12.864Z,1555705632.864 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-19T20:27:12.865Z,1555705632.865 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-19T20:27:12.866Z,1555705632.866 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-19T20:27:12.867Z,1555705632.867 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-19T20:27:12.868Z,1555705632.868 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-19T20:27:12.885Z,1555705632.885 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-19T20:27:12.940Z,1555705632.940 [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-19T20:27:12.941Z,1555705632.941 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-19T20:27:13.156Z,1555705633.156 [Radio_Surface](INFO): Powering up
2019-04-19T20:27:13.200Z,1555705633.200 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-19T20:27:13.201Z,1555705633.201 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-19T20:27:13.203Z,1555705633.203 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-19T20:27:13.233Z,1555705633.233 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-19T20:27:13.252Z,1555705633.252 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-19T20:27:13.258Z,1555705633.258 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-19T20:27:13.289Z,1555705633.289 [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-19T20:27:13.294Z,1555705633.294 [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-19T20:27:13.319Z,1555705633.319 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-19T20:27:13.354Z,1555705633.354 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-19T20:27:13.355Z,1555705633.355 [DUSBL_Hydroid](INFO): Powering up
2019-04-19T20:27:13.355Z,1555705633.355 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-19T20:27:13.436Z,1555705633.436 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-19T20:27:13.449Z,1555705633.449 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:27:13.456Z,1555705633.456 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-19T20:27:13.457Z,1555705633.457 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:27:13.464Z,1555705633.464 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-19T20:27:13.465Z,1555705633.465 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:27:13.472Z,1555705633.472 [MassServo](DEBUG): Initializing MassServo.
2019-04-19T20:27:13.472Z,1555705633.472 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:27:13.480Z,1555705633.480 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-19T20:27:13.480Z,1555705633.480 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:27:13.488Z,1555705633.488 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-19T20:27:13.716Z,1555705633.716 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-04-19T20:27:13.716Z,1555705633.716 [DropWeight] Hardware Fault, FailCount= 1
2019-04-19T20:27:13.716Z,1555705633.716 [DropWeight](ERROR): Hardware Fault
2019-04-19T20:27:13.718Z,1555705633.718 [Micromodem](INFO): Powering up
2019-04-19T20:27:13.718Z,1555705633.718 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-19T20:27:13.756Z,1555705633.756 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-19T20:27:13.764Z,1555705633.764 [CommandLine](FAULT): Scheduling is paused
2019-04-19T20:27:13.764Z,1555705633.764 [CBIT](INFO): Critical error at 20190419T202713
2019-04-19T20:27:13.765Z,1555705633.765 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-04-19T20:27:13.767Z,1555705633.767 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-04-19T20:27:13.768Z,1555705633.768 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-04-19T20:27:14.439Z,1555705634.439 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-19T20:27:14.440Z,1555705634.440 [RudderServo](FAULT): Rudder failed to initialize
2019-04-19T20:27:14.440Z,1555705634.440 [RudderServo] Communications Fault, FailCount= 1
2019-04-19T20:27:14.440Z,1555705634.440 [RudderServo](ERROR): Communications Fault
2019-04-19T20:27:14.549Z,1555705634.549 [CBIT](INFO): Critical error at 20190419T202713
2019-04-19T20:27:14.552Z,1555705634.552 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-19T20:27:14.720Z,1555705634.720 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-19T20:27:14.720Z,1555705634.720 [RudderServo](INFO): Powering down
2019-04-19T20:27:15.400Z,1555705635.400 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:27:15.520Z,1555705635.520 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-19T20:27:15.525Z,1555705635.525 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-19T20:27:15.525Z,1555705635.525 [RudderServo] No Fault, FailCount= 1
2019-04-19T20:27:24.933Z,1555705644.933 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004422
2019-04-19T20:27:26.711Z,1555705646.711 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-19T20:27:31.529Z,1555705651.529 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-19T20:27:39.641Z,1555705659.641 [NAL9602](INFO): Powering up NAL9602
2019-04-19T20:27:50.549Z,1555705670.549 [NAL9602](INFO): NAL9602 initialized
2019-04-19T20:27:51.351Z,1555705671.351 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:27:54.201Z,1555705674.201 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-19T20:27:54.201Z,1555705674.201 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190419133646900.1,   0.0,1448.9,  0
2019-04-19T20:27:57.437Z,1555705677.437 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-19T20:27:57.442Z,1555705677.442 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-19T20:27:59.033Z,1555705679.033 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-19T20:27:59.033Z,1555705679.033 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-04-19T20:27:59.205Z,1555705679.205 [CommandLine](IMPORTANT): got command show variable range
2019-04-19T20:27:59.208Z,1555705679.208 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-04-19T20:27:59.402Z,1555705679.402 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-19T20:27:59.403Z,1555705679.403 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-04-19T20:27:59.424Z,1555705679.424 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-04-19T20:27:59.426Z,1555705679.426 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-04-19T20:27:59.427Z,1555705679.427 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-04-19T20:27:59.432Z,1555705679.432 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-04-19T20:27:59.434Z,1555705679.434 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-04-19T20:28:01.541Z,1555705681.541 [NAL9602](INFO): SBD MO Status=0, MOMSN=3509, MT Status=0, MTMSN=0
2019-04-19T20:28:01.541Z,1555705681.541 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:28:02.355Z,1555705682.355 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:05.587Z,1555705685.587 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:08.407Z,1555705688.407 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:08.477Z,1555705688.477 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.020886
CHAN A1 (24V): -0.027449
CHAN A2 (12V): -0.007226
CHAN A3 (5V): -0.002059
CHAN B0 (3.3V): 0.000114
CHAN B1 (3.15aV): 0.000010
CHAN B2 (3.15bV): 0.000143
CHAN B3 (GND): 0.002213
OPEN: 0.004814
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-19T20:28:10.857Z,1555705690.857 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-04-19T20:28:11.644Z,1555705691.644 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:14.627Z,1555705694.627 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:17.455Z,1555705697.455 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:20.691Z,1555705700.691 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:23.523Z,1555705703.523 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:26.755Z,1555705706.755 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:27.143Z,1555705707.143 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202825.00,A,3648.15829,N,12147.21647,W,0.078,0.00,190419,,,A*71
2019-04-19T20:28:27.147Z,1555705707.147 [NAL9602](INFO): GPS fix at 20190419T202825: (36.802638, -121.786941)
2019-04-19T20:28:34.255Z,1555705714.255 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-04-19T20:28:43.735Z,1555705723.735 [CommandLine](IMPORTANT): got command show stack
2019-04-19T20:28:43.736Z,1555705723.736 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-19T20:28:43.736Z,1555705723.736 [MissionManager](IMPORTANT): Mission loaded, but not running.
2019-04-19T20:28:50.738Z,1555705730.738 [SBIT](IMPORTANT): SBIT PASSED
2019-04-19T20:28:50.791Z,1555705730.791 [CommandLine](IMPORTANT): got command configSet list
2019-04-19T20:28:50.792Z,1555705730.792 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-19T20:28:50.792Z,1555705730.792 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-04-19T20:28:50.792Z,1555705730.792 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=90 count;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-04-19T20:28:50.793Z,1555705730.793 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-04-19T20:28:50.794Z,1555705730.794 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-04-19T20:28:50.794Z,1555705730.794 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-04-19T20:28:51.122Z,1555705731.122 [MissionManager](IMPORTANT): Started mission Startup
2019-04-19T20:28:51.123Z,1555705731.123 [Startup] Running Loop=1
2019-04-19T20:28:51.123Z,1555705731.123 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-19T20:28:51.123Z,1555705731.123 [Startup:A.GoToSurface] Running Loop=1
2019-04-19T20:28:51.123Z,1555705731.123 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:28:51.124Z,1555705731.124 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:28:51.124Z,1555705731.124 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:28:51.125Z,1555705731.125 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:28:51.125Z,1555705731.125 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:28:51.125Z,1555705731.125 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:28:51.127Z,1555705731.127 [Startup:StartupSatComms] Running Loop=1
2019-04-19T20:28:51.127Z,1555705731.127 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-19T20:28:51.127Z,1555705731.127 [Startup:StartupSatComms:A] Running Loop=1
2019-04-19T20:28:51.531Z,1555705731.531 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-19T20:28:52.739Z,1555705732.739 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:28:53.119Z,1555705733.119 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202851.00,A,3648.16012,N,12147.21560,W,0.058,0.00,190419,,,A*75
2019-04-19T20:28:53.121Z,1555705733.121 [NAL9602](INFO): GPS fix at 20190419T202851: (36.802669, -121.786927)
2019-04-19T20:28:53.170Z,1555705733.170 [Startup:StartupSatComms:A] Stopped
2019-04-19T20:28:53.171Z,1555705733.171 [Startup:StartupSatComms:B] Running Loop=1
2019-04-19T20:28:53.567Z,1555705733.567 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-19T20:28:58.803Z,1555705738.803 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190411T185732/Courier0072.lzma
2019-04-19T20:28:59.622Z,1555705739.622 [DataOverHttps](INFO): Moved sent file to Logs/20190411T185732/Courier0072.lzma.bak
2019-04-19T20:28:59.622Z,1555705739.622 [DataOverHttps](INFO): SBD MOMSN=10666389
2019-04-19T20:29:11.487Z,1555705751.487 [DataOverHttps](INFO): Sending 304 bytes from file Logs/20190419T202702/Courier0000.lzma
2019-04-19T20:29:12.293Z,1555705752.293 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Courier0000.lzma.bak
2019-04-19T20:29:12.293Z,1555705752.293 [DataOverHttps](INFO): SBD MOMSN=10666391
2019-04-19T20:29:15.735Z,1555705755.735 [CommandLine](IMPORTANT): got command show stack
2019-04-19T20:29:15.735Z,1555705755.735 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-19T20:29:15.736Z,1555705755.736 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-04-19T20:29:15.736Z,1555705755.736 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B
2019-04-19T20:29:24.435Z,1555705764.435 [DataOverHttps](INFO): Sending 183 bytes from file Logs/20190411T185732/Express0073.lzma
2019-04-19T20:29:25.241Z,1555705765.241 [DataOverHttps](INFO): Moved sent file to Logs/20190411T185732/Express0073.lzma.bak
2019-04-19T20:29:25.241Z,1555705765.241 [DataOverHttps](INFO): SBD MOMSN=10666397
2019-04-19T20:29:25.485Z,1555705765.485 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:29:37.450Z,1555705777.450 [DataOverHttps](INFO): Sending 1482 bytes from file Logs/20190419T202702/Express0001.lzma
2019-04-19T20:29:38.253Z,1555705778.253 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Express0001.lzma.bak
2019-04-19T20:29:38.253Z,1555705778.253 [DataOverHttps](INFO): SBD MOMSN=10666403
2019-04-19T20:29:38.874Z,1555705778.874 [Startup:StartupSatComms:B] Stopped
2019-04-19T20:29:38.874Z,1555705778.874 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-19T20:29:38.874Z,1555705778.874 [Startup:StartupSatComms] Stopped
2019-04-19T20:29:38.874Z,1555705778.874 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-19T20:29:38.875Z,1555705778.875 [Startup](INFO): Completed Startup
2019-04-19T20:29:38.875Z,1555705778.875 [MissionManager](INFO): Startup is completed.
2019-04-19T20:29:38.879Z,1555705778.879 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-19T20:29:38.879Z,1555705778.879 [Startup] Stopped
2019-04-19T20:29:38.880Z,1555705778.880 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-19T20:29:38.880Z,1555705778.880 [Startup:A.GoToSurface] Stopped
2019-04-19T20:29:38.880Z,1555705778.880 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T20:29:39.255Z,1555705779.255 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T20:29:39.255Z,1555705779.255 [Default] Running Loop=1
2019-04-19T20:29:39.256Z,1555705779.256 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T20:29:39.256Z,1555705779.256 [Default:B.GoToSurface] Running Loop=1
2019-04-19T20:29:39.256Z,1555705779.256 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:29:39.256Z,1555705779.256 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:29:39.256Z,1555705779.256 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:29:39.257Z,1555705779.257 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:29:39.257Z,1555705779.257 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:29:39.257Z,1555705779.257 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:29:39.257Z,1555705779.257 [Default:A.Wait] Running Loop=1
2019-04-19T20:29:39.258Z,1555705779.258 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:29:46.512Z,1555705786.512 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:29:52.587Z,1555705792.587 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T20:29:52.587Z,1555705792.587 [Default:A.Wait] Stopped
2019-04-19T20:29:52.587Z,1555705792.587 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:29:52.995Z,1555705792.995 [Default:CheckIn] Running Loop=1
2019-04-19T20:29:52.995Z,1555705792.995 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:29:52.995Z,1555705792.995 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:29:53.386Z,1555705793.386 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-19T20:29:54.587Z,1555705794.587 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:29:55.005Z,1555705795.005 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202953.00,A,3648.15892,N,12147.21581,W,0.117,0.00,190419,,,A*70
2019-04-19T20:29:55.007Z,1555705795.007 [NAL9602](INFO): GPS fix at 20190419T202953: (36.802649, -121.786930)
2019-04-19T20:29:55.086Z,1555705795.086 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:29:55.086Z,1555705795.086 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:29:55.423Z,1555705795.423 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-19T20:29:56.218Z,1555705796.218 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:30:00.831Z,1555705800.831 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190419T202702/Courier0004.lzma
2019-04-19T20:30:01.640Z,1555705801.640 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Courier0004.lzma.bak
2019-04-19T20:30:01.640Z,1555705801.640 [DataOverHttps](INFO): SBD MOMSN=10666458
2019-04-19T20:30:06.316Z,1555705806.316 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:30:15.380Z,1555705815.380 [DataOverHttps](INFO): Sending 339 bytes from file Logs/20190419T202702/Express0005.lzma
2019-04-19T20:30:16.045Z,1555705816.045 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:30:16.185Z,1555705816.185 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Express0005.lzma.bak
2019-04-19T20:30:16.185Z,1555705816.185 [DataOverHttps](INFO): SBD MOMSN=10666534
2019-04-19T20:30:16.846Z,1555705816.846 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:30:16.846Z,1555705816.846 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T20:30:16.847Z,1555705816.847 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:30:24.070Z,1555705824.070 [NAL9602](INFO): SBD MO Status=2, MOMSN=3510, MT Status=2, MTMSN=0
2019-04-19T20:30:24.070Z,1555705824.070 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T20:30:25.721Z,1555705825.721 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:30:27.113Z,1555705827.113 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:30:27.114Z,1555705827.114 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:30:27.142Z,1555705827.142 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-19T20:30:27.146Z,1555705827.146 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-19T20:30:27.149Z,1555705827.149 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-19T20:30:27.153Z,1555705827.153 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-19T20:30:27.157Z,1555705827.157 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-19T20:30:27.158Z,1555705827.158 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-19T20:30:27.194Z,1555705827.194 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-19T20:30:27.225Z,1555705827.225 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-19T20:30:27.233Z,1555705827.233 [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-19T20:30:27.235Z,1555705827.235 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:30:27.329Z,1555705827.329 [Default] Stopped
2019-04-19T20:30:27.329Z,1555705827.329 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T20:30:27.329Z,1555705827.329 [Default:B.GoToSurface] Stopped
2019-04-19T20:30:27.329Z,1555705827.329 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T20:30:27.329Z,1555705827.329 [Default:CheckIn] Stopped
2019-04-19T20:30:27.330Z,1555705827.330 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T20:30:27.330Z,1555705827.330 [Default:CheckIn:C.Wait] Stopped
2019-04-19T20:30:27.330Z,1555705827.330 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:30:27.330Z,1555705827.330 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-19T20:30:27.330Z,1555705827.330 [DUSBL] Running Loop=1
2019-04-19T20:30:27.330Z,1555705827.330 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-19T20:30:27.330Z,1555705827.330 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:30:27.330Z,1555705827.330 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-19T20:30:27.331Z,1555705827.331 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:30:27.331Z,1555705827.331 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-19T20:30:27.331Z,1555705827.331 [DUSBL:C] Running Loop=1
2019-04-19T20:30:27.331Z,1555705827.331 [DUSBL:RequestRepeater] Running Loop=1
2019-04-19T20:30:27.335Z,1555705827.335 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:30:27.335Z,1555705827.335 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:30:27.336Z,1555705827.336 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:30:27.336Z,1555705827.336 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:30:27.336Z,1555705827.336 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:30:27.336Z,1555705827.336 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:30:27.336Z,1555705827.336 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:30:27.337Z,1555705827.337 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-19T20:30:27.338Z,1555705827.338 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-19T20:30:27.338Z,1555705827.338 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:30:27.338Z,1555705827.338 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:30:28.914Z,1555705828.914 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:30.935Z,1555705830.935 [NAL9602](INFO): SBD MO Status=0, MOMSN=3510, MT Status=0, MTMSN=0
2019-04-19T20:30:30.935Z,1555705830.935 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:30:32.953Z,1555705832.953 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:33.361Z,1555705833.361 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:30:33.761Z,1555705833.761 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:34.165Z,1555705834.165 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:30:34.167Z,1555705834.167 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203032.27*5B

2019-04-19T20:30:35.393Z,1555705835.393 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:30:37.426Z,1555705837.426 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:30:37.426Z,1555705837.426 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:30:37.427Z,1555705837.427 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:30:37.427Z,1555705837.427 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:30:37.427Z,1555705837.427 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater] Running Loop=2
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:30:37.428Z,1555705837.428 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:30:37.806Z,1555705837.806 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:38.209Z,1555705838.209 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:30:38.614Z,1555705838.614 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:39.017Z,1555705839.017 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:30:39.018Z,1555705839.018 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203037.11*5B

2019-04-19T20:30:42.671Z,1555705842.671 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:43.057Z,1555705843.057 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:30:43.461Z,1555705843.461 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:43.865Z,1555705843.865 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:30:43.866Z,1555705843.866 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203041.98*5B

2019-04-19T20:30:45.103Z,1555705845.103 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:30:47.498Z,1555705847.498 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:47.901Z,1555705847.901 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:30:48.032Z,1555705848.032 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:30:48.032Z,1555705848.032 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:30:48.032Z,1555705848.032 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater] Running Loop=3
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:30:48.033Z,1555705848.033 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:30:48.034Z,1555705848.034 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:30:48.305Z,1555705848.305 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:48.709Z,1555705848.709 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:30:48.710Z,1555705848.710 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203046.81*54

2019-04-19T20:30:52.361Z,1555705852.361 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:52.766Z,1555705852.766 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:30:53.161Z,1555705853.161 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:53.561Z,1555705853.561 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:30:53.562Z,1555705853.562 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203051.67*5A

2019-04-19T20:30:55.205Z,1555705855.205 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:30:57.197Z,1555705857.197 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:57.597Z,1555705857.597 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:30:58.009Z,1555705858.009 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:30:58.172Z,1555705858.172 [CommandLine](IMPORTANT): got command stop
2019-04-19T20:30:58.172Z,1555705858.172 [CommandLine](IMPORTANT): Scheduling is paused
2019-04-19T20:30:58.173Z,1555705858.173 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-19T20:30:58.405Z,1555705858.405 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:30:58.406Z,1555705858.406 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203056.51*58

2019-04-19T20:30:58.438Z,1555705858.438 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:30:58.439Z,1555705858.439 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:30:58.439Z,1555705858.439 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:30:58.463Z,1555705858.463 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater] Running Loop=4
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:30:58.464Z,1555705858.464 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:30:58.465Z,1555705858.465 [MissionManager](INFO): MissionManager is completed.
2019-04-19T20:30:58.465Z,1555705858.465 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-19T20:30:58.465Z,1555705858.465 [DUSBL] Stopped
2019-04-19T20:30:58.465Z,1555705858.465 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-19T20:30:58.465Z,1555705858.465 [DUSBL:A.Pitch] Stopped
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:B.SetSpeed] Stopped
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:C] Stopped
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:30:58.466Z,1555705858.466 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:30:58.860Z,1555705858.860 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T20:30:58.860Z,1555705858.860 [Default] Running Loop=1
2019-04-19T20:30:58.860Z,1555705858.860 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T20:30:58.860Z,1555705858.860 [Default:B.GoToSurface] Running Loop=1
2019-04-19T20:30:58.860Z,1555705858.860 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:30:58.860Z,1555705858.860 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:30:58.861Z,1555705858.861 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:30:58.861Z,1555705858.861 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:30:58.861Z,1555705858.861 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:30:58.862Z,1555705858.862 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:30:58.862Z,1555705858.862 [Default:A.Wait] Running Loop=1
2019-04-19T20:30:58.862Z,1555705858.862 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:31:01.663Z,1555705861.663 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:31:05.288Z,1555705865.288 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:31:12.175Z,1555705872.175 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T20:31:12.175Z,1555705872.175 [Default:A.Wait] Stopped
2019-04-19T20:31:12.175Z,1555705872.175 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:31:12.579Z,1555705872.579 [Default:CheckIn] Running Loop=1
2019-04-19T20:31:12.579Z,1555705872.579 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:31:12.579Z,1555705872.579 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:31:14.175Z,1555705874.175 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:31:14.571Z,1555705874.571 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203112.00,A,3648.15799,N,12147.20850,W,0.389,24.76,190419,,,A*4A
2019-04-19T20:31:14.585Z,1555705874.585 [NAL9602](INFO): GPS fix at 20190419T203112: (36.802633, -121.786808)
2019-04-19T20:31:14.674Z,1555705874.674 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:31:14.674Z,1555705874.674 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:31:14.763Z,1555705874.763 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:31:14.763Z,1555705874.763 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:31:14.811Z,1555705874.811 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-19T20:31:14.813Z,1555705874.813 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-19T20:31:14.815Z,1555705874.815 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-19T20:31:14.817Z,1555705874.817 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-19T20:31:14.819Z,1555705874.819 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-19T20:31:14.820Z,1555705874.820 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-19T20:31:14.825Z,1555705874.825 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-19T20:31:14.832Z,1555705874.832 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-19T20:31:14.835Z,1555705874.835 [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-19T20:31:14.837Z,1555705874.837 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:31:15.011Z,1555705875.011 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:31:15.082Z,1555705875.082 [Default] Stopped
2019-04-19T20:31:15.082Z,1555705875.082 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T20:31:15.082Z,1555705875.082 [Default:B.GoToSurface] Stopped
2019-04-19T20:31:15.082Z,1555705875.082 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T20:31:15.082Z,1555705875.082 [Default:CheckIn] Stopped
2019-04-19T20:31:15.082Z,1555705875.082 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T20:31:15.082Z,1555705875.082 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:31:15.083Z,1555705875.083 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-19T20:31:15.083Z,1555705875.083 [DUSBL] Running Loop=1
2019-04-19T20:31:15.083Z,1555705875.083 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-19T20:31:15.083Z,1555705875.083 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:31:15.083Z,1555705875.083 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-19T20:31:15.083Z,1555705875.083 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:31:15.084Z,1555705875.084 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-19T20:31:15.084Z,1555705875.084 [DUSBL:C] Running Loop=1
2019-04-19T20:31:15.084Z,1555705875.084 [DUSBL:RequestRepeater] Running Loop=1
2019-04-19T20:31:15.084Z,1555705875.084 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:31:15.084Z,1555705875.084 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:31:15.084Z,1555705875.084 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:31:15.084Z,1555705875.084 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:31:15.085Z,1555705875.085 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:31:15.085Z,1555705875.085 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:31:15.085Z,1555705875.085 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:31:15.086Z,1555705875.086 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-19T20:31:15.086Z,1555705875.086 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-19T20:31:15.086Z,1555705875.086 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:31:15.087Z,1555705875.087 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:31:16.589Z,1555705876.589 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:16.989Z,1555705876.989 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:17.400Z,1555705877.400 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:17.832Z,1555705877.832 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:17.833Z,1555705877.833 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203115.90*53

2019-04-19T20:31:20.226Z,1555705880.226 [NAL9602](INFO): SBD MO Status=0, MOMSN=3511, MT Status=0, MTMSN=0
2019-04-19T20:31:20.227Z,1555705880.227 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:31:21.437Z,1555705881.437 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:21.841Z,1555705881.841 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:22.245Z,1555705882.245 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:22.670Z,1555705882.670 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:22.671Z,1555705882.671 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203120.75*5E

2019-04-19T20:31:24.713Z,1555705884.713 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:31:25.134Z,1555705885.134 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:31:25.134Z,1555705885.134 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:31:25.134Z,1555705885.134 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:31:25.135Z,1555705885.135 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:31:25.135Z,1555705885.135 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:31:25.135Z,1555705885.135 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater] Running Loop=2
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:31:25.136Z,1555705885.136 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:31:26.285Z,1555705886.285 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:26.701Z,1555705886.701 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:27.089Z,1555705887.089 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:27.499Z,1555705887.499 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:27.501Z,1555705887.501 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203125.60*5F

2019-04-19T20:31:31.129Z,1555705891.129 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:31.544Z,1555705891.544 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:31.937Z,1555705891.937 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:32.341Z,1555705892.341 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:32.343Z,1555705892.343 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203130.44*5D

2019-04-19T20:31:34.386Z,1555705894.386 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:31:35.602Z,1555705895.602 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:31:35.602Z,1555705895.602 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:31:35.603Z,1555705895.603 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:31:35.619Z,1555705895.619 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:31:35.619Z,1555705895.619 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:31:35.619Z,1555705895.619 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater] Running Loop=3
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:31:35.620Z,1555705895.620 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:31:35.977Z,1555705895.977 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:36.385Z,1555705896.385 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:36.785Z,1555705896.785 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:37.196Z,1555705897.196 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:37.198Z,1555705897.198 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203135.29*53

2019-04-19T20:31:40.848Z,1555705900.848 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:41.233Z,1555705901.233 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:41.645Z,1555705901.645 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:42.041Z,1555705902.041 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:42.043Z,1555705902.043 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203140.17*5C

2019-04-19T20:31:42.884Z,1555705902.884 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-04-19T20:31:44.088Z,1555705904.088 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:31:44.215Z,1555705904.215 [CommandLine](IMPORTANT): got command failComponent
2019-04-19T20:31:44.215Z,1555705904.215 [CommandLine](IMPORTANT): Failed components:
2019-04-19T20:31:44.216Z,1555705904.216 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2019-04-19T20:31:45.678Z,1555705905.678 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:46.081Z,1555705906.081 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:46.107Z,1555705906.107 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:31:46.108Z,1555705906.108 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:31:46.108Z,1555705906.108 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:31:46.108Z,1555705906.108 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater] Running Loop=4
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:31:46.109Z,1555705906.109 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:31:46.481Z,1555705906.481 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:46.889Z,1555705906.889 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:46.891Z,1555705906.891 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203144.99*5E

2019-04-19T20:31:50.526Z,1555705910.526 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:50.929Z,1555705910.929 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:50.933Z,1555705910.933 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:31:51.329Z,1555705911.329 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:51.738Z,1555705911.738 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:51.739Z,1555705911.739 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203149.83*58

2019-04-19T20:31:53.791Z,1555705913.791 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:31:55.373Z,1555705915.373 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:55.777Z,1555705915.777 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:31:56.177Z,1555705916.177 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:31:56.585Z,1555705916.585 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:31:56.587Z,1555705916.587 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203154.69*50

2019-04-19T20:31:56.634Z,1555705916.634 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:31:56.634Z,1555705916.634 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:31:56.634Z,1555705916.634 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:31:56.637Z,1555705916.637 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:31:56.637Z,1555705916.637 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:31:56.638Z,1555705916.638 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:31:56.638Z,1555705916.638 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:31:56.638Z,1555705916.638 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:31:56.638Z,1555705916.638 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-19T20:31:56.639Z,1555705916.639 [DUSBL:RequestRepeater] Running Loop=5
2019-04-19T20:31:56.639Z,1555705916.639 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:31:56.640Z,1555705916.640 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:31:56.640Z,1555705916.640 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:31:56.640Z,1555705916.640 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:31:56.640Z,1555705916.640 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:32:00.225Z,1555705920.225 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:00.643Z,1555705920.643 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:01.029Z,1555705921.029 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:01.433Z,1555705921.433 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:01.435Z,1555705921.435 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203159.54*53

2019-04-19T20:32:03.895Z,1555705923.895 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:32:05.070Z,1555705925.070 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:05.469Z,1555705925.469 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:05.877Z,1555705925.877 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:06.277Z,1555705926.277 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:06.279Z,1555705926.279 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203204.39*53

2019-04-19T20:32:07.118Z,1555705927.118 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:32:07.119Z,1555705927.119 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:32:07.119Z,1555705927.119 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:32:07.123Z,1555705927.123 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater] Running Loop=6
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:32:07.124Z,1555705927.124 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:32:09.917Z,1555705929.917 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:10.325Z,1555705930.325 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:10.721Z,1555705930.721 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:11.129Z,1555705931.129 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:11.131Z,1555705931.131 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203209.23*55

2019-04-19T20:32:14.765Z,1555705934.765 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:15.165Z,1555705935.165 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:15.573Z,1555705935.573 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:15.977Z,1555705935.977 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:15.979Z,1555705935.979 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203214.08*50

2019-04-19T20:32:17.652Z,1555705937.652 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:32:17.652Z,1555705937.652 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:32:17.653Z,1555705937.653 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:32:17.654Z,1555705937.654 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:32:17.655Z,1555705937.655 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:32:17.655Z,1555705937.655 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:32:17.655Z,1555705937.655 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:32:17.658Z,1555705937.658 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:32:17.658Z,1555705937.658 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-04-19T20:32:17.659Z,1555705937.659 [DUSBL:RequestRepeater] Running Loop=7
2019-04-19T20:32:17.667Z,1555705937.667 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:32:17.667Z,1555705937.667 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:32:17.667Z,1555705937.667 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:32:17.668Z,1555705937.668 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:32:17.668Z,1555705937.668 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:32:19.613Z,1555705939.613 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:20.017Z,1555705940.017 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:20.417Z,1555705940.417 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:20.829Z,1555705940.829 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:20.831Z,1555705940.831 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203218.93*5E

2019-04-19T20:32:24.461Z,1555705944.461 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:24.865Z,1555705944.865 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:25.265Z,1555705945.265 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:25.681Z,1555705945.681 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:25.683Z,1555705945.683 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203223.80*54

2019-04-19T20:32:28.134Z,1555705948.134 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:32:28.135Z,1555705948.135 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:32:28.135Z,1555705948.135 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater] Running Loop=8
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:32:28.140Z,1555705948.140 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:32:28.141Z,1555705948.141 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:32:28.141Z,1555705948.141 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:32:29.309Z,1555705949.309 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:29.713Z,1555705949.713 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:30.113Z,1555705950.113 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:30.522Z,1555705950.522 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:30.523Z,1555705950.523 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203228.62*53

2019-04-19T20:32:34.157Z,1555705954.157 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:34.561Z,1555705954.561 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:32:34.965Z,1555705954.965 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:32:35.379Z,1555705955.379 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:32:35.380Z,1555705955.380 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203233.47*5E

2019-04-19T20:32:35.532Z,1555705955.532 [CommandLine](IMPORTANT): got command stop
2019-04-19T20:32:35.532Z,1555705955.532 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-19T20:32:35.842Z,1555705955.842 [MissionManager](INFO): MissionManager is completed.
2019-04-19T20:32:35.842Z,1555705955.842 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL] Stopped
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:A.Pitch] Stopped
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:B.SetSpeed] Stopped
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:C] Stopped
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:32:35.842Z,1555705955.842 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:32:35.843Z,1555705955.843 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:32:35.843Z,1555705955.843 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:32:36.219Z,1555705956.219 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T20:32:36.219Z,1555705956.219 [Default] Running Loop=1
2019-04-19T20:32:36.219Z,1555705956.219 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T20:32:36.219Z,1555705956.219 [Default:B.GoToSurface] Running Loop=1
2019-04-19T20:32:36.219Z,1555705956.219 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:32:36.220Z,1555705956.220 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:32:36.220Z,1555705956.220 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:32:36.220Z,1555705956.220 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:32:36.221Z,1555705956.221 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:32:36.221Z,1555705956.221 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:32:36.221Z,1555705956.221 [Default:A.Wait] Running Loop=1
2019-04-19T20:32:36.221Z,1555705956.221 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:32:47.898Z,1555705967.898 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem
2019-04-19T20:32:47.899Z,1555705967.899 [Micromodem] Hardware Fault, FailCount= 1
2019-04-19T20:32:47.899Z,1555705967.899 [Micromodem](ERROR): Hardware Fault
2019-04-19T20:32:47.899Z,1555705967.899 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault
2019-04-19T20:32:47.905Z,1555705967.905 [Micromodem](INFO): Powering down
2019-04-19T20:32:48.086Z,1555705968.086 [CBIT](ERROR): Hardware Fault in component: Micromodem
2019-04-19T20:32:48.810Z,1555705968.810 [CBIT](INFO): Clearing failed state for component Micromodem
2019-04-19T20:32:48.810Z,1555705968.810 [Micromodem] No Fault, FailCount= 1
2019-04-19T20:32:49.563Z,1555705969.563 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T20:32:49.563Z,1555705969.563 [Default:A.Wait] Stopped
2019-04-19T20:32:49.563Z,1555705969.563 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:32:49.979Z,1555705969.979 [Default:CheckIn] Running Loop=1
2019-04-19T20:32:49.979Z,1555705969.979 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:32:49.983Z,1555705969.983 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:32:51.533Z,1555705971.533 [Micromodem](INFO): Powering up
2019-04-19T20:32:51.533Z,1555705971.533 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-19T20:32:51.559Z,1555705971.559 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:32:51.931Z,1555705971.931 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203250.00,A,3648.15876,N,12147.21157,W,0.117,24.76,190419,,,A*4B
2019-04-19T20:32:51.934Z,1555705971.934 [NAL9602](INFO): GPS fix at 20190419T203250: (36.802646, -121.786860)
2019-04-19T20:32:52.053Z,1555705972.053 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:32:52.053Z,1555705972.053 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:32:57.723Z,1555705977.723 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190419T202702/Courier0007.lzma
2019-04-19T20:32:58.529Z,1555705978.529 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Courier0007.lzma.bak
2019-04-19T20:32:58.529Z,1555705978.529 [DataOverHttps](INFO): SBD MOMSN=10666600
2019-04-19T20:33:10.221Z,1555705990.221 [DataOverHttps](INFO): Sending 640 bytes from file Logs/20190419T202702/Express0008.lzma
2019-04-19T20:33:11.025Z,1555705991.025 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Express0008.lzma.bak
2019-04-19T20:33:11.025Z,1555705991.025 [DataOverHttps](INFO): SBD MOMSN=10666604
2019-04-19T20:33:11.796Z,1555705991.796 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:33:11.796Z,1555705991.796 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T20:33:11.796Z,1555705991.796 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:33:33.662Z,1555706013.662 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:33:33.666Z,1555706013.666 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:33:33.711Z,1555706013.711 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-19T20:33:33.723Z,1555706013.723 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-19T20:33:33.737Z,1555706013.737 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-19T20:33:33.752Z,1555706013.752 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-19T20:33:33.754Z,1555706013.754 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-19T20:33:33.755Z,1555706013.755 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-19T20:33:33.769Z,1555706013.769 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-19T20:33:33.808Z,1555706013.808 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-19T20:33:33.812Z,1555706013.812 [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-19T20:33:33.814Z,1555706013.814 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:33:34.014Z,1555706014.014 [Default] Stopped
2019-04-19T20:33:34.014Z,1555706014.014 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T20:33:34.014Z,1555706014.014 [Default:B.GoToSurface] Stopped
2019-04-19T20:33:34.014Z,1555706014.014 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T20:33:34.014Z,1555706014.014 [Default:CheckIn] Stopped
2019-04-19T20:33:34.015Z,1555706014.015 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T20:33:34.015Z,1555706014.015 [Default:CheckIn:C.Wait] Stopped
2019-04-19T20:33:34.015Z,1555706014.015 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:33:34.015Z,1555706014.015 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-19T20:33:34.016Z,1555706014.016 [DUSBL] Running Loop=1
2019-04-19T20:33:34.016Z,1555706014.016 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-19T20:33:34.016Z,1555706014.016 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:33:34.016Z,1555706014.016 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-19T20:33:34.016Z,1555706014.016 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:33:34.016Z,1555706014.016 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-19T20:33:34.016Z,1555706014.016 [DUSBL:C] Running Loop=1
2019-04-19T20:33:34.017Z,1555706014.017 [DUSBL:RequestRepeater] Running Loop=1
2019-04-19T20:33:34.017Z,1555706014.017 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:33:34.017Z,1555706014.017 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:33:34.017Z,1555706014.017 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:33:34.017Z,1555706014.017 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:33:34.017Z,1555706014.017 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:33:34.017Z,1555706014.017 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:33:34.018Z,1555706014.018 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:33:34.018Z,1555706014.018 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-19T20:33:34.019Z,1555706014.019 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-19T20:33:34.019Z,1555706014.019 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:33:34.019Z,1555706014.019 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:33:35.602Z,1555706015.602 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:36.005Z,1555706016.005 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:33:36.409Z,1555706016.409 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:40.449Z,1555706020.449 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:40.941Z,1555706020.941 [Micromodem](ERROR): Response from modem unexpected: $CATMG,2019-04-19T20:33:36Z,USER_CMD,RTC*3E

2019-04-19T20:33:44.158Z,1555706024.158 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:33:44.158Z,1555706024.158 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:33:44.158Z,1555706024.158 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:33:44.159Z,1555706024.159 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:33:44.175Z,1555706024.175 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:33:44.175Z,1555706024.175 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater] Running Loop=2
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:33:44.176Z,1555706024.176 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:33:44.509Z,1555706024.509 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:44.913Z,1555706024.913 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:33:45.317Z,1555706025.317 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:45.725Z,1555706025.725 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:33:45.727Z,1555706025.727 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203344.82*56

2019-04-19T20:33:49.357Z,1555706029.357 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:49.392Z,1555706029.392 [NAL9602](INFO): SBD MO Status=0, MOMSN=3512, MT Status=0, MTMSN=0
2019-04-19T20:33:49.393Z,1555706029.393 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:33:49.760Z,1555706029.760 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:33:50.161Z,1555706030.161 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:50.565Z,1555706030.565 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:33:50.567Z,1555706030.567 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203349.67*50

2019-04-19T20:33:54.205Z,1555706034.205 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:54.611Z,1555706034.611 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:33:54.689Z,1555706034.689 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T20:33:54.689Z,1555706034.689 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:33:54.689Z,1555706034.689 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater] Running Loop=3
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:33:54.690Z,1555706034.690 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:33:54.691Z,1555706034.691 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:33:55.009Z,1555706035.009 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:55.417Z,1555706035.417 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:33:55.419Z,1555706035.419 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203354.52*5A

2019-04-19T20:33:59.049Z,1555706039.049 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:33:59.457Z,1555706039.457 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:33:59.858Z,1555706039.858 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:34:00.265Z,1555706040.265 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:34:00.267Z,1555706040.267 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203359.36*55

2019-04-19T20:34:02.537Z,1555706042.537 [CommandLine](IMPORTANT): got command stop
2019-04-19T20:34:02.538Z,1555706042.538 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-19T20:34:02.754Z,1555706042.754 [MissionManager](INFO): MissionManager is completed.
2019-04-19T20:34:02.754Z,1555706042.754 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-19T20:34:02.754Z,1555706042.754 [DUSBL] Stopped
2019-04-19T20:34:02.754Z,1555706042.754 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-19T20:34:02.754Z,1555706042.754 [DUSBL:A.Pitch] Stopped
2019-04-19T20:34:02.754Z,1555706042.754 [DUSBL:B.SetSpeed] Stopped
2019-04-19T20:34:02.754Z,1555706042.754 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-19T20:34:02.755Z,1555706042.755 [DUSBL:C] Stopped
2019-04-19T20:34:02.755Z,1555706042.755 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:34:02.755Z,1555706042.755 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:34:02.755Z,1555706042.755 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:34:02.755Z,1555706042.755 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:34:02.755Z,1555706042.755 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:34:02.755Z,1555706042.755 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:34:03.142Z,1555706043.142 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T20:34:03.143Z,1555706043.143 [Default] Running Loop=1
2019-04-19T20:34:03.143Z,1555706043.143 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T20:34:03.143Z,1555706043.143 [Default:B.GoToSurface] Running Loop=1
2019-04-19T20:34:03.143Z,1555706043.143 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:34:03.156Z,1555706043.156 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:34:03.156Z,1555706043.156 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:34:03.156Z,1555706043.156 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:34:03.157Z,1555706043.157 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:34:03.157Z,1555706043.157 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:34:03.157Z,1555706043.157 [Default:A.Wait] Running Loop=1
2019-04-19T20:34:03.157Z,1555706043.157 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:34:16.448Z,1555706056.448 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T20:34:16.448Z,1555706056.448 [Default:A.Wait] Stopped
2019-04-19T20:34:16.448Z,1555706056.448 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:34:16.867Z,1555706056.867 [Default:CheckIn] Running Loop=1
2019-04-19T20:34:16.867Z,1555706056.867 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:34:16.883Z,1555706056.883 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:34:18.459Z,1555706058.459 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:34:18.847Z,1555706058.847 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203418.00,A,3648.15694,N,12147.20781,W,0.253,327.87,190419,,,A*72
2019-04-19T20:34:18.865Z,1555706058.865 [NAL9602](INFO): GPS fix at 20190419T203418: (36.802616, -121.786797)
2019-04-19T20:34:18.923Z,1555706058.923 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:34:18.923Z,1555706058.923 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:34:24.471Z,1555706064.471 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190419T202702/Courier0010.lzma
2019-04-19T20:34:25.277Z,1555706065.277 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Courier0010.lzma.bak
2019-04-19T20:34:25.277Z,1555706065.277 [DataOverHttps](INFO): SBD MOMSN=10666622
2019-04-19T20:34:37.575Z,1555706077.575 [DataOverHttps](INFO): Sending 333 bytes from file Logs/20190419T202702/Express0011.lzma
2019-04-19T20:34:38.381Z,1555706078.381 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Express0011.lzma.bak
2019-04-19T20:34:38.381Z,1555706078.381 [DataOverHttps](INFO): SBD MOMSN=10666625
2019-04-19T20:34:39.084Z,1555706079.084 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:34:39.084Z,1555706079.084 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T20:34:39.084Z,1555706079.084 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:34:41.083Z,1555706081.083 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:34:50.814Z,1555706090.814 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:34:51.573Z,1555706091.573 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:35:00.898Z,1555706100.898 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:35:11.000Z,1555706111.000 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:35:21.086Z,1555706121.086 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:35:31.190Z,1555706131.190 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:35:41.280Z,1555706141.280 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:35:50.981Z,1555706150.981 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:36:01.073Z,1555706161.073 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:36:11.176Z,1555706171.176 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:36:20.881Z,1555706180.881 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:36:30.564Z,1555706190.564 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:36:40.268Z,1555706200.268 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:36:50.376Z,1555706210.376 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:37:00.477Z,1555706220.477 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:37:35.883Z,1555706255.883 [CommandLine](IMPORTANT): got command show stack
2019-04-19T20:37:35.883Z,1555706255.883 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-19T20:37:35.884Z,1555706255.884 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-04-19T20:37:35.884Z,1555706255.884 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-04-19T20:37:39.084Z,1555706259.084 [CommandLine](IMPORTANT): got command failComponent
2019-04-19T20:37:39.085Z,1555706259.085 [CommandLine](IMPORTANT): Failed components:
2019-04-19T20:37:39.085Z,1555706259.085 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2019-04-19T20:37:49.657Z,1555706269.657 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:37:49.659Z,1555706269.659 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:37:49.688Z,1555706269.688 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-19T20:37:49.690Z,1555706269.690 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-19T20:37:49.692Z,1555706269.692 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-19T20:37:49.694Z,1555706269.694 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-19T20:37:49.697Z,1555706269.697 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-19T20:37:49.698Z,1555706269.698 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-19T20:37:49.702Z,1555706269.702 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-19T20:37:49.710Z,1555706269.710 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-19T20:37:49.714Z,1555706269.714 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

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

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><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-19T20:37:49.733Z,1555706269.733 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-19T20:37:49.807Z,1555706269.807 [Default] Stopped
2019-04-19T20:37:49.807Z,1555706269.807 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T20:37:49.819Z,1555706269.819 [Default:B.GoToSurface] Stopped
2019-04-19T20:37:49.819Z,1555706269.819 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T20:37:49.820Z,1555706269.820 [Default:CheckIn] Stopped
2019-04-19T20:37:49.820Z,1555706269.820 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T20:37:49.820Z,1555706269.820 [Default:CheckIn:C.Wait] Stopped
2019-04-19T20:37:49.820Z,1555706269.820 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:37:49.820Z,1555706269.820 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-19T20:37:49.820Z,1555706269.820 [DUSBL] Running Loop=1
2019-04-19T20:37:49.820Z,1555706269.820 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-19T20:37:49.820Z,1555706269.820 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:C] Running Loop=1
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:RequestRepeater] Running Loop=1
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:37:49.821Z,1555706269.821 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:37:49.822Z,1555706269.822 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T20:37:49.822Z,1555706269.822 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:37:49.822Z,1555706269.822 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T20:37:49.822Z,1555706269.822 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T20:37:49.823Z,1555706269.823 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-19T20:37:49.832Z,1555706269.832 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-19T20:37:49.832Z,1555706269.832 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T20:37:49.832Z,1555706269.832 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T20:37:51.365Z,1555706271.365 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:37:51.760Z,1555706271.760 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T20:37:52.160Z,1555706272.160 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:37:52.566Z,1555706272.566 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T20:37:52.568Z,1555706272.568 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,203751.68*52

2019-04-19T20:37:56.086Z,1555706276.086 [CommandLine](IMPORTANT): got command stop
2019-04-19T20:37:56.086Z,1555706276.086 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-19T20:37:56.197Z,1555706276.197 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T20:37:56.280Z,1555706276.280 [MissionManager](INFO): MissionManager is completed.
2019-04-19T20:37:56.280Z,1555706276.280 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-19T20:37:56.280Z,1555706276.280 [DUSBL] Stopped
2019-04-19T20:37:56.280Z,1555706276.280 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-19T20:37:56.280Z,1555706276.280 [DUSBL:A.Pitch] Stopped
2019-04-19T20:37:56.280Z,1555706276.280 [DUSBL:B.SetSpeed] Stopped
2019-04-19T20:37:56.280Z,1555706276.280 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-19T20:37:56.280Z,1555706276.280 [DUSBL:C] Stopped
2019-04-19T20:37:56.281Z,1555706276.281 [DUSBL:RequestRepeater] Stopped
2019-04-19T20:37:56.281Z,1555706276.281 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T20:37:56.281Z,1555706276.281 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T20:37:56.281Z,1555706276.281 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T20:37:56.281Z,1555706276.281 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T20:37:56.281Z,1555706276.281 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:37:56.666Z,1555706276.666 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T20:37:56.666Z,1555706276.666 [Default] Running Loop=1
2019-04-19T20:37:56.666Z,1555706276.666 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T20:37:56.666Z,1555706276.666 [Default:B.GoToSurface] Running Loop=1
2019-04-19T20:37:56.666Z,1555706276.666 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:37:56.667Z,1555706276.667 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:37:56.667Z,1555706276.667 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:37:56.668Z,1555706276.668 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:37:56.668Z,1555706276.668 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:37:56.668Z,1555706276.668 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:37:56.669Z,1555706276.669 [Default:A.Wait] Running Loop=1
2019-04-19T20:37:56.669Z,1555706276.669 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:38:09.978Z,1555706289.978 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T20:38:09.978Z,1555706289.978 [Default:A.Wait] Stopped
2019-04-19T20:38:09.979Z,1555706289.979 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:38:10.381Z,1555706290.381 [Default:CheckIn] Running Loop=1
2019-04-19T20:38:10.381Z,1555706290.381 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:38:10.381Z,1555706290.381 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:38:11.967Z,1555706291.967 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:38:12.363Z,1555706292.363 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203811.00,A,3648.15763,N,12147.20767,W,0.156,327.87,190419,,,A*70
2019-04-19T20:38:12.365Z,1555706292.365 [NAL9602](INFO): GPS fix at 20190419T203811: (36.802627, -121.786794)
2019-04-19T20:38:12.395Z,1555706292.395 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:38:12.395Z,1555706292.395 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:38:16.003Z,1555706296.003 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190419T202702/Courier0013.lzma
2019-04-19T20:38:16.809Z,1555706296.809 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Courier0013.lzma.bak
2019-04-19T20:38:16.809Z,1555706296.809 [DataOverHttps](INFO): SBD MOMSN=10666651
2019-04-19T20:38:24.637Z,1555706304.637 [NAL9602](INFO): SBD MO Status=0, MOMSN=3513, MT Status=0, MTMSN=0
2019-04-19T20:38:24.638Z,1555706304.638 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:38:28.732Z,1555706308.732 [DataOverHttps](INFO): Sending 694 bytes from file Logs/20190419T202702/Express0014.lzma
2019-04-19T20:38:29.537Z,1555706309.537 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Express0014.lzma.bak
2019-04-19T20:38:29.537Z,1555706309.537 [DataOverHttps](INFO): SBD MOMSN=10666654
2019-04-19T20:38:30.306Z,1555706310.306 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:38:30.307Z,1555706310.307 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T20:38:30.307Z,1555706310.307 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:38:55.325Z,1555706335.325 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:39:32.153Z,1555706372.153 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:39:42.272Z,1555706382.272 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:39:51.979Z,1555706391.979 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:40:01.800Z,1555706401.800 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:40:11.928Z,1555706411.928 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:40:22.115Z,1555706422.115 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:40:32.075Z,1555706432.075 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:40:42.198Z,1555706442.198 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:40:52.256Z,1555706452.256 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:41:02.354Z,1555706462.354 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:41:07.028Z,1555706467.028 [CommandLine](IMPORTANT): got command restart application
2019-04-19T20:41:08.044Z,1555706468.044 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:08.044Z,1555706468.044 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.091Z,1555706468.091 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-04-19T20:41:08.091Z,1555706468.091 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.092Z,1555706468.092 [CommandLine](INFO): Join timeout helper Thread ID is 5201
2019-04-19T20:41:08.093Z,1555706468.093 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-04-19T20:41:08.093Z,1555706468.093 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.093Z,1555706468.093 [NavChartDb](INFO): Join timeout helper Thread ID is 5202
2019-04-19T20:41:08.172Z,1555706468.172 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:08.172Z,1555706468.172 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.191Z,1555706468.191 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-04-19T20:41:08.191Z,1555706468.191 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.192Z,1555706468.192 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 5203
2019-04-19T20:41:08.395Z,1555706468.395 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:08.396Z,1555706468.396 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-19T20:41:08.396Z,1555706468.396 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.399Z,1555706468.399 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-04-19T20:41:08.399Z,1555706468.399 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.400Z,1555706468.400 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5204
2019-04-19T20:41:08.432Z,1555706468.432 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:08.432Z,1555706468.432 [CTD_NeilBrown](INFO): Powering down
2019-04-19T20:41:08.443Z,1555706468.443 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.452Z,1555706468.452 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-04-19T20:41:08.452Z,1555706468.452 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.452Z,1555706468.452 [Radio_Surface](INFO): Join timeout helper Thread ID is 5205
2019-04-19T20:41:08.847Z,1555706468.847 [Radio_Surface](INFO): Powering down
2019-04-19T20:41:08.848Z,1555706468.848 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:08.849Z,1555706468.849 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.850Z,1555706468.850 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-04-19T20:41:08.850Z,1555706468.850 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.851Z,1555706468.851 [DataOverHttps](INFO): Join timeout helper Thread ID is 5206
2019-04-19T20:41:08.924Z,1555706468.924 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:08.924Z,1555706468.924 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.936Z,1555706468.936 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-04-19T20:41:08.936Z,1555706468.936 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.937Z,1555706468.937 [logger](INFO): Join timeout helper Thread ID is 5207
2019-04-19T20:41:08.943Z,1555706468.943 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:08.944Z,1555706468.944 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.956Z,1555706468.956 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-04-19T20:41:08.956Z,1555706468.956 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.956Z,1555706468.956 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-04-19T20:41:08.956Z,1555706468.956 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:08.957Z,1555706468.957 [controlThread](INFO): Join timeout helper Thread ID is 5208
2019-04-19T20:41:09.191Z,1555706469.191 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T20:41:09.192Z,1555706469.192 [controlThread](DEBUG): Uninitializing ControlThread
2019-04-19T20:41:09.192Z,1555706469.192 [AHRS_M2](INFO): Powering down
2019-04-19T20:41:09.264Z,1555706469.264 [DUSBL_Hydroid](INFO): Powering down
2019-04-19T20:41:09.336Z,1555706469.336 [Micromodem](INFO): Powering down
2019-04-19T20:41:09.432Z,1555706469.432 [NAL9602](INFO): Powering down
2019-04-19T20:41:09.503Z,1555706469.503 [RDI_Pathfinder](INFO): Powering down
2019-04-19T20:41:09.505Z,1555706469.505 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-04-19T20:41:09.506Z,1555706469.506 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-04-19T20:41:09.507Z,1555706469.507 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-04-19T20:41:09.507Z,1555706469.507 [MissionManager](INFO): Uninitializing Mission Default
2019-04-19T20:41:09.507Z,1555706469.507 [Default] Stopped
2019-04-19T20:41:09.507Z,1555706469.507 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T20:41:09.507Z,1555706469.507 [Default:B.GoToSurface] Stopped
2019-04-19T20:41:09.507Z,1555706469.507 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T20:41:09.508Z,1555706469.508 [Default:CheckIn] Stopped
2019-04-19T20:41:09.508Z,1555706469.508 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T20:41:09.508Z,1555706469.508 [Default:CheckIn:C.Wait] Stopped
2019-04-19T20:41:09.508Z,1555706469.508 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:41:09.510Z,1555706469.510 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-04-19T20:41:09.510Z,1555706469.510 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-04-19T20:41:09.511Z,1555706469.511 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-04-19T20:41:09.511Z,1555706469.511 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-04-19T20:41:09.511Z,1555706469.511 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-04-19T20:41:09.511Z,1555706469.511 [BuoyancyServo](INFO): Powering down
2019-04-19T20:41:09.523Z,1555706469.523 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-04-19T20:41:09.524Z,1555706469.524 [ElevatorServo](INFO): Powering down
2019-04-19T20:41:09.524Z,1555706469.524 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-04-19T20:41:09.524Z,1555706469.524 [MassServo](INFO): Powering down
2019-04-19T20:41:09.525Z,1555706469.525 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-19T20:41:09.525Z,1555706469.525 [RudderServo](INFO): Powering down
2019-04-19T20:41:09.526Z,1555706469.526 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-04-19T20:41:09.526Z,1555706469.526 [ThrusterServo](INFO): Powering down
2019-04-19T20:41:09.527Z,1555706469.527 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-04-19T20:41:09.527Z,1555706469.527 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-04-19T20:41:09.528Z,1555706469.528 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-04-19T20:41:09.528Z,1555706469.528 [CBIT](DEBUG): Powering off loads.
2019-04-19T20:41:09.539Z,1555706469.539 [CBIT](DEBUG): Disabling WDT.
2019-04-19T20:41:09.551Z,1555706469.551 [CBIT](DEBUG): Opening all GF detection circuits.
2019-04-19T20:41:09.552Z,1555706469.552 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:09.595Z,1555706469.595 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:09.604Z,1555706469.604 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:09.652Z,1555706469.652 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:09.654Z,1555706469.654 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:09.728Z,1555706469.728 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-19T20:41:09.797Z,1555706469.797 [logger ThreadHandler](INFO): Thread cancelled.