2019-04-19T20:41:10.909Z,1555706470.909 [Supervisor](DEBUG): Initializing supervisor.
2019-04-19T20:41:10.912Z,1555706470.912 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-19T20:41:10.912Z,1555706470.912 [SyncHandler](INFO): Protected caller Thread ID is 5209
2019-04-19T20:41:10.913Z,1555706470.913 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-19T20:41:10.914Z,1555706470.914 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-19T20:41:10.914Z,1555706470.914 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5210
2019-04-19T20:41:10.917Z,1555706470.917 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-19T20:41:10.929Z,1555706470.929 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-19T20:41:10.930Z,1555706470.930 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-19T20:41:10.930Z,1555706470.930 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5211
2019-04-19T20:41:10.931Z,1555706470.931 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-19T20:41:10.932Z,1555706470.932 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-19T20:41:10.933Z,1555706470.933 [logger ThreadHandler](INFO): Protected caller Thread ID is 5212
2019-04-19T20:41:10.934Z,1555706470.934 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-19T20:41:10.935Z,1555706470.935 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-19T20:41:10.937Z,1555706470.937 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-19T20:41:11.428Z,1555706471.428 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-19T20:41:11.428Z,1555706471.428 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-19T20:41:11.529Z,1555706471.529 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-19T20:41:11.529Z,1555706471.529 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-19T20:41:11.857Z,1555706471.857 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-19T20:41:11.858Z,1555706471.858 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-19T20:41:12.002Z,1555706472.002 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-19T20:41:12.003Z,1555706472.003 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-19T20:41:12.200Z,1555706472.200 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-19T20:41:12.201Z,1555706472.201 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-19T20:41:12.712Z,1555706472.712 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-19T20:41:12.713Z,1555706472.713 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-19T20:41:12.926Z,1555706472.926 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-19T20:41:12.926Z,1555706472.926 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-19T20:41:13.075Z,1555706473.075 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-19T20:41:13.075Z,1555706473.075 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-19T20:41:13.272Z,1555706473.272 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-19T20:41:13.273Z,1555706473.273 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-19T20:41:13.371Z,1555706473.371 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-19T20:41:13.372Z,1555706473.372 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-19T20:41:13.696Z,1555706473.696 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-19T20:41:13.696Z,1555706473.696 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-19T20:41:13.780Z,1555706473.780 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-19T20:41:13.885Z,1555706473.885 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-19T20:41:13.886Z,1555706473.886 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-19T20:41:14.417Z,1555706474.417 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-19T20:41:14.418Z,1555706474.418 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-19T20:41:14.814Z,1555706474.814 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-19T20:41:14.816Z,1555706474.816 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-19T20:41:14.817Z,1555706474.817 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-19T20:41:15.028Z,1555706475.028 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-19T20:41:15.132Z,1555706475.132 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-19T20:41:15.234Z,1555706475.234 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-19T20:41:15.463Z,1555706475.463 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-19T20:41:15.464Z,1555706475.464 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-19T20:41:15.551Z,1555706475.551 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-19T20:41:15.648Z,1555706475.648 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-19T20:41:15.747Z,1555706475.747 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-19T20:41:15.947Z,1555706475.947 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-19T20:41:16.561Z,1555706476.561 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-19T20:41:17.398Z,1555706477.398 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-19T20:41:17.860Z,1555706477.860 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-19T20:41:18.255Z,1555706478.255 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-19T20:41:18.711Z,1555706478.711 [AHRS_M2] Loaded
2019-04-19T20:41:18.711Z,1555706478.711 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-19T20:41:18.783Z,1555706478.783 [DataOverHttps] Loaded
2019-04-19T20:41:18.784Z,1555706478.784 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-19T20:41:18.785Z,1555706478.785 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-04-19T20:41:18.785Z,1555706478.785 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5291
2019-04-19T20:41:18.798Z,1555706478.798 [Depth_Keller] Loaded
2019-04-19T20:41:18.798Z,1555706478.798 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-19T20:41:18.803Z,1555706478.803 [DropWeight] Loaded
2019-04-19T20:41:18.803Z,1555706478.803 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-19T20:41:18.858Z,1555706478.858 [DUSBL_Hydroid] Loaded
2019-04-19T20:41:18.858Z,1555706478.858 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-19T20:41:18.897Z,1555706478.897 [Micromodem] Loaded
2019-04-19T20:41:18.897Z,1555706478.897 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-19T20:41:18.992Z,1555706478.992 [NAL9602] Loaded
2019-04-19T20:41:18.992Z,1555706478.992 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-19T20:41:19.008Z,1555706479.008 [Onboard] Loaded
2019-04-19T20:41:19.008Z,1555706479.008 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-19T20:41:19.014Z,1555706479.014 [PowerOnly] Loaded
2019-04-19T20:41:19.014Z,1555706479.014 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-19T20:41:19.020Z,1555706479.020 [Radio_Surface] Loaded
2019-04-19T20:41:19.021Z,1555706479.021 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-19T20:41:19.022Z,1555706479.022 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-04-19T20:41:19.022Z,1555706479.022 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5292
2019-04-19T20:41:19.064Z,1555706479.064 [RDI_Pathfinder] Loaded
2019-04-19T20:41:19.065Z,1555706479.065 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-19T20:41:20.518Z,1555706480.518 [BPC1] Loaded
2019-04-19T20:41:20.518Z,1555706480.518 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-19T20:41:20.518Z,1555706480.518 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-19T20:41:20.519Z,1555706480.519 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-19T20:41:20.542Z,1555706480.542 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-19T20:41:20.543Z,1555706480.543 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-19T20:41:20.662Z,1555706480.662 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-19T20:41:20.663Z,1555706480.663 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-19T20:41:20.683Z,1555706480.683 [NavChart] Loaded
2019-04-19T20:41:20.683Z,1555706480.683 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-19T20:41:20.687Z,1555706480.687 [UniversalFixResidualReporter] Loaded
2019-04-19T20:41:20.687Z,1555706480.687 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-19T20:41:20.688Z,1555706480.688 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-19T20:41:20.688Z,1555706480.688 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-19T20:41:20.817Z,1555706480.817 [BuoyancyServo] Loaded
2019-04-19T20:41:20.818Z,1555706480.818 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-19T20:41:20.833Z,1555706480.833 [ElevatorServo] Loaded
2019-04-19T20:41:20.833Z,1555706480.833 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-19T20:41:20.833Z,1555706480.833 [Module Loader](CRITICAL): Could not find element LineCaptureServo.loadAtStartup
2019-04-19T20:41:20.847Z,1555706480.847 [MassServo] Loaded
2019-04-19T20:41:20.848Z,1555706480.848 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-19T20:41:20.862Z,1555706480.862 [RudderServo] Loaded
2019-04-19T20:41:20.863Z,1555706480.863 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-19T20:41:20.877Z,1555706480.877 [ThrusterServo] Loaded
2019-04-19T20:41:20.877Z,1555706480.877 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-19T20:41:20.877Z,1555706480.877 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-19T20:41:20.878Z,1555706480.878 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-19T20:41:21.193Z,1555706481.193 [CTD_NeilBrown] Loaded
2019-04-19T20:41:21.193Z,1555706481.193 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-19T20:41:21.194Z,1555706481.194 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-04-19T20:41:21.194Z,1555706481.194 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5293
2019-04-19T20:41:21.238Z,1555706481.238 [WetLabsSeaOWL_UV_A] Loaded
2019-04-19T20:41:21.238Z,1555706481.238 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-19T20:41:21.239Z,1555706481.239 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-04-19T20:41:21.240Z,1555706481.240 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 5294
2019-04-19T20:41:21.240Z,1555706481.240 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-19T20:41:21.241Z,1555706481.241 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-19T20:41:21.571Z,1555706481.571 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-19T20:41:21.572Z,1555706481.572 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-19T20:41:21.626Z,1555706481.626 [DepthRateCalculator] Loaded
2019-04-19T20:41:21.626Z,1555706481.626 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-19T20:41:21.632Z,1555706481.632 [PitchRateCalculator] Loaded
2019-04-19T20:41:21.632Z,1555706481.632 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-19T20:41:21.644Z,1555706481.644 [SpeedCalculator] Loaded
2019-04-19T20:41:21.644Z,1555706481.644 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-19T20:41:21.665Z,1555706481.665 [TempGradientCalculator] Loaded
2019-04-19T20:41:21.665Z,1555706481.665 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-19T20:41:21.670Z,1555706481.670 [YawRateCalculator] Loaded
2019-04-19T20:41:21.671Z,1555706481.671 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-19T20:41:21.710Z,1555706481.710 [ElevatorOffsetCalculator] Loaded
2019-04-19T20:41:21.711Z,1555706481.711 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-19T20:41:21.711Z,1555706481.711 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-19T20:41:21.712Z,1555706481.712 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-19T20:41:21.867Z,1555706481.867 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-19T20:41:21.889Z,1555706481.889 [SBIT] Loaded
2019-04-19T20:41:21.889Z,1555706481.889 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-19T20:41:21.890Z,1555706481.890 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-19T20:41:21.901Z,1555706481.901 [IBIT] Loaded
2019-04-19T20:41:21.901Z,1555706481.901 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-19T20:41:21.904Z,1555706481.904 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-19T20:41:22.039Z,1555706482.039 [CBIT] Loaded
2019-04-19T20:41:22.039Z,1555706482.039 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-19T20:41:22.040Z,1555706482.040 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-19T20:41:22.041Z,1555706482.041 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-19T20:41:22.149Z,1555706482.149 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-19T20:41:22.150Z,1555706482.150 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-19T20:41:22.273Z,1555706482.273 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-19T20:41:22.273Z,1555706482.273 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-19T20:41:22.358Z,1555706482.358 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-19T20:41:22.439Z,1555706482.439 [VerticalControl] Loaded
2019-04-19T20:41:22.440Z,1555706482.440 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-19T20:41:22.440Z,1555706482.440 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-19T20:41:22.497Z,1555706482.497 [HorizontalControl] Loaded
2019-04-19T20:41:22.497Z,1555706482.497 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-19T20:41:22.498Z,1555706482.498 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-19T20:41:22.499Z,1555706482.499 [SpeedControl] Loaded
2019-04-19T20:41:22.500Z,1555706482.500 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-19T20:41:22.500Z,1555706482.500 [LoopControl](DEBUG): Construct LoopControl.
2019-04-19T20:41:22.501Z,1555706482.501 [LoopControl] Loaded
2019-04-19T20:41:22.501Z,1555706482.501 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-19T20:41:22.502Z,1555706482.502 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-19T20:41:22.502Z,1555706482.502 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-19T20:41:22.556Z,1555706482.556 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-19T20:41:22.560Z,1555706482.560 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-19T20:41:22.561Z,1555706482.561 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-19T20:41:22.568Z,1555706482.568 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-19T20:41:22.569Z,1555706482.569 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-04-19T20:41:22.569Z,1555706482.569 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5295
2019-04-19T20:41:22.574Z,1555706482.574 [Supervisor](INFO): Main Thread ID is 5034
2019-04-19T20:41:22.574Z,1555706482.574 [Supervisor](DEBUG): Running supervisor.
2019-04-19T20:41:22.574Z,1555706482.574 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5296
2019-04-19T20:41:22.577Z,1555706482.577 [controlThread ThreadHandler](INFO): Handler Thread ID is 5297
2019-04-19T20:41:22.577Z,1555706482.577 [controlThread](DEBUG): Initializing ControlThread
2019-04-19T20:41:22.583Z,1555706482.583 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-19T20:41:22.583Z,1555706482.583 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-19T20:41:22.584Z,1555706482.584 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-19T20:41:22.585Z,1555706482.585 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-19T20:41:22.585Z,1555706482.585 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-19T20:41:22.585Z,1555706482.585 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-19T20:41:22.586Z,1555706482.586 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-19T20:41:22.586Z,1555706482.586 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-19T20:41:22.587Z,1555706482.587 [SBIT](INFO): Initialize SBIT Component.
2019-04-19T20:41:22.587Z,1555706482.587 [SBIT](IMPORTANT): git: 2019-04-10-14-g08d638a
2019-04-19T20:41:22.588Z,1555706482.588 [SBIT](INFO): git hash: 08d638a599400f5b89d801042872eecc619e609b
2019-04-19T20:41:22.588Z,1555706482.588 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-19T20:41:22.588Z,1555706482.588 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-19T20:41:22.589Z,1555706482.589 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-04-19T20:41:22.590Z,1555706482.590 [IBIT](INFO): Initialize IBIT Component.
2019-04-19T20:41:22.591Z,1555706482.591 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-19T20:41:22.592Z,1555706482.592 [logger ThreadHandler](INFO): Handler Thread ID is 5298
2019-04-19T20:41:22.603Z,1555706482.603 [CBIT](DEBUG): Initialized mux pins.
2019-04-19T20:41:22.603Z,1555706482.603 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-19T20:41:22.612Z,1555706482.612 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5299
2019-04-19T20:41:22.613Z,1555706482.613 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-19T20:41:22.624Z,1555706482.624 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5300
2019-04-19T20:41:22.627Z,1555706482.627 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-19T20:41:22.628Z,1555706482.628 [CBIT](DEBUG): Initializing heartbeat.
2019-04-19T20:41:22.644Z,1555706482.644 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5301
2019-04-19T20:41:22.645Z,1555706482.645 [CTD_NeilBrown](INFO): Powering down
2019-04-19T20:41:22.676Z,1555706482.676 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 5302
2019-04-19T20:41:22.677Z,1555706482.677 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-19T20:41:22.699Z,1555706482.699 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-19T20:41:22.699Z,1555706482.699 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-19T20:41:22.704Z,1555706482.704 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5303
2019-04-19T20:41:22.710Z,1555706482.710 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-19T20:41:22.710Z,1555706482.710 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-19T20:41:22.710Z,1555706482.710 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-19T20:41:22.710Z,1555706482.710 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-19T20:41:22.710Z,1555706482.710 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-19T20:41:22.711Z,1555706482.711 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-19T20:41:22.711Z,1555706482.711 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-19T20:41:22.711Z,1555706482.711 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-19T20:41:22.711Z,1555706482.711 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-19T20:41:22.712Z,1555706482.712 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-19T20:41:22.712Z,1555706482.712 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-19T20:41:22.712Z,1555706482.712 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-19T20:41:22.712Z,1555706482.712 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-19T20:41:22.712Z,1555706482.712 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-19T20:41:22.712Z,1555706482.712 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-19T20:41:22.713Z,1555706482.713 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-19T20:41:22.735Z,1555706482.735 [CBIT](DEBUG): Backplane powered.
2019-04-19T20:41:22.736Z,1555706482.736 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-19T20:41:22.737Z,1555706482.737 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-19T20:41:22.738Z,1555706482.738 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-19T20:41:22.739Z,1555706482.739 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-19T20:41:22.740Z,1555706482.740 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-19T20:41:22.753Z,1555706482.753 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-19T20:41:22.785Z,1555706482.785 [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:41:22.786Z,1555706482.786 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-19T20:41:22.838Z,1555706482.838 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-19T20:41:22.839Z,1555706482.839 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-19T20:41:22.857Z,1555706482.857 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-19T20:41:22.880Z,1555706482.880 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-19T20:41:22.882Z,1555706482.882 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-19T20:41:22.904Z,1555706482.904 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-19T20:41:22.923Z,1555706482.923 [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:41:22.928Z,1555706482.928 [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:41:22.946Z,1555706482.946 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-19T20:41:23.005Z,1555706483.005 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-19T20:41:23.005Z,1555706483.005 [DUSBL_Hydroid](INFO): Powering up
2019-04-19T20:41:23.006Z,1555706483.006 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-19T20:41:23.027Z,1555706483.027 [Radio_Surface](INFO): Powering up
2019-04-19T20:41:23.081Z,1555706483.081 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-19T20:41:23.095Z,1555706483.095 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:41:23.104Z,1555706483.104 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-19T20:41:23.105Z,1555706483.105 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:41:23.112Z,1555706483.112 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-19T20:41:23.113Z,1555706483.113 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:41:23.120Z,1555706483.120 [MassServo](DEBUG): Initializing MassServo.
2019-04-19T20:41:23.121Z,1555706483.121 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:41:23.128Z,1555706483.128 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-19T20:41:23.128Z,1555706483.128 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:41:23.136Z,1555706483.136 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-19T20:41:23.138Z,1555706483.138 [CommandLine](FAULT): Scheduling is paused
2019-04-19T20:41:23.138Z,1555706483.138 [CBIT](INFO): Critical error at 20190419T204120
2019-04-19T20:41:23.138Z,1555706483.138 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-04-19T20:41:23.352Z,1555706483.352 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-04-19T20:41:23.352Z,1555706483.352 [DropWeight] Hardware Fault, FailCount= 1
2019-04-19T20:41:23.352Z,1555706483.352 [DropWeight](ERROR): Hardware Fault
2019-04-19T20:41:23.354Z,1555706483.354 [Micromodem](INFO): Powering up
2019-04-19T20:41:23.354Z,1555706483.354 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-19T20:41:23.388Z,1555706483.388 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-19T20:41:23.396Z,1555706483.396 [CBIT](INFO): Critical error at 20190419T204123
2019-04-19T20:41:23.399Z,1555706483.399 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-04-19T20:41:23.399Z,1555706483.399 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-04-19T20:41:24.071Z,1555706484.071 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-19T20:41:24.072Z,1555706484.072 [RudderServo](FAULT): Rudder failed to initialize
2019-04-19T20:41:24.072Z,1555706484.072 [RudderServo] Communications Fault, FailCount= 1
2019-04-19T20:41:24.072Z,1555706484.072 [RudderServo](ERROR): Communications Fault
2019-04-19T20:41:24.181Z,1555706484.181 [CBIT](INFO): Critical error at 20190419T204123
2019-04-19T20:41:24.184Z,1555706484.184 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-19T20:41:24.349Z,1555706484.349 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-19T20:41:24.349Z,1555706484.349 [RudderServo](INFO): Powering down
2019-04-19T20:41:25.038Z,1555706485.038 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-19T20:41:25.156Z,1555706485.156 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-19T20:41:25.161Z,1555706485.161 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-19T20:41:25.161Z,1555706485.161 [RudderServo] No Fault, FailCount= 1
2019-04-19T20:41:36.375Z,1555706496.375 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-19T20:41:41.202Z,1555706501.202 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-19T20:41:49.265Z,1555706509.265 [NAL9602](INFO): Powering up NAL9602
2019-04-19T20:42:00.177Z,1555706520.177 [NAL9602](INFO): NAL9602 initialized
2019-04-19T20:42:00.995Z,1555706520.995 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:42:07.094Z,1555706527.094 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-19T20:42:07.099Z,1555706527.099 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-19T20:42:18.124Z,1555706538.124 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.020170
CHAN A1 (24V): -0.026684
CHAN A2 (12V): -0.007017
CHAN A3 (5V): -0.001918
CHAN B0 (3.3V): 0.000143
CHAN B1 (3.15aV): -0.000310
CHAN B2 (3.15bV): 0.000090
CHAN B3 (GND): 0.001869
OPEN: 0.005806
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-19T20:43:00.326Z,1555706580.326 [SBIT](IMPORTANT): SBIT PASSED
2019-04-19T20:43:00.388Z,1555706580.388 [CommandLine](IMPORTANT): got command configSet list
2019-04-19T20:43:00.389Z,1555706580.389 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=90 count;

2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-04-19T20:43:00.390Z,1555706580.390 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-04-19T20:43:00.391Z,1555706580.391 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-04-19T20:43:00.391Z,1555706580.391 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-04-19T20:43:00.391Z,1555706580.391 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-04-19T20:43:00.391Z,1555706580.391 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-04-19T20:43:00.391Z,1555706580.391 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-04-19T20:43:00.723Z,1555706580.723 [MissionManager](IMPORTANT): Started mission Startup
2019-04-19T20:43:00.724Z,1555706580.724 [Startup] Running Loop=1
2019-04-19T20:43:00.724Z,1555706580.724 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-19T20:43:00.724Z,1555706580.724 [Startup:A.GoToSurface] Running Loop=1
2019-04-19T20:43:00.724Z,1555706580.724 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:43:00.725Z,1555706580.725 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:43:00.725Z,1555706580.725 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:43:00.725Z,1555706580.725 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:43:00.726Z,1555706580.726 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:43:00.726Z,1555706580.726 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:43:00.728Z,1555706580.728 [Startup:StartupSatComms] Running Loop=1
2019-04-19T20:43:00.728Z,1555706580.728 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-19T20:43:00.728Z,1555706580.728 [Startup:StartupSatComms:A] Running Loop=1
2019-04-19T20:43:01.137Z,1555706581.137 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-19T20:44:00.921Z,1555706640.921 [Startup:StartupSatComms:A](INFO): Timed out from 2019-04-19T20:43:00.7Z
2019-04-19T20:44:00.921Z,1555706640.921 [Startup:StartupSatComms:A] Stopped
2019-04-19T20:44:00.921Z,1555706640.921 [Startup:StartupSatComms:B] Running Loop=1
2019-04-19T20:44:01.339Z,1555706641.339 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-19T20:44:07.356Z,1555706647.356 [NAL9602](INFO): SBD MO Status=0, MOMSN=3514, MT Status=0, MTMSN=0
2019-04-19T20:44:07.356Z,1555706647.356 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:44:08.188Z,1555706648.188 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:44:08.227Z,1555706648.227 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,    +0,  +113,   +20,A
2019-04-19T20:44:08.571Z,1555706648.571 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204406.00,A,3648.15893,N,12147.21449,W,0.175,222.82,190419,,,A*73
2019-04-19T20:44:08.574Z,1555706648.574 [NAL9602](INFO): GPS fix at 20190419T204406: (36.802649, -121.786908)
2019-04-19T20:44:18.760Z,1555706658.760 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:44:19.146Z,1555706659.146 [NAL9602](INFO): SBD MO Status=1, MOMSN=3515, MT Status=0, MTMSN=0
2019-04-19T20:44:19.201Z,1555706659.201 [NAL9602](INFO): Sent 25 bytes from file Logs/20190419T202702/Courier0016.lzma
2019-04-19T20:44:19.201Z,1555706659.201 [NAL9602](INFO): Packets left to send: 0
2019-04-19T20:44:23.766Z,1555706663.766 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:44:27.360Z,1555706667.360 [NAL9602](INFO): SBD MO Status=1, MOMSN=3516, MT Status=0, MTMSN=0
2019-04-19T20:44:27.408Z,1555706667.408 [NAL9602](INFO): Sent 203 bytes from file Logs/20190419T204110/Courier0000.lzma
2019-04-19T20:44:27.408Z,1555706667.408 [NAL9602](INFO): Packets left to send: 0
2019-04-19T20:44:33.550Z,1555706673.550 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:44:36.758Z,1555706676.758 [NAL9602](INFO): SBD MO Status=1, MOMSN=3517, MT Status=0, MTMSN=0
2019-04-19T20:44:36.809Z,1555706676.809 [NAL9602](INFO): Sent 332 bytes from file Logs/20190419T202702/Express0017.lzma
2019-04-19T20:44:36.809Z,1555706676.809 [NAL9602](INFO): Packets left to send: 1
2019-04-19T20:44:43.375Z,1555706683.375 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:44:47.373Z,1555706687.373 [NAL9602](INFO): SBD MO Status=2, MOMSN=3518, MT Status=2, MTMSN=0
2019-04-19T20:44:47.374Z,1555706687.374 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T20:44:54.883Z,1555706694.883 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:44:59.829Z,1555706699.829 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004334
2019-04-19T20:45:01.327Z,1555706701.327 [Startup:StartupSatComms:B](INFO): Timed out from 2019-04-19T20:44:00.9Z
2019-04-19T20:45:01.327Z,1555706701.327 [Startup:StartupSatComms:B] Stopped
2019-04-19T20:45:01.327Z,1555706701.327 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-19T20:45:01.331Z,1555706701.331 [Startup:StartupSatComms] Stopped
2019-04-19T20:45:01.331Z,1555706701.331 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-19T20:45:01.332Z,1555706701.332 [Startup](INFO): Completed Startup
2019-04-19T20:45:01.332Z,1555706701.332 [MissionManager](INFO): Startup is completed.
2019-04-19T20:45:01.333Z,1555706701.333 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-19T20:45:01.333Z,1555706701.333 [Startup] Stopped
2019-04-19T20:45:01.333Z,1555706701.333 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-19T20:45:01.333Z,1555706701.333 [Startup:A.GoToSurface] Stopped
2019-04-19T20:45:01.333Z,1555706701.333 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T20:45:01.714Z,1555706701.714 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T20:45:01.715Z,1555706701.715 [Default] Running Loop=1
2019-04-19T20:45:01.715Z,1555706701.715 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T20:45:01.715Z,1555706701.715 [Default:B.GoToSurface] Running Loop=1
2019-04-19T20:45:01.715Z,1555706701.715 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T20:45:01.715Z,1555706701.715 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T20:45:01.716Z,1555706701.716 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T20:45:01.716Z,1555706701.716 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T20:45:01.716Z,1555706701.716 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T20:45:01.717Z,1555706701.717 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T20:45:01.717Z,1555706701.717 [Default:A.Wait] Running Loop=1
2019-04-19T20:45:01.717Z,1555706701.717 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:45:04.538Z,1555706704.538 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:45:05.396Z,1555706705.396 [DataOverHttps](INFO): Sending 369 bytes from file Logs/20190419T202702/Express0017.lzma
2019-04-19T20:45:05.730Z,1555706705.730 [NAL9602](INFO): SBD MO Status=1, MOMSN=3518, MT Status=0, MTMSN=0
2019-04-19T20:45:05.792Z,1555706705.792 [NAL9602](INFO): Sent 37 bytes from file Logs/20190419T202702/Express0017.lzma
2019-04-19T20:45:05.792Z,1555706705.792 [NAL9602](INFO): Packets left to send: 0
2019-04-19T20:45:06.203Z,1555706706.203 [DataOverHttps](INFO): Moved sent file to Logs/20190419T202702/Express0017.lzma.bak
2019-04-19T20:45:06.204Z,1555706706.204 [DataOverHttps](INFO): SBD MOMSN=10666804
2019-04-19T20:45:14.629Z,1555706714.629 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:45:15.067Z,1555706715.067 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T20:45:15.067Z,1555706715.067 [Default:A.Wait] Stopped
2019-04-19T20:45:15.067Z,1555706715.067 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:45:15.487Z,1555706715.487 [Default:CheckIn] Running Loop=1
2019-04-19T20:45:15.487Z,1555706715.487 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:45:15.487Z,1555706715.487 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:45:15.861Z,1555706715.861 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-19T20:45:17.051Z,1555706717.051 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:45:17.447Z,1555706717.447 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204515.00,A,3648.15887,N,12147.21463,W,0.272,222.82,190419,,,A*79
2019-04-19T20:45:17.450Z,1555706717.450 [NAL9602](INFO): GPS fix at 20190419T204515: (36.802648, -121.786911)
2019-04-19T20:45:17.483Z,1555706717.483 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:45:17.484Z,1555706717.484 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:45:17.896Z,1555706717.896 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-19T20:45:23.100Z,1555706723.100 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20190419T204110/Courier0004.lzma
2019-04-19T20:45:23.905Z,1555706723.905 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0004.lzma.bak
2019-04-19T20:45:23.905Z,1555706723.905 [DataOverHttps](INFO): SBD MOMSN=10666807
2019-04-19T20:45:24.752Z,1555706724.752 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:45:34.465Z,1555706734.465 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:45:35.998Z,1555706735.998 [DataOverHttps](INFO): Sending 1319 bytes from file Logs/20190419T204110/Express0001.lzma
2019-04-19T20:45:36.801Z,1555706736.801 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0001.lzma.bak
2019-04-19T20:45:36.801Z,1555706736.801 [DataOverHttps](INFO): SBD MOMSN=10666811
2019-04-19T20:45:44.148Z,1555706744.148 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:45:48.499Z,1555706748.499 [DataOverHttps](INFO): Sending 357 bytes from file Logs/20190419T204110/Express0005.lzma
2019-04-19T20:45:49.305Z,1555706749.305 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0005.lzma.bak
2019-04-19T20:45:49.305Z,1555706749.305 [DataOverHttps](INFO): SBD MOMSN=10666849
2019-04-19T20:45:49.396Z,1555706749.396 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:45:50.285Z,1555706750.285 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:45:50.286Z,1555706750.286 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T20:45:50.286Z,1555706750.286 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:45:54.262Z,1555706754.262 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:46:03.947Z,1555706763.947 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:46:14.041Z,1555706774.041 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:46:24.140Z,1555706784.140 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:46:34.261Z,1555706794.261 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:46:43.944Z,1555706803.944 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:47:04.550Z,1555706824.550 [BPC1](ERROR): BPC1A: No match for serial number FFFF in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-04-19T20:49:15.844Z,1555706955.844 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:49:25.944Z,1555706965.944 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:49:35.651Z,1555706975.651 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:49:45.740Z,1555706985.740 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:49:55.840Z,1555706995.840 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:50:05.543Z,1555707005.543 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:50:11.233Z,1555707011.233 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-19T20:50:11.233Z,1555707011.233 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   +2,    +9,A
2019-04-19T20:50:15.636Z,1555707015.636 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:50:25.341Z,1555707025.341 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:50:35.022Z,1555707035.022 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:50:44.725Z,1555707044.725 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:50:49.586Z,1555707049.586 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-19T20:50:49.587Z,1555707049.587 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19041913594246,31,   0.0,1448.9,  0
2019-04-19T20:50:50.792Z,1555707050.792 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-19T20:50:50.793Z,1555707050.793 [Default:CheckIn:C.Wait] Stopped
2019-04-19T20:50:50.793Z,1555707050.793 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:50:50.793Z,1555707050.793 [Default:CheckIn:D] Running Loop=1
2019-04-19T20:50:51.307Z,1555707051.307 [Default:CheckIn:D] Stopped
2019-04-19T20:50:51.307Z,1555707051.307 [Default:CheckIn:E] Running Loop=1
2019-04-19T20:50:51.607Z,1555707051.607 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.826536 min 
2019-04-19T20:50:51.607Z,1555707051.607 [Default:CheckIn:E] Stopped
2019-04-19T20:50:51.608Z,1555707051.608 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-19T20:50:51.608Z,1555707051.608 [Default:CheckIn] Stopped
2019-04-19T20:50:51.608Z,1555707051.608 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T20:50:51.608Z,1555707051.608 [Default:CheckIn](INFO): Running loop #2
2019-04-19T20:50:51.608Z,1555707051.608 [Default:CheckIn] Running Loop=2
2019-04-19T20:50:51.608Z,1555707051.608 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:50:51.608Z,1555707051.608 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:50:53.235Z,1555707053.235 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:50:53.599Z,1555707053.599 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205052.00,A,3648.15812,N,12147.21363,W,0.117,231.54,190419,,,A*7C
2019-04-19T20:50:53.601Z,1555707053.601 [NAL9602](INFO): GPS fix at 20190419T205052: (36.802635, -121.786894)
2019-04-19T20:50:53.625Z,1555707053.625 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:50:53.625Z,1555707053.625 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:50:54.873Z,1555707054.873 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:50:59.213Z,1555707059.213 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190419T204110/Courier0007.lzma
2019-04-19T20:51:00.005Z,1555707060.005 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0007.lzma.bak
2019-04-19T20:51:00.005Z,1555707060.005 [DataOverHttps](INFO): SBD MOMSN=10666880
2019-04-19T20:51:04.952Z,1555707064.952 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:51:11.669Z,1555707071.669 [DataOverHttps](INFO): Sending 634 bytes from file Logs/20190419T204110/Express0008.lzma
2019-04-19T20:51:12.469Z,1555707072.469 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0008.lzma.bak
2019-04-19T20:51:12.469Z,1555707072.469 [DataOverHttps](INFO): SBD MOMSN=10666883
2019-04-19T20:51:13.473Z,1555707073.473 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:51:13.473Z,1555707073.473 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T20:51:13.473Z,1555707073.473 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:51:15.058Z,1555707075.058 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:51:25.174Z,1555707085.174 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:51:35.267Z,1555707095.267 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:51:55.043Z,1555707115.043 [NAL9602](INFO): SBD MO Status=2, MOMSN=3519, MT Status=2, MTMSN=0
2019-04-19T20:51:55.043Z,1555707115.043 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T20:52:14.431Z,1555707134.431 [NAL9602](INFO): SBD MO Status=0, MOMSN=3519, MT Status=0, MTMSN=0
2019-04-19T20:52:14.431Z,1555707134.431 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:52:28.598Z,1555707148.598 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-19T20:52:28.598Z,1555707148.598 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,1921 0.0,1448.9,  0
2019-04-19T20:52:45.129Z,1555707165.129 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:54:05.562Z,1555707245.562 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:54:15.256Z,1555707255.256 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:54:24.932Z,1555707264.932 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:54:35.036Z,1555707275.036 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:54:44.732Z,1555707284.732 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:54:49.595Z,1555707289.595 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-19T20:54:49.595Z,1555707289.595 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19041914034246,35,448.9,  0
2019-04-19T20:54:54.454Z,1555707294.454 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:55:04.537Z,1555707304.537 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:55:14.260Z,1555707314.260 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:55:23.941Z,1555707323.941 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:55:34.020Z,1555707334.020 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:55:44.120Z,1555707344.120 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:55:53.817Z,1555707353.817 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:56:03.924Z,1555707363.924 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:56:14.024Z,1555707374.024 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:56:14.037Z,1555707374.037 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-19T20:56:14.037Z,1555707374.037 [Default:CheckIn:C.Wait] Stopped
2019-04-19T20:56:14.037Z,1555707374.037 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T20:56:14.037Z,1555707374.037 [Default:CheckIn:D] Running Loop=1
2019-04-19T20:56:14.471Z,1555707374.471 [Default:CheckIn:D] Stopped
2019-04-19T20:56:14.471Z,1555707374.471 [Default:CheckIn:E] Running Loop=1
2019-04-19T20:56:14.871Z,1555707374.871 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.212598 min 
2019-04-19T20:56:14.871Z,1555707374.871 [Default:CheckIn:E] Stopped
2019-04-19T20:56:14.871Z,1555707374.871 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-19T20:56:14.871Z,1555707374.871 [Default:CheckIn] Stopped
2019-04-19T20:56:14.871Z,1555707374.871 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T20:56:14.872Z,1555707374.872 [Default:CheckIn](INFO): Running loop #3
2019-04-19T20:56:14.872Z,1555707374.872 [Default:CheckIn] Running Loop=3
2019-04-19T20:56:14.872Z,1555707374.872 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T20:56:14.872Z,1555707374.872 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T20:56:16.443Z,1555707376.443 [NAL9602](DEBUG): Fix Requested
2019-04-19T20:56:16.840Z,1555707376.840 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205616.00,A,3648.15761,N,12147.21056,W,0.292,231.54,190419,,,D*7F
2019-04-19T20:56:16.842Z,1555707376.842 [NAL9602](INFO): GPS fix at 20190419T205616: (36.802627, -121.786843)
2019-04-19T20:56:16.865Z,1555707376.865 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T20:56:16.865Z,1555707376.865 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T20:56:18.872Z,1555707378.872 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-19T20:56:22.815Z,1555707382.815 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190419T204110/Courier0010.lzma
2019-04-19T20:56:23.419Z,1555707383.419 [CBIT](INFO): Clearing failed state for component DropWeight
2019-04-19T20:56:23.419Z,1555707383.419 [DropWeight] No Fault, FailCount= 1
2019-04-19T20:56:23.621Z,1555707383.621 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0010.lzma.bak
2019-04-19T20:56:23.621Z,1555707383.621 [DataOverHttps](INFO): SBD MOMSN=10667040
2019-04-19T20:56:23.733Z,1555707383.733 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:56:35.512Z,1555707395.512 [DataOverHttps](INFO): Sending 549 bytes from file Logs/20190419T204110/Express0011.lzma
2019-04-19T20:56:36.317Z,1555707396.317 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0011.lzma.bak
2019-04-19T20:56:36.317Z,1555707396.317 [DataOverHttps](INFO): SBD MOMSN=10667044
2019-04-19T20:56:37.082Z,1555707397.082 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T20:56:37.083Z,1555707397.083 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T20:56:37.083Z,1555707397.083 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T20:56:40.686Z,1555707400.686 [NAL9602](INFO): SBD MO Status=0, MOMSN=3520, MT Status=0, MTMSN=0
2019-04-19T20:56:40.686Z,1555707400.686 [NAL9602](INFO): No messages in MT queue
2019-04-19T20:57:11.393Z,1555707431.393 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T20:58:50.864Z,1555707530.864 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-04-19T20:58:56.045Z,1555707536.045 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:59:05.750Z,1555707545.750 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:59:15.850Z,1555707555.850 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:59:25.556Z,1555707565.556 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:59:35.643Z,1555707575.643 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:59:45.350Z,1555707585.350 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T20:59:55.438Z,1555707595.438 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:00:05.130Z,1555707605.130 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:00:15.253Z,1555707615.253 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:00:24.924Z,1555707624.924 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:00:35.025Z,1555707635.025 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:00:45.120Z,1555707645.120 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:00:55.242Z,1555707655.242 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:01:04.917Z,1555707664.917 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:01:15.016Z,1555707675.016 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:01:37.652Z,1555707697.652 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-19T21:01:37.652Z,1555707697.652 [Default:CheckIn:C.Wait] Stopped
2019-04-19T21:01:37.652Z,1555707697.652 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:01:37.652Z,1555707697.652 [Default:CheckIn:D] Running Loop=1
2019-04-19T21:01:38.057Z,1555707698.057 [Default:CheckIn:D] Stopped
2019-04-19T21:01:38.057Z,1555707698.057 [Default:CheckIn:E] Running Loop=1
2019-04-19T21:01:38.470Z,1555707698.470 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.605699 min 
2019-04-19T21:01:38.470Z,1555707698.470 [Default:CheckIn:E] Stopped
2019-04-19T21:01:38.470Z,1555707698.470 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-19T21:01:38.470Z,1555707698.470 [Default:CheckIn] Stopped
2019-04-19T21:01:38.470Z,1555707698.470 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:01:38.470Z,1555707698.470 [Default:CheckIn](INFO): Running loop #4
2019-04-19T21:01:38.470Z,1555707698.470 [Default:CheckIn] Running Loop=4
2019-04-19T21:01:38.471Z,1555707698.471 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T21:01:38.471Z,1555707698.471 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T21:01:40.067Z,1555707700.067 [NAL9602](DEBUG): Fix Requested
2019-04-19T21:01:40.459Z,1555707700.459 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210139.00,A,3648.15689,N,12147.20670,W,0.078,231.54,190419,,,A*76
2019-04-19T21:01:40.461Z,1555707700.461 [NAL9602](INFO): GPS fix at 20190419T210139: (36.802615, -121.786778)
2019-04-19T21:01:40.495Z,1555707700.495 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T21:01:40.495Z,1555707700.495 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T21:01:46.007Z,1555707706.007 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190419T204110/Courier0013.lzma
2019-04-19T21:01:46.825Z,1555707706.825 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0013.lzma.bak
2019-04-19T21:01:46.825Z,1555707706.825 [DataOverHttps](INFO): SBD MOMSN=10667058
2019-04-19T21:01:56.650Z,1555707716.650 [NAL9602](INFO): SBD MO Status=0, MOMSN=3521, MT Status=0, MTMSN=0
2019-04-19T21:01:56.650Z,1555707716.650 [NAL9602](INFO): No messages in MT queue
2019-04-19T21:01:58.836Z,1555707718.836 [DataOverHttps](INFO): Sending 553 bytes from file Logs/20190419T204110/Express0014.lzma
2019-04-19T21:01:59.637Z,1555707719.637 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0014.lzma.bak
2019-04-19T21:01:59.637Z,1555707719.637 [DataOverHttps](INFO): SBD MOMSN=10667063
2019-04-19T21:02:00.317Z,1555707720.317 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T21:02:00.317Z,1555707720.317 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T21:02:00.317Z,1555707720.317 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:02:27.357Z,1555707747.357 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T21:02:51.240Z,1555707771.240 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2019-04-19T21:03:44.941Z,1555707824.941 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:03:50.246Z,1555707830.246 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:03:59.883Z,1555707839.883 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:04:09.604Z,1555707849.604 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:04:19.685Z,1555707859.685 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:04:29.785Z,1555707869.785 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:04:39.491Z,1555707879.491 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:04:49.586Z,1555707889.586 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:04:59.282Z,1555707899.282 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:05:09.385Z,1555707909.385 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:05:19.491Z,1555707919.491 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:05:29.576Z,1555707929.576 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-19T21:05:29.576Z,1555707929.576 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  37.86,  26.22,  30.00
2019-04-19T21:05:29.577Z,1555707929.577 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:05:39.677Z,1555707939.677 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:05:49.381Z,1555707949.381 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:05:59.485Z,1555707959.485 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:06:09.600Z,1555707969.600 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:07:00.888Z,1555708020.888 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-19T21:07:00.888Z,1555708020.888 [Default:CheckIn:C.Wait] Stopped
2019-04-19T21:07:00.888Z,1555708020.888 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:07:00.888Z,1555708020.888 [Default:CheckIn:D] Running Loop=1
2019-04-19T21:07:01.303Z,1555708021.303 [Default:CheckIn:D] Stopped
2019-04-19T21:07:01.303Z,1555708021.303 [Default:CheckIn:E] Running Loop=1
2019-04-19T21:07:01.705Z,1555708021.705 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.993132 min 
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn:E] Stopped
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn] Stopped
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn](INFO): Running loop #5
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn] Running Loop=5
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T21:07:01.706Z,1555708021.706 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T21:07:03.299Z,1555708023.299 [NAL9602](DEBUG): Fix Requested
2019-04-19T21:07:03.695Z,1555708023.695 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210702.00,A,3648.15726,N,12147.20983,W,0.136,0.00,190419,,,D*70
2019-04-19T21:07:03.697Z,1555708023.697 [NAL9602](INFO): GPS fix at 20190419T210702: (36.802621, -121.786830)
2019-04-19T21:07:03.744Z,1555708023.744 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T21:07:03.744Z,1555708023.744 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T21:07:05.752Z,1555708025.752 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-19T21:07:09.715Z,1555708029.715 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190419T204110/Courier0016.lzma
2019-04-19T21:07:10.521Z,1555708030.521 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0016.lzma.bak
2019-04-19T21:07:10.521Z,1555708030.521 [DataOverHttps](INFO): SBD MOMSN=10667213
2019-04-19T21:07:22.268Z,1555708042.268 [DataOverHttps](INFO): Sending 567 bytes from file Logs/20190419T204110/Express0017.lzma
2019-04-19T21:07:23.073Z,1555708043.073 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0017.lzma.bak
2019-04-19T21:07:23.073Z,1555708043.073 [DataOverHttps](INFO): SBD MOMSN=10667216
2019-04-19T21:07:23.956Z,1555708043.956 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T21:07:23.956Z,1555708043.956 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T21:07:23.956Z,1555708043.956 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:07:48.971Z,1555708068.971 [NAL9602](INFO): SBD MO Status=2, MOMSN=3522, MT Status=2, MTMSN=0
2019-04-19T21:07:48.971Z,1555708068.971 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T21:08:41.111Z,1555708121.111 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:08:51.244Z,1555708131.244 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:09:01.320Z,1555708141.320 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:09:11.002Z,1555708151.002 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:09:20.699Z,1555708160.699 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:09:30.785Z,1555708170.785 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:09:40.885Z,1555708180.885 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:09:50.598Z,1555708190.598 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:10:00.288Z,1555708200.288 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:10:10.404Z,1555708210.404 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:10:20.496Z,1555708220.496 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:10:30.231Z,1555708230.231 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:10:33.795Z,1555708233.795 [NAL9602](INFO): SBD MO Status=2, MOMSN=3522, MT Status=2, MTMSN=0
2019-04-19T21:10:33.795Z,1555708233.795 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T21:10:40.293Z,1555708240.293 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:10:42.686Z,1555708242.686 [NAL9602](INFO): SBD MO Status=0, MOMSN=3522, MT Status=0, MTMSN=0
2019-04-19T21:10:42.686Z,1555708242.686 [NAL9602](INFO): No messages in MT queue
2019-04-19T21:10:50.391Z,1555708250.391 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:11:00.490Z,1555708260.490 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-19T21:11:10.600Z,1555708270.600 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2019-04-19T21:11:10.601Z,1555708270.601 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   +9, 

2019-04-19T21:11:13.393Z,1555708273.393 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T21:12:23.777Z,1555708343.777 [BPC1](INFO): Calculating totals. Valid battery stick count: 52. Valid reserve battery stick count: 4.
2019-04-19T21:12:23.780Z,1555708343.780 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2019-04-19T21:12:24.525Z,1555708344.525 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-19T21:12:24.526Z,1555708344.526 [Default:CheckIn:C.Wait] Stopped
2019-04-19T21:12:24.526Z,1555708344.526 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:12:24.526Z,1555708344.526 [Default:CheckIn:D] Running Loop=1
2019-04-19T21:12:24.924Z,1555708344.924 [Default:CheckIn:D] Stopped
2019-04-19T21:12:24.924Z,1555708344.924 [Default:CheckIn:E] Running Loop=1
2019-04-19T21:12:25.341Z,1555708345.341 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.386827 min 
2019-04-19T21:12:25.341Z,1555708345.341 [Default:CheckIn:E] Stopped
2019-04-19T21:12:25.341Z,1555708345.341 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-19T21:12:25.341Z,1555708345.341 [Default:CheckIn] Stopped
2019-04-19T21:12:25.341Z,1555708345.341 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:12:25.341Z,1555708345.341 [Default:CheckIn](INFO): Running loop #6
2019-04-19T21:12:25.341Z,1555708345.341 [Default:CheckIn] Running Loop=6
2019-04-19T21:12:25.342Z,1555708345.342 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T21:12:25.342Z,1555708345.342 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T21:12:26.927Z,1555708346.927 [NAL9602](DEBUG): Fix Requested
2019-04-19T21:12:27.323Z,1555708347.323 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211226.00,A,3648.15785,N,12147.20699,W,0.175,126.15,190419,,,A*7C
2019-04-19T21:12:27.325Z,1555708347.325 [NAL9602](INFO): GPS fix at 20190419T211226: (36.802631, -121.786783)
2019-04-19T21:12:27.358Z,1555708347.358 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T21:12:27.358Z,1555708347.358 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T21:12:32.899Z,1555708352.899 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190419T204110/Courier0019.lzma
2019-04-19T21:12:33.705Z,1555708353.705 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0019.lzma.bak
2019-04-19T21:12:33.705Z,1555708353.705 [DataOverHttps](INFO): SBD MOMSN=10667229
2019-04-19T21:12:48.730Z,1555708368.730 [NAL9602](INFO): SBD MO Status=2, MOMSN=3523, MT Status=2, MTMSN=0
2019-04-19T21:12:48.731Z,1555708368.731 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T21:12:51.445Z,1555708371.445 [DataOverHttps](INFO): Sending 600 bytes from file Logs/20190419T204110/Express0020.lzma
2019-04-19T21:12:52.249Z,1555708372.249 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0020.lzma.bak
2019-04-19T21:12:52.249Z,1555708372.249 [DataOverHttps](INFO): SBD MOMSN=10667247
2019-04-19T21:12:53.275Z,1555708373.275 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T21:12:53.275Z,1555708373.275 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T21:12:53.275Z,1555708373.275 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:13:19.034Z,1555708399.034 [NAL9602](INFO): SBD MO Status=2, MOMSN=3523, MT Status=2, MTMSN=0
2019-04-19T21:13:19.034Z,1555708399.034 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T21:13:31.577Z,1555708411.577 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-19T21:13:31.578Z,1555708411.578 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.03,  26.72,  32.21,  33.54
2019-04-19T21:13:37.218Z,1555708417.218 [NAL9602](INFO): SBD MO Status=0, MOMSN=3523, MT Status=0, MTMSN=0
2019-04-19T21:13:37.218Z,1555708417.218 [NAL9602](INFO): No messages in MT queue
2019-04-19T21:14:07.929Z,1555708447.929 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T21:17:53.788Z,1555708673.788 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-19T21:17:53.788Z,1555708673.788 [Default:CheckIn:C.Wait] Stopped
2019-04-19T21:17:53.788Z,1555708673.788 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:17:53.789Z,1555708673.789 [Default:CheckIn:D] Running Loop=1
2019-04-19T21:17:54.214Z,1555708674.214 [Default:CheckIn:D] Stopped
2019-04-19T21:17:54.214Z,1555708674.214 [Default:CheckIn:E] Running Loop=1
2019-04-19T21:17:54.576Z,1555708674.576 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-19T21:17:54.577Z,1555708674.577 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19041914264746,35.0, -0.1,   0.0,1448.9,,  0.00,  38.53,  25.89,  31.71,  32.87
2019-04-19T21:17:54.587Z,1555708674.587 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.874982 min 
2019-04-19T21:17:54.587Z,1555708674.587 [Default:CheckIn:E] Stopped
2019-04-19T21:17:54.587Z,1555708674.587 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-19T21:17:54.589Z,1555708674.589 [Default:CheckIn] Stopped
2019-04-19T21:17:54.589Z,1555708674.589 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:17:54.589Z,1555708674.589 [Default:CheckIn](INFO): Running loop #7
2019-04-19T21:17:54.589Z,1555708674.589 [Default:CheckIn] Running Loop=7
2019-04-19T21:17:54.589Z,1555708674.589 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T21:17:54.589Z,1555708674.589 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T21:17:56.215Z,1555708676.215 [NAL9602](DEBUG): Fix Requested
2019-04-19T21:17:56.583Z,1555708676.583 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211755.00,A,3648.15799,N,12147.21050,W,0.039,106.98,190419,,,D*79
2019-04-19T21:17:56.585Z,1555708676.585 [NAL9602](INFO): GPS fix at 20190419T211755: (36.802633, -121.786842)
2019-04-19T21:17:56.621Z,1555708676.621 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T21:17:56.621Z,1555708676.621 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T21:18:02.843Z,1555708682.843 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190419T204110/Courier0022.lzma
2019-04-19T21:18:03.649Z,1555708683.649 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0022.lzma.bak
2019-04-19T21:18:03.649Z,1555708683.649 [DataOverHttps](INFO): SBD MOMSN=10667383
2019-04-19T21:18:18.136Z,1555708698.136 [DataOverHttps](INFO): Sending 558 bytes from file Logs/20190419T204110/Express0023.lzma
2019-04-19T21:18:18.941Z,1555708698.941 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0023.lzma.bak
2019-04-19T21:18:18.941Z,1555708698.941 [DataOverHttps](INFO): SBD MOMSN=10667386
2019-04-19T21:18:19.645Z,1555708699.645 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T21:18:19.645Z,1555708699.645 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T21:18:19.645Z,1555708699.645 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:19:19.945Z,1555708759.945 [CommandLine](IMPORTANT): got command show variable range
2019-04-19T21:19:19.949Z,1555708759.949 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-04-19T21:19:20.041Z,1555708760.041 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-04-19T21:19:20.041Z,1555708760.041 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-04-19T21:19:20.058Z,1555708760.058 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-19T21:19:20.059Z,1555708760.059 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-04-19T21:19:20.060Z,1555708760.060 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-04-19T21:19:20.062Z,1555708760.062 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-04-19T21:19:20.063Z,1555708760.063 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-04-19T21:19:20.063Z,1555708760.063 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-04-19T21:19:20.064Z,1555708760.064 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-04-19T21:19:36.542Z,1555708776.542 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-04-19T21:19:49.298Z,1555708789.298 [NAL9602](INFO): SBD MO Status=2, MOMSN=3524, MT Status=2, MTMSN=0
2019-04-19T21:19:49.298Z,1555708789.298 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T21:20:06.667Z,1555708806.667 [NAL9602](INFO): SBD MO Status=2, MOMSN=3524, MT Status=2, MTMSN=0
2019-04-19T21:20:06.667Z,1555708806.667 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T21:20:18.384Z,1555708818.384 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-19T21:20:18.384Z,1555708818.384 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-19T21:20:18.484Z,1555708818.484 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-19T21:20:18.488Z,1555708818.488 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-19T21:20:18.492Z,1555708818.492 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-19T21:20:18.511Z,1555708818.511 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-19T21:20:18.515Z,1555708818.515 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-19T21:20:18.520Z,1555708818.520 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-19T21:20:18.527Z,1555708818.527 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-19T21:20:18.552Z,1555708818.552 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-19T21:20:18.560Z,1555708818.560 [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-19T21:20:18.562Z,1555708818.562 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-19T21:20:18.826Z,1555708818.826 [Default] Stopped
2019-04-19T21:20:18.827Z,1555708818.827 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T21:20:18.827Z,1555708818.827 [Default:B.GoToSurface] Stopped
2019-04-19T21:20:18.827Z,1555708818.827 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T21:20:18.827Z,1555708818.827 [Default:CheckIn] Stopped
2019-04-19T21:20:18.827Z,1555708818.827 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:20:18.827Z,1555708818.827 [Default:CheckIn:C.Wait] Stopped
2019-04-19T21:20:18.827Z,1555708818.827 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:20:18.827Z,1555708818.827 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-19T21:20:18.828Z,1555708818.828 [DUSBL] Running Loop=1
2019-04-19T21:20:18.828Z,1555708818.828 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-19T21:20:18.828Z,1555708818.828 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T21:20:18.828Z,1555708818.828 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-19T21:20:18.828Z,1555708818.828 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T21:20:18.828Z,1555708818.828 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-19T21:20:18.828Z,1555708818.829 [DUSBL:C] Running Loop=1
2019-04-19T21:20:18.829Z,1555708818.829 [DUSBL:RequestRepeater] Running Loop=1
2019-04-19T21:20:18.829Z,1555708818.829 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:20:18.829Z,1555708818.829 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:20:18.829Z,1555708818.829 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:20:18.829Z,1555708818.829 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:20:18.829Z,1555708818.829 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:20:18.829Z,1555708818.829 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:20:18.830Z,1555708818.830 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:20:18.830Z,1555708818.830 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-19T21:20:18.831Z,1555708818.831 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-19T21:20:18.831Z,1555708818.831 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T21:20:18.832Z,1555708818.832 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T21:20:20.406Z,1555708820.406 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:24.445Z,1555708824.445 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:24.852Z,1555708824.852 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:20:25.249Z,1555708825.249 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:25.657Z,1555708825.657 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:20:25.659Z,1555708825.659 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212024.75*5B

2019-04-19T21:20:28.922Z,1555708828.922 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:20:28.922Z,1555708828.922 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:20:28.923Z,1555708828.923 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:20:28.923Z,1555708828.923 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:20:28.923Z,1555708828.923 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater] Running Loop=2
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:20:28.924Z,1555708828.924 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:20:29.290Z,1555708829.290 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:29.697Z,1555708829.697 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:20:30.098Z,1555708830.098 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:30.502Z,1555708830.502 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:20:30.503Z,1555708830.503 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212029.60*52

2019-04-19T21:20:34.144Z,1555708834.144 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:34.545Z,1555708834.545 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:20:34.570Z,1555708834.570 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,   -58,  +127,   +19,A
2019-04-19T21:20:34.946Z,1555708834.946 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:35.357Z,1555708835.357 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:20:35.359Z,1555708835.359 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212034.45*59

2019-04-19T21:20:38.998Z,1555708838.998 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:39.391Z,1555708839.391 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:20:39.449Z,1555708839.449 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:20:39.449Z,1555708839.449 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:20:39.449Z,1555708839.449 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:20:39.449Z,1555708839.449 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:20:39.449Z,1555708839.449 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater] Running Loop=3
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:20:39.450Z,1555708839.450 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:20:39.797Z,1555708839.797 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:40.213Z,1555708840.213 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:20:40.214Z,1555708840.214 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212039.30*56

2019-04-19T21:20:43.833Z,1555708843.833 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:44.237Z,1555708844.237 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:20:44.641Z,1555708844.641 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:45.045Z,1555708845.045 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:20:45.047Z,1555708845.047 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212044.14*5A

2019-04-19T21:20:48.689Z,1555708848.689 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:49.089Z,1555708849.089 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:20:49.493Z,1555708849.493 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:49.897Z,1555708849.897 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:20:49.899Z,1555708849.899 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212049.00*52

2019-04-19T21:20:49.980Z,1555708849.980 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:20:49.980Z,1555708849.980 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:20:49.980Z,1555708849.980 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater] Running Loop=4
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:20:49.981Z,1555708849.981 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:20:49.982Z,1555708849.982 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:20:49.982Z,1555708849.982 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:20:53.533Z,1555708853.533 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:53.937Z,1555708853.937 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:20:54.338Z,1555708854.338 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:54.745Z,1555708854.745 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:20:54.747Z,1555708854.747 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212053.84*55

2019-04-19T21:20:58.381Z,1555708858.381 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:20:58.849Z,1555708858.849 [Reporter](INFO): acoustic_contact_range 660.779968 m
2019-04-19T21:21:00.431Z,1555708860.431 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:21:00.431Z,1555708860.431 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:21:00.431Z,1555708860.431 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:21:00.432Z,1555708860.432 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:21:00.432Z,1555708860.432 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:21:00.432Z,1555708860.432 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:21:00.432Z,1555708860.432 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:21:00.432Z,1555708860.432 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:21:00.432Z,1555708860.432 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-19T21:21:00.432Z,1555708860.432 [DUSBL:RequestRepeater] Running Loop=5
2019-04-19T21:21:00.433Z,1555708860.433 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:21:00.433Z,1555708860.433 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:21:00.433Z,1555708860.433 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:21:00.433Z,1555708860.433 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:21:00.433Z,1555708860.433 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:21:01.211Z,1555708861.211 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:21:05.249Z,1555708865.249 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:21:05.653Z,1555708865.653 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:21:06.057Z,1555708866.057 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:21:06.455Z,1555708866.455 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:21:06.457Z,1555708866.457 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212105.55*5B

2019-04-19T21:21:10.097Z,1555708870.097 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:21:10.501Z,1555708870.501 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:21:10.905Z,1555708870.905 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:21:10.952Z,1555708870.952 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:21:10.952Z,1555708870.952 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:21:10.952Z,1555708870.952 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:21:10.953Z,1555708870.953 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:21:10.953Z,1555708870.953 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:21:10.953Z,1555708870.953 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:21:10.953Z,1555708870.953 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:21:10.953Z,1555708870.953 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:21:10.953Z,1555708870.953 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-19T21:21:10.954Z,1555708870.954 [DUSBL:RequestRepeater] Running Loop=6
2019-04-19T21:21:10.954Z,1555708870.954 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:21:10.954Z,1555708870.954 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:21:10.954Z,1555708870.954 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:21:10.954Z,1555708870.954 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:21:10.954Z,1555708870.954 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:21:11.305Z,1555708871.305 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:21:11.307Z,1555708871.307 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212110.41*5A

2019-04-19T21:21:13.742Z,1555708873.742 [CommandLine](IMPORTANT): got command stop
2019-04-19T21:21:13.742Z,1555708873.742 [CommandLine](IMPORTANT): Scheduling is paused
2019-04-19T21:21:13.742Z,1555708873.742 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-19T21:21:13.779Z,1555708873.779 [MissionManager](INFO): MissionManager is completed.
2019-04-19T21:21:13.780Z,1555708873.780 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:A.Pitch] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:B.SetSpeed] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:C] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:21:13.780Z,1555708873.780 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:21:14.186Z,1555708874.186 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T21:21:14.187Z,1555708874.187 [Default] Running Loop=1
2019-04-19T21:21:14.187Z,1555708874.187 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T21:21:14.188Z,1555708874.188 [Default:B.GoToSurface] Running Loop=1
2019-04-19T21:21:14.188Z,1555708874.188 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T21:21:14.189Z,1555708874.189 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T21:21:14.190Z,1555708874.190 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T21:21:14.191Z,1555708874.191 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T21:21:14.192Z,1555708874.192 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T21:21:14.194Z,1555708874.194 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T21:21:14.194Z,1555708874.194 [Default:A.Wait] Running Loop=1
2019-04-19T21:21:14.194Z,1555708874.194 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:21:27.510Z,1555708887.510 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T21:21:27.510Z,1555708887.510 [Default:A.Wait] Stopped
2019-04-19T21:21:27.510Z,1555708887.510 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:21:27.906Z,1555708887.906 [Default:CheckIn] Running Loop=1
2019-04-19T21:21:27.906Z,1555708887.906 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T21:21:27.906Z,1555708887.906 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T21:21:29.104Z,1555708889.104 [CommandLine](IMPORTANT): got command show variable detection
2019-04-19T21:21:29.254Z,1555708889.254 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-04-19T21:21:40.402Z,1555708900.402 [NAL9602](INFO): SBD MO Status=2, MOMSN=3524, MT Status=2, MTMSN=0
2019-04-19T21:21:40.402Z,1555708900.402 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-19T21:21:42.918Z,1555708902.918 [CommandLine](IMPORTANT): got command get DUSBL_Hydroid.detectionThreshold
2019-04-19T21:21:42.918Z,1555708902.918 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold 90 count
2019-04-19T21:21:58.542Z,1555708918.542 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-19T21:21:58.543Z,1555708918.543 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-19T21:21:58.599Z,1555708918.599 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-19T21:21:58.613Z,1555708918.613 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-19T21:21:58.645Z,1555708918.645 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-19T21:21:58.667Z,1555708918.667 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-19T21:21:58.669Z,1555708918.669 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-19T21:21:58.670Z,1555708918.670 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-19T21:21:58.679Z,1555708918.679 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-19T21:21:58.702Z,1555708918.702 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-19T21:21:58.728Z,1555708918.728 [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-19T21:21:58.729Z,1555708918.729 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-19T21:21:59.006Z,1555708919.006 [Default] Stopped
2019-04-19T21:21:59.006Z,1555708919.006 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T21:21:59.006Z,1555708919.006 [Default:B.GoToSurface] Stopped
2019-04-19T21:21:59.006Z,1555708919.006 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T21:21:59.007Z,1555708919.007 [Default:CheckIn] Stopped
2019-04-19T21:21:59.007Z,1555708919.007 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:21:59.007Z,1555708919.007 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T21:21:59.007Z,1555708919.007 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-19T21:21:59.007Z,1555708919.007 [DUSBL] Running Loop=1
2019-04-19T21:21:59.007Z,1555708919.007 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-19T21:21:59.008Z,1555708919.008 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T21:21:59.008Z,1555708919.008 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-19T21:21:59.008Z,1555708919.008 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T21:21:59.008Z,1555708919.008 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-19T21:21:59.008Z,1555708919.008 [DUSBL:C] Running Loop=1
2019-04-19T21:21:59.008Z,1555708919.008 [DUSBL:RequestRepeater] Running Loop=1
2019-04-19T21:21:59.009Z,1555708919.009 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:21:59.009Z,1555708919.009 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:21:59.009Z,1555708919.009 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:21:59.009Z,1555708919.009 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:21:59.009Z,1555708919.009 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:21:59.009Z,1555708919.009 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:21:59.009Z,1555708919.009 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:21:59.010Z,1555708919.010 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-19T21:21:59.011Z,1555708919.011 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-19T21:21:59.011Z,1555708919.011 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-19T21:21:59.011Z,1555708919.011 [DUSBL:A.Pitch] Running Loop=1
2019-04-19T21:22:00.598Z,1555708920.598 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:01.001Z,1555708921.001 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:01.405Z,1555708921.405 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:01.806Z,1555708921.806 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:01.807Z,1555708921.807 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212200.90*54

2019-04-19T21:22:05.442Z,1555708925.442 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:05.845Z,1555708925.845 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:06.257Z,1555708926.257 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:06.654Z,1555708926.654 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:06.655Z,1555708926.655 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212205.75*5A

2019-04-19T21:22:09.104Z,1555708929.104 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:22:09.105Z,1555708929.105 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:22:09.105Z,1555708929.105 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:22:09.105Z,1555708929.105 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:22:09.105Z,1555708929.105 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:22:09.105Z,1555708929.105 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:22:09.105Z,1555708929.105 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater] Running Loop=2
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:22:09.106Z,1555708929.106 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:22:10.294Z,1555708930.294 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:10.697Z,1555708930.697 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:11.098Z,1555708931.098 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:11.506Z,1555708931.506 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:11.507Z,1555708931.507 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212210.60*5A

2019-04-19T21:22:15.143Z,1555708935.143 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:15.545Z,1555708935.545 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:15.953Z,1555708935.953 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:16.354Z,1555708936.354 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:16.389Z,1555708936.389 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212215.45*58

2019-04-19T21:22:19.622Z,1555708939.622 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:22:19.623Z,1555708939.623 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:22:19.623Z,1555708939.623 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:22:19.623Z,1555708939.623 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:22:19.623Z,1555708939.623 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater] Running Loop=3
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:22:19.624Z,1555708939.624 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:22:19.986Z,1555708939.986 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:20.393Z,1555708940.393 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:20.797Z,1555708940.797 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:21.202Z,1555708941.202 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:21.203Z,1555708941.203 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212220.29*54

2019-04-19T21:22:24.838Z,1555708944.838 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:25.241Z,1555708945.241 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:25.647Z,1555708945.647 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:26.060Z,1555708946.060 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:26.062Z,1555708946.062 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212225.15*5E

2019-04-19T21:22:29.682Z,1555708949.682 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:30.131Z,1555708950.131 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:22:30.131Z,1555708950.131 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:22:30.131Z,1555708950.131 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:22:30.135Z,1555708950.135 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater] Running Loop=4
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:22:30.136Z,1555708950.136 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:22:30.150Z,1555708950.150 [Reporter](INFO): acoustic_contact_range 62.100002 m
2019-04-19T21:22:32.510Z,1555708952.510 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:36.550Z,1555708956.550 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:36.957Z,1555708956.957 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:37.362Z,1555708957.362 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:37.761Z,1555708957.761 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:37.763Z,1555708957.763 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212236.86*56

2019-04-19T21:22:40.626Z,1555708960.626 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:22:40.626Z,1555708960.626 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:22:40.626Z,1555708960.626 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:22:40.627Z,1555708960.627 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:22:40.627Z,1555708960.627 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:22:40.627Z,1555708960.627 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:22:40.627Z,1555708960.627 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:22:40.627Z,1555708960.627 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:22:40.627Z,1555708960.627 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-19T21:22:40.628Z,1555708960.628 [DUSBL:RequestRepeater] Running Loop=5
2019-04-19T21:22:40.628Z,1555708960.628 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:22:40.628Z,1555708960.628 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:22:40.628Z,1555708960.628 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:22:40.628Z,1555708960.628 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:22:40.628Z,1555708960.628 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:22:41.401Z,1555708961.401 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:41.799Z,1555708961.799 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:42.214Z,1555708962.214 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:42.613Z,1555708962.613 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:42.615Z,1555708962.615 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212241.71*5E

2019-04-19T21:22:42.656Z,1555708962.656 [NAL9602](INFO): SBD MO Status=0, MOMSN=3524, MT Status=0, MTMSN=0
2019-04-19T21:22:42.656Z,1555708962.656 [NAL9602](INFO): No messages in MT queue
2019-04-19T21:22:46.248Z,1555708966.248 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:46.653Z,1555708966.653 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:47.058Z,1555708967.058 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:47.461Z,1555708967.461 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:47.463Z,1555708967.463 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212246.56*5C

2019-04-19T21:22:51.094Z,1555708971.094 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:51.141Z,1555708971.141 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:22:51.141Z,1555708971.141 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:22:51.141Z,1555708971.141 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:22:51.142Z,1555708971.142 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:22:51.142Z,1555708971.142 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:22:51.143Z,1555708971.143 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:22:51.143Z,1555708971.143 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:22:51.143Z,1555708971.143 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:22:51.143Z,1555708971.143 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-19T21:22:51.144Z,1555708971.144 [DUSBL:RequestRepeater] Running Loop=6
2019-04-19T21:22:51.144Z,1555708971.144 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:22:51.144Z,1555708971.144 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:22:51.144Z,1555708971.144 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:22:51.144Z,1555708971.144 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:22:51.144Z,1555708971.144 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:22:51.497Z,1555708971.497 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:51.905Z,1555708971.905 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:52.309Z,1555708972.309 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:52.311Z,1555708972.311 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212251.40*5D

2019-04-19T21:22:55.942Z,1555708975.942 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:56.349Z,1555708976.349 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:22:56.750Z,1555708976.750 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:22:57.180Z,1555708977.180 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:22:57.181Z,1555708977.181 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212256.25*59

2019-04-19T21:23:00.799Z,1555708980.799 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:01.200Z,1555708981.200 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:23:01.598Z,1555708981.598 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:01.644Z,1555708981.644 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-19T21:23:01.644Z,1555708981.644 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-04-19T21:23:01.668Z,1555708981.668 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:23:01.669Z,1555708981.669 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:23:01.669Z,1555708981.669 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:23:01.670Z,1555708981.670 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:23:01.670Z,1555708981.670 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:23:01.670Z,1555708981.670 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:23:01.670Z,1555708981.670 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:23:01.670Z,1555708981.670 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:23:01.670Z,1555708981.670 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-04-19T21:23:01.670Z,1555708981.670 [DUSBL:RequestRepeater] Running Loop=7
2019-04-19T21:23:01.671Z,1555708981.671 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:23:01.671Z,1555708981.671 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:23:01.671Z,1555708981.671 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:23:01.671Z,1555708981.671 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:23:01.671Z,1555708981.671 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:23:02.005Z,1555708982.005 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:23:02.007Z,1555708982.007 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212301.11*5D

2019-04-19T21:23:05.637Z,1555708985.637 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:06.045Z,1555708986.045 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:23:06.445Z,1555708986.445 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:06.853Z,1555708986.853 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:23:06.855Z,1555708986.855 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212305.95*55

2019-04-19T21:23:10.493Z,1555708990.493 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:10.889Z,1555708990.889 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:23:11.293Z,1555708991.293 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:11.701Z,1555708991.701 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:23:11.703Z,1555708991.703 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212310.80*55

2019-04-19T21:23:12.134Z,1555708992.134 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:23:12.134Z,1555708992.134 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:23:12.134Z,1555708992.134 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:23:12.135Z,1555708992.135 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:23:12.135Z,1555708992.135 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:23:12.135Z,1555708992.135 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:23:12.135Z,1555708992.135 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:23:12.135Z,1555708992.135 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:23:12.135Z,1555708992.135 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-04-19T21:23:12.135Z,1555708992.135 [DUSBL:RequestRepeater] Running Loop=8
2019-04-19T21:23:12.136Z,1555708992.136 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:23:12.136Z,1555708992.136 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:23:12.136Z,1555708992.136 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:23:12.136Z,1555708992.136 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:23:12.136Z,1555708992.136 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:23:13.318Z,1555708993.318 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T21:23:15.337Z,1555708995.337 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:15.737Z,1555708995.737 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:23:16.146Z,1555708996.146 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:16.546Z,1555708996.546 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:23:16.547Z,1555708996.547 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212315.65*5B

2019-04-19T21:23:20.202Z,1555709000.202 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:20.589Z,1555709000.589 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-04-19T21:23:20.990Z,1555709000.990 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-19T21:23:21.397Z,1555709001.397 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-19T21:23:21.399Z,1555709001.399 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,212320.51*5A

2019-04-19T21:23:22.640Z,1555709002.640 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-19T21:23:22.640Z,1555709002.640 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:23:22.640Z,1555709002.640 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:23:22.641Z,1555709002.641 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-19T21:23:22.641Z,1555709002.641 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:23:22.641Z,1555709002.641 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:23:22.641Z,1555709002.641 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:23:22.641Z,1555709002.641 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:23:22.641Z,1555709002.641 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-04-19T21:23:22.641Z,1555709002.641 [DUSBL:RequestRepeater] Running Loop=9
2019-04-19T21:23:22.642Z,1555709002.642 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-19T21:23:22.642Z,1555709002.642 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-19T21:23:22.642Z,1555709002.642 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-19T21:23:22.642Z,1555709002.642 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-19T21:23:22.642Z,1555709002.642 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:23:23.352Z,1555709003.352 [CommandLine](IMPORTANT): got command stop
2019-04-19T21:23:23.352Z,1555709003.352 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-19T21:23:23.455Z,1555709003.455 [MissionManager](INFO): MissionManager is completed.
2019-04-19T21:23:23.455Z,1555709003.455 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-19T21:23:23.455Z,1555709003.455 [DUSBL] Stopped
2019-04-19T21:23:23.455Z,1555709003.455 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-19T21:23:23.455Z,1555709003.455 [DUSBL:A.Pitch] Stopped
2019-04-19T21:23:23.455Z,1555709003.455 [DUSBL:B.SetSpeed] Stopped
2019-04-19T21:23:23.455Z,1555709003.455 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-19T21:23:23.455Z,1555709003.455 [DUSBL:C] Stopped
2019-04-19T21:23:23.456Z,1555709003.456 [DUSBL:RequestRepeater] Stopped
2019-04-19T21:23:23.456Z,1555709003.456 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-19T21:23:23.456Z,1555709003.456 [DUSBL:RequestRepeater:A] Stopped
2019-04-19T21:23:23.456Z,1555709003.456 [DUSBL:RequestRepeater:B] Stopped
2019-04-19T21:23:23.456Z,1555709003.456 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-19T21:23:23.456Z,1555709003.456 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:23:23.853Z,1555709003.853 [MissionManager](IMPORTANT): Started mission Default
2019-04-19T21:23:23.853Z,1555709003.853 [Default] Running Loop=1
2019-04-19T21:23:23.853Z,1555709003.853 [Default](DEBUG): Aggregate::initialize Default
2019-04-19T21:23:23.853Z,1555709003.853 [Default:B.GoToSurface] Running Loop=1
2019-04-19T21:23:23.853Z,1555709003.853 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-19T21:23:23.854Z,1555709003.854 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-19T21:23:23.854Z,1555709003.854 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-19T21:23:23.854Z,1555709003.854 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-19T21:23:23.855Z,1555709003.855 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-19T21:23:23.855Z,1555709003.855 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-19T21:23:23.855Z,1555709003.855 [Default:A.Wait] Running Loop=1
2019-04-19T21:23:23.856Z,1555709003.856 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:23:37.238Z,1555709017.238 [Default:A.Wait](INFO): Done Waiting.
2019-04-19T21:23:37.238Z,1555709017.238 [Default:A.Wait] Stopped
2019-04-19T21:23:37.238Z,1555709017.238 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:23:37.583Z,1555709017.583 [Default:CheckIn] Running Loop=1
2019-04-19T21:23:37.583Z,1555709017.583 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T21:23:37.583Z,1555709017.583 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T21:23:39.207Z,1555709019.207 [NAL9602](DEBUG): Fix Requested
2019-04-19T21:23:39.579Z,1555709019.579 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212338.00,A,3648.15842,N,12147.21471,W,0.350,103.14,190419,,,D*76
2019-04-19T21:23:39.581Z,1555709019.581 [NAL9602](INFO): GPS fix at 20190419T212338: (36.802640, -121.786912)
2019-04-19T21:23:39.606Z,1555709019.606 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T21:23:39.607Z,1555709019.607 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T21:23:41.911Z,1555709021.911 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20190419T204110/Courier0025.lzma
2019-04-19T21:23:42.549Z,1555709022.549 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0025.lzma.bak
2019-04-19T21:23:42.549Z,1555709022.549 [DataOverHttps](INFO): SBD MOMSN=10667450
2019-04-19T21:23:54.650Z,1555709034.650 [DataOverHttps](INFO): Sending 1211 bytes from file Logs/20190419T204110/Express0026.lzma
2019-04-19T21:23:55.453Z,1555709035.453 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0026.lzma.bak
2019-04-19T21:23:55.453Z,1555709035.453 [DataOverHttps](INFO): SBD MOMSN=10667533
2019-04-19T21:23:56.375Z,1555709036.375 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T21:23:56.375Z,1555709036.375 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T21:23:56.375Z,1555709036.375 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:24:55.420Z,1555709095.420 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-04-19T21:24:55.420Z,1555709095.420 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-04-19T21:24:55.420Z,1555709095.420 [RDI_Pathfinder](ERROR): Communications Fault
2019-04-19T21:24:55.420Z,1555709095.420 [RDI_Pathfinder](ERROR): Failed to parse:
2019-04-19T21:24:55.445Z,1555709095.445 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-04-19T21:24:55.820Z,1555709095.820 [RDI_Pathfinder](INFO): Powering down
2019-04-19T21:24:56.567Z,1555709096.567 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-04-19T21:24:56.567Z,1555709096.567 [RDI_Pathfinder] No Fault, FailCount= 1
2019-04-19T21:25:09.892Z,1555709109.892 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-19T21:25:28.852Z,1555709128.852 [NAL9602](INFO): SBD MO Status=0, MOMSN=3525, MT Status=0, MTMSN=0
2019-04-19T21:25:28.852Z,1555709128.852 [NAL9602](INFO): No messages in MT queue
2019-04-19T21:25:59.549Z,1555709159.549 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-19T21:26:24.588Z,1555709184.588 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-04-19T21:26:24.588Z,1555709184.588 [DropWeight] Hardware Fault, FailCount= 1
2019-04-19T21:26:24.588Z,1555709184.588 [DropWeight](ERROR): Hardware Fault
2019-04-19T21:26:24.621Z,1555709184.621 [CommandLine](FAULT): Scheduling is paused
2019-04-19T21:26:24.621Z,1555709184.621 [CBIT](INFO): Critical error at 20190419T212624
2019-04-19T21:26:24.628Z,1555709184.628 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-04-19T21:26:24.628Z,1555709184.628 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-04-19T21:26:25.051Z,1555709185.051 [CBIT](INFO): Critical error at 20190419T212624
2019-04-19T21:28:57.034Z,1555709337.034 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-19T21:28:57.034Z,1555709337.034 [Default:CheckIn:C.Wait] Stopped
2019-04-19T21:28:57.034Z,1555709337.034 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:28:57.034Z,1555709337.034 [Default:CheckIn:D] Running Loop=1
2019-04-19T21:28:57.391Z,1555709337.391 [Default:CheckIn:D] Stopped
2019-04-19T21:28:57.391Z,1555709337.391 [Default:CheckIn:E] Running Loop=1
2019-04-19T21:28:57.876Z,1555709337.876 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.558967 min 
2019-04-19T21:28:57.876Z,1555709337.876 [Default:CheckIn:E] Stopped
2019-04-19T21:28:57.876Z,1555709337.876 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-19T21:28:57.876Z,1555709337.876 [Default:CheckIn] Stopped
2019-04-19T21:28:57.876Z,1555709337.876 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:28:57.877Z,1555709337.877 [Default:CheckIn](INFO): Running loop #2
2019-04-19T21:28:57.877Z,1555709337.877 [Default:CheckIn] Running Loop=2
2019-04-19T21:28:57.877Z,1555709337.877 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-19T21:28:57.877Z,1555709337.877 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-19T21:28:59.400Z,1555709339.400 [NAL9602](DEBUG): Fix Requested
2019-04-19T21:28:59.841Z,1555709339.841 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212859.00,A,3648.15825,N,12147.21478,W,0.214,237.81,190419,,,A*7E
2019-04-19T21:28:59.848Z,1555709339.848 [NAL9602](INFO): GPS fix at 20190419T212859: (36.802638, -121.786913)
2019-04-19T21:28:59.953Z,1555709339.953 [Default:CheckIn:Read_GPS] Stopped
2019-04-19T21:28:59.953Z,1555709339.953 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-19T21:29:07.623Z,1555709347.623 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20190419T204110/Courier0028.lzma
2019-04-19T21:29:08.429Z,1555709348.429 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Courier0028.lzma.bak
2019-04-19T21:29:08.429Z,1555709348.429 [DataOverHttps](INFO): SBD MOMSN=10667583
2019-04-19T21:29:20.352Z,1555709360.352 [DataOverHttps](INFO): Sending 692 bytes from file Logs/20190419T204110/Express0029.lzma
2019-04-19T21:29:21.157Z,1555709361.157 [DataOverHttps](INFO): Moved sent file to Logs/20190419T204110/Express0029.lzma.bak
2019-04-19T21:29:21.157Z,1555709361.157 [DataOverHttps](INFO): SBD MOMSN=10667588
2019-04-19T21:29:21.977Z,1555709361.977 [Default:CheckIn:Read_Iridium] Stopped
2019-04-19T21:29:21.977Z,1555709361.977 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-19T21:29:21.977Z,1555709361.977 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-19T21:29:22.612Z,1555709362.612 [CommandLine](IMPORTANT): got command restart application
2019-04-19T21:29:23.616Z,1555709363.616 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:23.616Z,1555709363.616 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.643Z,1555709363.643 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-04-19T21:29:23.644Z,1555709363.644 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.644Z,1555709363.644 [CommandLine](INFO): Join timeout helper Thread ID is 5450
2019-04-19T21:29:23.651Z,1555709363.651 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-04-19T21:29:23.651Z,1555709363.651 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.652Z,1555709363.652 [NavChartDb](INFO): Join timeout helper Thread ID is 5451
2019-04-19T21:29:23.688Z,1555709363.688 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:23.688Z,1555709363.688 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.695Z,1555709363.695 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-04-19T21:29:23.696Z,1555709363.696 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.696Z,1555709363.696 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 5452
2019-04-19T21:29:23.728Z,1555709363.728 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:23.728Z,1555709363.728 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-19T21:29:23.729Z,1555709363.729 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.748Z,1555709363.748 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-04-19T21:29:23.748Z,1555709363.748 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.748Z,1555709363.748 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5453
2019-04-19T21:29:23.780Z,1555709363.780 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:23.780Z,1555709363.780 [CTD_NeilBrown](INFO): Powering down
2019-04-19T21:29:23.791Z,1555709363.791 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.796Z,1555709363.796 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-04-19T21:29:23.796Z,1555709363.796 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:23.797Z,1555709363.797 [Radio_Surface](INFO): Join timeout helper Thread ID is 5454
2019-04-19T21:29:24.152Z,1555709364.152 [Radio_Surface](INFO): Powering down
2019-04-19T21:29:24.152Z,1555709364.152 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:24.153Z,1555709364.153 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:24.172Z,1555709364.172 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-04-19T21:29:24.172Z,1555709364.172 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:24.173Z,1555709364.173 [DataOverHttps](INFO): Join timeout helper Thread ID is 5455
2019-04-19T21:29:26.351Z,1555709366.351 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:26.353Z,1555709366.353 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.373Z,1555709366.373 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-04-19T21:29:26.373Z,1555709366.373 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.374Z,1555709366.374 [logger](INFO): Join timeout helper Thread ID is 5456
2019-04-19T21:29:26.378Z,1555709366.378 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:26.380Z,1555709366.380 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.396Z,1555709366.396 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-04-19T21:29:26.396Z,1555709366.396 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.396Z,1555709366.396 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-04-19T21:29:26.397Z,1555709366.397 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.397Z,1555709366.397 [controlThread](INFO): Join timeout helper Thread ID is 5457
2019-04-19T21:29:26.413Z,1555709366.413 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-19T21:29:26.413Z,1555709366.413 [controlThread](DEBUG): Uninitializing ControlThread
2019-04-19T21:29:26.414Z,1555709366.414 [AHRS_M2](INFO): Powering down
2019-04-19T21:29:26.484Z,1555709366.484 [DUSBL_Hydroid](INFO): Powering down
2019-04-19T21:29:26.556Z,1555709366.556 [Micromodem](INFO): Powering down
2019-04-19T21:29:26.652Z,1555709366.652 [NAL9602](INFO): Powering down
2019-04-19T21:29:26.723Z,1555709366.723 [RDI_Pathfinder](INFO): Powering down
2019-04-19T21:29:26.725Z,1555709366.725 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-04-19T21:29:26.726Z,1555709366.726 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-04-19T21:29:26.726Z,1555709366.726 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-04-19T21:29:26.727Z,1555709366.727 [MissionManager](INFO): Uninitializing Mission Default
2019-04-19T21:29:26.727Z,1555709366.727 [Default] Stopped
2019-04-19T21:29:26.727Z,1555709366.727 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-19T21:29:26.727Z,1555709366.727 [Default:B.GoToSurface] Stopped
2019-04-19T21:29:26.727Z,1555709366.727 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-19T21:29:26.727Z,1555709366.727 [Default:CheckIn] Stopped
2019-04-19T21:29:26.727Z,1555709366.727 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-19T21:29:26.727Z,1555709366.727 [Default:CheckIn:C.Wait] Stopped
2019-04-19T21:29:26.727Z,1555709366.727 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-19T21:29:26.730Z,1555709366.730 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-04-19T21:29:26.730Z,1555709366.730 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-04-19T21:29:26.730Z,1555709366.730 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-04-19T21:29:26.730Z,1555709366.730 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-04-19T21:29:26.731Z,1555709366.731 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-04-19T21:29:26.731Z,1555709366.731 [BuoyancyServo](INFO): Powering down
2019-04-19T21:29:26.743Z,1555709366.743 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-04-19T21:29:26.744Z,1555709366.744 [ElevatorServo](INFO): Powering down
2019-04-19T21:29:26.744Z,1555709366.744 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-04-19T21:29:26.744Z,1555709366.744 [MassServo](INFO): Powering down
2019-04-19T21:29:26.745Z,1555709366.745 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-19T21:29:26.745Z,1555709366.745 [RudderServo](INFO): Powering down
2019-04-19T21:29:26.746Z,1555709366.746 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-04-19T21:29:26.746Z,1555709366.746 [ThrusterServo](INFO): Powering down
2019-04-19T21:29:26.747Z,1555709366.747 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-04-19T21:29:26.747Z,1555709366.747 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-04-19T21:29:26.748Z,1555709366.748 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-04-19T21:29:26.748Z,1555709366.748 [CBIT](DEBUG): Powering off loads.
2019-04-19T21:29:26.759Z,1555709366.759 [CBIT](DEBUG): Disabling WDT.
2019-04-19T21:29:26.771Z,1555709366.771 [CBIT](DEBUG): Opening all GF detection circuits.
2019-04-19T21:29:26.772Z,1555709366.772 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.828Z,1555709366.828 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.837Z,1555709366.837 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.882Z,1555709366.882 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.884Z,1555709366.884 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:26.951Z,1555709366.951 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-19T21:29:27.017Z,1555709367.017 [logger ThreadHandler](INFO): Thread cancelled.