2019-04-09T23:24:37.161Z,1554852277.161 [Supervisor](DEBUG): Initializing supervisor.
2019-04-09T23:24:37.164Z,1554852277.164 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-09T23:24:37.164Z,1554852277.164 [SyncHandler](INFO): Protected caller Thread ID is 1576
2019-04-09T23:24:37.165Z,1554852277.165 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-09T23:24:37.165Z,1554852277.165 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-09T23:24:37.166Z,1554852277.166 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1577
2019-04-09T23:24:37.169Z,1554852277.169 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-09T23:24:37.181Z,1554852277.181 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-09T23:24:37.182Z,1554852277.182 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-09T23:24:37.182Z,1554852277.182 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1578
2019-04-09T23:24:37.183Z,1554852277.183 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-09T23:24:37.184Z,1554852277.184 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-09T23:24:37.184Z,1554852277.184 [logger ThreadHandler](INFO): Protected caller Thread ID is 1579
2019-04-09T23:24:37.186Z,1554852277.186 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-09T23:24:37.187Z,1554852277.187 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-09T23:24:37.188Z,1554852277.188 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-09T23:24:37.661Z,1554852277.661 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-09T23:24:37.662Z,1554852277.662 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-09T23:24:37.764Z,1554852277.764 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-09T23:24:37.765Z,1554852277.765 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-09T23:24:38.217Z,1554852278.217 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-09T23:24:38.217Z,1554852278.217 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-09T23:24:38.370Z,1554852278.370 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-09T23:24:38.370Z,1554852278.370 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-09T23:24:38.581Z,1554852278.581 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-09T23:24:38.582Z,1554852278.582 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-09T23:24:39.093Z,1554852279.093 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-09T23:24:39.094Z,1554852279.094 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-09T23:24:39.324Z,1554852279.324 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-09T23:24:39.325Z,1554852279.325 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-09T23:24:39.482Z,1554852279.482 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-09T23:24:39.483Z,1554852279.483 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-09T23:24:39.701Z,1554852279.701 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-09T23:24:39.702Z,1554852279.702 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-09T23:24:39.802Z,1554852279.802 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-09T23:24:39.803Z,1554852279.803 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-09T23:24:40.278Z,1554852280.278 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-09T23:24:40.278Z,1554852280.278 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-09T23:24:40.370Z,1554852280.370 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-09T23:24:40.480Z,1554852280.480 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-09T23:24:40.481Z,1554852280.481 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-09T23:24:41.038Z,1554852281.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-09T23:24:41.038Z,1554852281.038 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-09T23:24:41.473Z,1554852281.473 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-09T23:24:41.475Z,1554852281.475 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-09T23:24:41.476Z,1554852281.476 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-09T23:24:41.706Z,1554852281.706 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-09T23:24:41.813Z,1554852281.813 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-09T23:24:41.917Z,1554852281.917 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-09T23:24:42.163Z,1554852282.163 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-09T23:24:42.164Z,1554852282.164 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-09T23:24:42.251Z,1554852282.251 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-09T23:24:42.349Z,1554852282.349 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-09T23:24:42.451Z,1554852282.451 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-09T23:24:42.536Z,1554852282.536 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-09T23:24:42.654Z,1554852282.654 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-09T23:24:42.849Z,1554852282.849 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-09T23:24:42.997Z,1554852282.997 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-04-09T23:24:42.997Z,1554852282.997 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-09T23:24:43.009Z,1554852283.009 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-09T23:24:43.435Z,1554852283.435 [AHRS_M2] Loaded
2019-04-09T23:24:43.435Z,1554852283.435 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-09T23:24:43.510Z,1554852283.510 [DataOverHttps] Loaded
2019-04-09T23:24:43.510Z,1554852283.510 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-09T23:24:43.511Z,1554852283.511 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-04-09T23:24:43.511Z,1554852283.511 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1659
2019-04-09T23:24:43.526Z,1554852283.526 [Depth_Keller] Loaded
2019-04-09T23:24:43.526Z,1554852283.526 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-09T23:24:43.531Z,1554852283.531 [DropWeight] Loaded
2019-04-09T23:24:43.532Z,1554852283.532 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-09T23:24:43.594Z,1554852283.594 [DUSBL_Hydroid] Loaded
2019-04-09T23:24:43.594Z,1554852283.594 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-09T23:24:43.639Z,1554852283.639 [Micromodem] Loaded
2019-04-09T23:24:43.639Z,1554852283.639 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-09T23:24:43.748Z,1554852283.748 [NAL9602] Loaded
2019-04-09T23:24:43.748Z,1554852283.748 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-09T23:24:43.765Z,1554852283.765 [Onboard] Loaded
2019-04-09T23:24:43.765Z,1554852283.765 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-09T23:24:43.772Z,1554852283.772 [PowerOnly] Loaded
2019-04-09T23:24:43.772Z,1554852283.772 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-09T23:24:43.779Z,1554852283.779 [Radio_Surface] Loaded
2019-04-09T23:24:43.780Z,1554852283.780 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-09T23:24:43.781Z,1554852283.781 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-04-09T23:24:43.781Z,1554852283.781 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1660
2019-04-09T23:24:43.830Z,1554852283.830 [RDI_Pathfinder] Loaded
2019-04-09T23:24:43.831Z,1554852283.831 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-09T23:24:45.647Z,1554852285.647 [BPC1] Loaded
2019-04-09T23:24:45.647Z,1554852285.647 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-09T23:24:45.648Z,1554852285.648 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-09T23:24:45.648Z,1554852285.648 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-09T23:24:45.661Z,1554852285.661 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-09T23:24:45.662Z,1554852285.662 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-09T23:24:45.944Z,1554852285.944 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-09T23:24:45.944Z,1554852285.944 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-09T23:24:45.966Z,1554852285.966 [NavChart] Loaded
2019-04-09T23:24:45.967Z,1554852285.967 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-09T23:24:45.971Z,1554852285.971 [UniversalFixResidualReporter] Loaded
2019-04-09T23:24:45.971Z,1554852285.971 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-09T23:24:45.972Z,1554852285.972 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-09T23:24:45.972Z,1554852285.972 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-09T23:24:46.085Z,1554852286.085 [BuoyancyServo] Loaded
2019-04-09T23:24:46.085Z,1554852286.085 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-09T23:24:46.102Z,1554852286.102 [ElevatorServo] Loaded
2019-04-09T23:24:46.102Z,1554852286.102 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-09T23:24:46.118Z,1554852286.118 [MassServo] Loaded
2019-04-09T23:24:46.119Z,1554852286.119 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-09T23:24:46.135Z,1554852286.135 [RudderServo] Loaded
2019-04-09T23:24:46.135Z,1554852286.135 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-09T23:24:46.151Z,1554852286.151 [ThrusterServo] Loaded
2019-04-09T23:24:46.151Z,1554852286.151 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-09T23:24:46.152Z,1554852286.152 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-09T23:24:46.153Z,1554852286.153 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-09T23:24:46.429Z,1554852286.429 [CTD_NeilBrown] Loaded
2019-04-09T23:24:46.429Z,1554852286.429 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-09T23:24:46.430Z,1554852286.430 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CF4E0
2019-04-09T23:24:46.431Z,1554852286.431 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1661
2019-04-09T23:24:46.480Z,1554852286.480 [WetLabsSeaOWL_UV_A] Loaded
2019-04-09T23:24:46.480Z,1554852286.480 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-09T23:24:46.481Z,1554852286.481 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FF4E0
2019-04-09T23:24:46.481Z,1554852286.481 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1662
2019-04-09T23:24:46.482Z,1554852286.482 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-09T23:24:46.483Z,1554852286.483 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-09T23:24:46.794Z,1554852286.794 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-09T23:24:46.794Z,1554852286.794 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-09T23:24:46.839Z,1554852286.839 [DepthRateCalculator] Loaded
2019-04-09T23:24:46.840Z,1554852286.840 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-09T23:24:46.846Z,1554852286.846 [PitchRateCalculator] Loaded
2019-04-09T23:24:46.846Z,1554852286.846 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-09T23:24:46.860Z,1554852286.860 [SpeedCalculator] Loaded
2019-04-09T23:24:46.860Z,1554852286.860 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-09T23:24:46.883Z,1554852286.883 [TempGradientCalculator] Loaded
2019-04-09T23:24:46.883Z,1554852286.883 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-09T23:24:46.889Z,1554852286.889 [YawRateCalculator] Loaded
2019-04-09T23:24:46.889Z,1554852286.889 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-09T23:24:46.934Z,1554852286.934 [ElevatorOffsetCalculator] Loaded
2019-04-09T23:24:46.934Z,1554852286.934 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-09T23:24:46.934Z,1554852286.934 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-09T23:24:46.935Z,1554852286.935 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-09T23:24:47.088Z,1554852287.088 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-09T23:24:47.113Z,1554852287.113 [SBIT] Loaded
2019-04-09T23:24:47.113Z,1554852287.113 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-09T23:24:47.114Z,1554852287.114 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-09T23:24:47.127Z,1554852287.127 [IBIT] Loaded
2019-04-09T23:24:47.127Z,1554852287.127 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-09T23:24:47.130Z,1554852287.130 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-09T23:24:47.280Z,1554852287.280 [CBIT] Loaded
2019-04-09T23:24:47.281Z,1554852287.281 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-09T23:24:47.281Z,1554852287.281 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-09T23:24:47.282Z,1554852287.282 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-09T23:24:47.358Z,1554852287.358 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-09T23:24:47.358Z,1554852287.358 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-09T23:24:47.471Z,1554852287.471 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-09T23:24:47.472Z,1554852287.472 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-09T23:24:47.546Z,1554852287.546 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-09T23:24:47.638Z,1554852287.638 [VerticalControl] Loaded
2019-04-09T23:24:47.638Z,1554852287.638 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-09T23:24:47.639Z,1554852287.639 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-09T23:24:47.701Z,1554852287.701 [HorizontalControl] Loaded
2019-04-09T23:24:47.701Z,1554852287.701 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-09T23:24:47.702Z,1554852287.702 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-09T23:24:47.704Z,1554852287.704 [SpeedControl] Loaded
2019-04-09T23:24:47.704Z,1554852287.704 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-09T23:24:47.705Z,1554852287.705 [LoopControl](DEBUG): Construct LoopControl.
2019-04-09T23:24:47.705Z,1554852287.705 [LoopControl] Loaded
2019-04-09T23:24:47.706Z,1554852287.706 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-09T23:24:47.706Z,1554852287.706 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-09T23:24:47.707Z,1554852287.707 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-09T23:24:47.736Z,1554852287.736 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-09T23:24:47.740Z,1554852287.740 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-09T23:24:47.740Z,1554852287.740 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-09T23:24:47.747Z,1554852287.747 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-09T23:24:47.749Z,1554852287.749 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2019-04-09T23:24:47.749Z,1554852287.749 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1663
2019-04-09T23:24:47.753Z,1554852287.753 [Supervisor](INFO): Main Thread ID is 802
2019-04-09T23:24:47.754Z,1554852287.754 [Supervisor](DEBUG): Running supervisor.
2019-04-09T23:24:47.754Z,1554852287.754 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1664
2019-04-09T23:24:47.757Z,1554852287.757 [controlThread ThreadHandler](INFO): Handler Thread ID is 1665
2019-04-09T23:24:47.757Z,1554852287.757 [controlThread](DEBUG): Initializing ControlThread
2019-04-09T23:24:47.764Z,1554852287.764 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-09T23:24:47.764Z,1554852287.764 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-09T23:24:47.765Z,1554852287.765 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-09T23:24:47.766Z,1554852287.766 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-09T23:24:47.766Z,1554852287.766 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-09T23:24:47.766Z,1554852287.766 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-09T23:24:47.767Z,1554852287.767 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-09T23:24:47.767Z,1554852287.767 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-09T23:24:47.768Z,1554852287.768 [SBIT](INFO): Initialize SBIT Component.
2019-04-09T23:24:47.768Z,1554852287.768 [SBIT](IMPORTANT): git: 2019-03-18-31-ge98d5dc
2019-04-09T23:24:47.768Z,1554852287.768 [SBIT](INFO): git hash: e98d5dc50cbc39e402f19b9946ff4dc0776c8725
2019-04-09T23:24:47.769Z,1554852287.769 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-09T23:24:47.769Z,1554852287.769 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-09T23:24:47.770Z,1554852287.770 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-04-09T23:24:47.771Z,1554852287.771 [IBIT](INFO): Initialize IBIT Component.
2019-04-09T23:24:47.771Z,1554852287.771 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-09T23:24:47.772Z,1554852287.772 [logger ThreadHandler](INFO): Handler Thread ID is 1666
2019-04-09T23:24:47.785Z,1554852287.785 [CBIT](DEBUG): Initialized mux pins.
2019-04-09T23:24:47.785Z,1554852287.785 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-09T23:24:47.789Z,1554852287.789 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1667
2019-04-09T23:24:47.790Z,1554852287.790 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-09T23:24:47.797Z,1554852287.797 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1668
2019-04-09T23:24:47.805Z,1554852287.805 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1669
2019-04-09T23:24:47.806Z,1554852287.806 [CTD_NeilBrown](INFO): Powering down
2019-04-09T23:24:47.809Z,1554852287.809 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-09T23:24:47.809Z,1554852287.809 [CBIT](DEBUG): Initializing heartbeat.
2019-04-09T23:24:47.837Z,1554852287.837 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1670
2019-04-09T23:24:47.838Z,1554852287.838 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-09T23:24:47.865Z,1554852287.865 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1671
2019-04-09T23:24:47.868Z,1554852287.868 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-09T23:24:47.869Z,1554852287.869 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-09T23:24:47.869Z,1554852287.869 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-09T23:24:47.869Z,1554852287.869 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-09T23:24:47.869Z,1554852287.869 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-09T23:24:47.869Z,1554852287.869 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-09T23:24:47.870Z,1554852287.870 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-09T23:24:47.870Z,1554852287.870 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-09T23:24:47.870Z,1554852287.870 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-09T23:24:47.870Z,1554852287.870 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-09T23:24:47.870Z,1554852287.870 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-09T23:24:47.871Z,1554852287.871 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-09T23:24:47.871Z,1554852287.871 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-09T23:24:47.871Z,1554852287.871 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-09T23:24:47.871Z,1554852287.871 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-09T23:24:47.871Z,1554852287.871 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-09T23:24:47.881Z,1554852287.881 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-09T23:24:47.881Z,1554852287.881 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-09T23:24:47.917Z,1554852287.917 [CBIT](DEBUG): Backplane powered.
2019-04-09T23:24:47.917Z,1554852287.917 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-09T23:24:47.919Z,1554852287.919 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-09T23:24:47.919Z,1554852287.919 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-09T23:24:47.920Z,1554852287.920 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-09T23:24:47.921Z,1554852287.921 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-09T23:24:47.931Z,1554852287.931 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T23:24:47.954Z,1554852287.954 [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-09T23:24:47.955Z,1554852287.955 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-09T23:24:48.022Z,1554852288.022 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-09T23:24:48.023Z,1554852288.023 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-09T23:24:48.049Z,1554852288.049 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T23:24:48.060Z,1554852288.060 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-09T23:24:48.078Z,1554852288.078 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-09T23:24:48.084Z,1554852288.084 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-09T23:24:48.100Z,1554852288.100 [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-09T23:24:48.117Z,1554852288.117 [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-09T23:24:48.129Z,1554852288.129 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-09T23:24:48.163Z,1554852288.163 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-09T23:24:48.164Z,1554852288.164 [DUSBL_Hydroid](INFO): Powering up
2019-04-09T23:24:48.164Z,1554852288.164 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-09T23:24:48.201Z,1554852288.201 [Radio_Surface](INFO): Powering up
2019-04-09T23:24:48.245Z,1554852288.245 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T23:24:48.279Z,1554852288.279 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:24:48.289Z,1554852288.289 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-09T23:24:48.290Z,1554852288.290 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:24:48.297Z,1554852288.297 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-09T23:24:48.298Z,1554852288.298 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:24:48.305Z,1554852288.305 [MassServo](DEBUG): Initializing MassServo.
2019-04-09T23:24:48.306Z,1554852288.306 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:24:48.317Z,1554852288.317 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T23:24:48.318Z,1554852288.318 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:24:48.325Z,1554852288.325 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-09T23:24:48.547Z,1554852288.547 [Micromodem](INFO): Powering up
2019-04-09T23:24:48.547Z,1554852288.547 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-09T23:24:48.581Z,1554852288.581 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T23:24:49.281Z,1554852289.281 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-09T23:24:49.281Z,1554852289.281 [RudderServo](FAULT): Rudder failed to initialize
2019-04-09T23:24:49.281Z,1554852289.281 [RudderServo] Communications Fault, FailCount= 1
2019-04-09T23:24:49.281Z,1554852289.281 [RudderServo](ERROR): Communications Fault
2019-04-09T23:24:49.392Z,1554852289.392 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-09T23:24:49.562Z,1554852289.562 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-09T23:24:49.562Z,1554852289.562 [RudderServo](INFO): Powering down
2019-04-09T23:24:50.236Z,1554852290.236 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:24:50.358Z,1554852290.358 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T23:24:50.362Z,1554852290.362 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-09T23:24:50.362Z,1554852290.362 [RudderServo] No Fault, FailCount= 1
2019-04-09T23:25:01.580Z,1554852301.580 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-09T23:25:05.998Z,1554852305.998 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-09T23:25:14.076Z,1554852314.076 [NAL9602](INFO): Powering up NAL9602
2019-04-09T23:25:24.985Z,1554852324.985 [NAL9602](INFO): NAL9602 initialized
2019-04-09T23:25:25.809Z,1554852325.809 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:25:32.322Z,1554852332.322 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-09T23:25:32.331Z,1554852332.331 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-09T23:25:43.347Z,1554852343.347 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.019679
CHAN A1 (24V): -0.025891
CHAN A2 (12V): -0.007133
CHAN A3 (5V): -0.002204
CHAN B0 (3.3V): 0.000369
CHAN B1 (3.15aV): 0.000442
CHAN B2 (3.15bV): 0.000290
CHAN B3 (GND): 0.002124
OPEN: 0.006488
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-09T23:26:26.402Z,1554852386.402 [SBIT](IMPORTANT): SBIT PASSED
2019-04-09T23:26:26.443Z,1554852386.443 [CommandLine](IMPORTANT): got command configSet list
2019-04-09T23:26:26.443Z,1554852386.443 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-09T23:26:26.444Z,1554852386.444 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-04-09T23:26:26.444Z,1554852386.444 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-04-09T23:26:26.444Z,1554852386.444 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-04-09T23:26:26.444Z,1554852386.444 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-04-09T23:26:26.444Z,1554852386.444 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-04-09T23:26:26.445Z,1554852386.445 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-04-09T23:26:26.445Z,1554852386.445 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-04-09T23:26:26.445Z,1554852386.445 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-04-09T23:26:26.445Z,1554852386.445 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-04-09T23:26:26.446Z,1554852386.446 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-04-09T23:26:26.446Z,1554852386.446 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-04-09T23:26:26.780Z,1554852386.780 [MissionManager](IMPORTANT): Started mission Startup
2019-04-09T23:26:26.780Z,1554852386.780 [Startup] Running Loop=1
2019-04-09T23:26:26.780Z,1554852386.780 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-09T23:26:26.780Z,1554852386.780 [Startup:A.GoToSurface] Running Loop=1
2019-04-09T23:26:26.780Z,1554852386.780 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:26:26.782Z,1554852386.782 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:26:26.783Z,1554852386.783 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:26:26.783Z,1554852386.783 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:26:26.784Z,1554852386.784 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:26:26.784Z,1554852386.784 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:26:26.786Z,1554852386.786 [Startup:StartupSatComms] Running Loop=1
2019-04-09T23:26:26.786Z,1554852386.786 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-09T23:26:26.786Z,1554852386.786 [Startup:StartupSatComms:A] Running Loop=1
2019-04-09T23:26:27.193Z,1554852387.193 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-09T23:26:47.422Z,1554852407.422 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:26:57.473Z,1554852417.473 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:27:07.567Z,1554852427.567 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:27:08.367Z,1554852428.367 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:27:08.367Z,1554852428.367 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:27:13.931Z,1554852433.931 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004905
2019-04-09T23:27:17.682Z,1554852437.682 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:27:26.995Z,1554852446.995 [Startup:StartupSatComms:A](INFO): Timed out from 2019-04-09T23:26:26.8Z
2019-04-09T23:27:26.995Z,1554852446.995 [Startup:StartupSatComms:A] Stopped
2019-04-09T23:27:26.995Z,1554852446.995 [Startup:StartupSatComms:B] Running Loop=1
2019-04-09T23:27:27.365Z,1554852447.365 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:27:27.377Z,1554852447.377 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T23:27:32.568Z,1554852452.568 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190409T231108/Courier0010.lzma
2019-04-09T23:27:33.378Z,1554852453.378 [DataOverHttps](INFO): Moved sent file to Logs/20190409T231108/Courier0010.lzma.bak
2019-04-09T23:27:33.379Z,1554852453.379 [DataOverHttps](INFO): SBD MOMSN=10521242
2019-04-09T23:27:37.477Z,1554852457.477 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:27:44.590Z,1554852464.590 [DataOverHttps](INFO): Sending 1229 bytes from file Logs/20190409T231108/Express0011.lzma
2019-04-09T23:27:45.396Z,1554852465.396 [DataOverHttps](INFO): Moved sent file to Logs/20190409T231108/Express0011.lzma.bak
2019-04-09T23:27:45.396Z,1554852465.396 [DataOverHttps](INFO): SBD MOMSN=10521244
2019-04-09T23:27:47.574Z,1554852467.574 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:27:47.997Z,1554852467.997 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-04-09T23:27:47.997Z,1554852467.997 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-04-09T23:27:48.015Z,1554852468.015 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-04-09T23:27:48.480Z,1554852468.480 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-04-09T23:27:48.480Z,1554852468.480 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-04-09T23:27:51.581Z,1554852471.581 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:27:51.581Z,1554852471.581 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:27:56.643Z,1554852476.643 [DataOverHttps](INFO): Sending 1437 bytes from file Logs/20190409T232437/Express0001.lzma
2019-04-09T23:27:57.446Z,1554852477.446 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0001.lzma.bak
2019-04-09T23:27:57.446Z,1554852477.446 [DataOverHttps](INFO): SBD MOMSN=10521299
2019-04-09T23:27:57.674Z,1554852477.674 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:27:58.526Z,1554852478.526 [Startup:StartupSatComms:B] Stopped
2019-04-09T23:27:58.526Z,1554852478.526 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-09T23:27:58.526Z,1554852478.526 [Startup:StartupSatComms] Stopped
2019-04-09T23:27:58.526Z,1554852478.526 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-09T23:27:58.527Z,1554852478.527 [Startup](INFO): Completed Startup
2019-04-09T23:27:58.527Z,1554852478.527 [MissionManager](INFO): Startup is completed.
2019-04-09T23:27:58.527Z,1554852478.527 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-09T23:27:58.527Z,1554852478.527 [Startup] Stopped
2019-04-09T23:27:58.527Z,1554852478.527 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-09T23:27:58.528Z,1554852478.528 [Startup:A.GoToSurface] Stopped
2019-04-09T23:27:58.528Z,1554852478.528 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:27:58.898Z,1554852478.898 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T23:27:58.898Z,1554852478.898 [Default] Running Loop=1
2019-04-09T23:27:58.898Z,1554852478.898 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T23:27:58.898Z,1554852478.898 [Default:B.GoToSurface] Running Loop=1
2019-04-09T23:27:58.898Z,1554852478.898 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:27:58.898Z,1554852478.898 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:27:58.899Z,1554852478.899 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:27:58.899Z,1554852478.899 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:27:58.899Z,1554852478.899 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:27:58.900Z,1554852478.900 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:27:58.900Z,1554852478.900 [Default:A.Wait] Running Loop=1
2019-04-09T23:27:58.900Z,1554852478.900 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:28:07.350Z,1554852487.350 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:28:12.216Z,1554852492.216 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T23:28:12.216Z,1554852492.216 [Default:A.Wait] Stopped
2019-04-09T23:28:12.216Z,1554852492.216 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:28:12.639Z,1554852492.639 [Default:CheckIn] Running Loop=1
2019-04-09T23:28:12.639Z,1554852492.639 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:28:12.639Z,1554852492.639 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:28:13.018Z,1554852493.018 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-09T23:28:17.451Z,1554852497.451 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:28:25.121Z,1554852505.121 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:28:25.121Z,1554852505.121 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:28:27.561Z,1554852507.561 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:28:37.680Z,1554852517.680 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:28:47.771Z,1554852527.771 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:28:57.851Z,1554852537.851 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:29:07.575Z,1554852547.575 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:29:53.992Z,1554852593.992 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:29:53.992Z,1554852593.992 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:30:08.136Z,1554852608.136 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:30:08.137Z,1554852608.137 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:30:28.332Z,1554852628.332 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T23:30:29.157Z,1554852629.157 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:30:29.545Z,1554852629.545 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,232934.00,A,3648.16379,N,12147.28261,W,0.253,329.85,090419,,,A*78
2019-04-09T23:30:29.548Z,1554852629.548 [NAL9602](INFO): GPS fix at 20190409T232934: (36.802730, -121.788044)
2019-04-09T23:30:29.576Z,1554852629.576 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:30:29.576Z,1554852629.576 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:30:30.006Z,1554852630.006 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T23:30:39.104Z,1554852639.104 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190409T232437/Courier0004.lzma
2019-04-09T23:30:39.910Z,1554852639.910 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Courier0004.lzma.bak
2019-04-09T23:30:39.910Z,1554852639.910 [DataOverHttps](INFO): SBD MOMSN=10521325
2019-04-09T23:30:53.742Z,1554852653.742 [DataOverHttps](INFO): Sending 759 bytes from file Logs/20190409T232437/Express0005.lzma
2019-04-09T23:30:54.546Z,1554852654.546 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0005.lzma.bak
2019-04-09T23:30:54.546Z,1554852654.546 [DataOverHttps](INFO): SBD MOMSN=10521328
2019-04-09T23:30:55.564Z,1554852655.564 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:30:55.564Z,1554852655.564 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:30:55.564Z,1554852655.564 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:31:01.575Z,1554852661.575 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T23:31:39.581Z,1554852699.581 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:31:49.263Z,1554852709.263 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:31:59.364Z,1554852719.364 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:32:09.063Z,1554852729.063 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:32:19.158Z,1554852739.158 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:32:29.258Z,1554852749.258 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:32:39.389Z,1554852759.389 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:32:49.472Z,1554852769.472 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:32:59.568Z,1554852779.568 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:33:09.672Z,1554852789.672 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:33:19.769Z,1554852799.769 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:33:29.473Z,1554852809.473 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:33:39.565Z,1554852819.565 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:33:49.662Z,1554852829.662 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:33:59.769Z,1554852839.769 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:35:56.144Z,1554852956.144 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T23:35:56.144Z,1554852956.144 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:35:56.144Z,1554852956.144 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:35:56.144Z,1554852956.144 [Default:CheckIn:D] Running Loop=1
2019-04-09T23:35:56.536Z,1554852956.536 [Default:CheckIn:D] Stopped
2019-04-09T23:35:56.536Z,1554852956.536 [Default:CheckIn:E] Running Loop=1
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.960639 min 
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn:E] Stopped
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn] Stopped
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn](INFO): Running loop #2
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn] Running Loop=2
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:35:56.934Z,1554852956.934 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:35:58.529Z,1554852958.529 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:35:58.925Z,1554852958.925 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,233504.00,A,3648.16501,N,12147.28110,W,0.175,329.85,090419,,,A*7D
2019-04-09T23:35:58.927Z,1554852958.927 [NAL9602](INFO): GPS fix at 20190409T233504: (36.802750, -121.788018)
2019-04-09T23:35:58.958Z,1554852958.958 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:35:58.959Z,1554852958.959 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:36:04.664Z,1554852964.664 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190409T232437/Courier0007.lzma
2019-04-09T23:36:05.470Z,1554852965.470 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Courier0007.lzma.bak
2019-04-09T23:36:05.470Z,1554852965.470 [DataOverHttps](INFO): SBD MOMSN=10521332
2019-04-09T23:36:17.698Z,1554852977.698 [DataOverHttps](INFO): Sending 857 bytes from file Logs/20190409T232437/Express0008.lzma
2019-04-09T23:36:18.491Z,1554852978.491 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0008.lzma.bak
2019-04-09T23:36:18.491Z,1554852978.491 [DataOverHttps](INFO): SBD MOMSN=10521335
2019-04-09T23:36:19.262Z,1554852979.262 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:36:19.262Z,1554852979.262 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:36:19.262Z,1554852979.262 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:36:29.667Z,1554852989.667 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-04-09T23:36:29.749Z,1554852989.749 [NAL9602](FAULT): received: 
+CSQ:0

OK58, 2, 0, 0, 0

OK
2019-04-09T23:36:29.749Z,1554852989.749 [NAL9602] Data Fault, FailCount= 1
2019-04-09T23:36:29.749Z,1554852989.749 [NAL9602](ERROR): Data Fault
2019-04-09T23:36:29.831Z,1554852989.831 [CBIT](ERROR): Data Fault in component: NAL9602
2019-04-09T23:36:30.083Z,1554852990.083 [NAL9602](INFO): Powering down
2019-04-09T23:36:30.498Z,1554852990.498 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:36:30.925Z,1554852990.925 [CBIT](INFO): Clearing failed state for component NAL9602
2019-04-09T23:36:30.925Z,1554852990.925 [NAL9602] No Fault, FailCount= 1
2019-04-09T23:36:40.187Z,1554853000.187 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:36:49.879Z,1554853009.879 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:36:59.589Z,1554853019.589 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:37:00.397Z,1554853020.397 [NAL9602](INFO): Powering up NAL9602
2019-04-09T23:37:09.689Z,1554853029.689 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:37:11.278Z,1554853031.278 [NAL9602](INFO): NAL9602 initialized
2019-04-09T23:37:19.413Z,1554853039.413 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:37:29.068Z,1554853049.068 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:37:38.775Z,1554853058.775 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:37:42.386Z,1554853062.386 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T23:37:48.878Z,1554853068.878 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:37:58.583Z,1554853078.583 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:38:08.255Z,1554853088.255 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:38:18.398Z,1554853098.398 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:38:28.470Z,1554853108.470 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:38:38.568Z,1554853118.568 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:38:48.670Z,1554853128.670 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:40:37.377Z,1554853237.377 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-04-09T23:40:37.377Z,1554853237.377 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,       -1.89,        +2.2 -0.77,   0.00, 10.00
2019-04-09T23:41:02.432Z,1554853262.432 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-04-09T23:41:19.760Z,1554853279.760 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:41:19.778Z,1554853279.778 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T23:41:19.778Z,1554853279.778 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:41:19.778Z,1554853279.778 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:41:19.779Z,1554853279.779 [Default:CheckIn:D] Running Loop=1
2019-04-09T23:41:20.188Z,1554853280.188 [Default:CheckIn:D] Stopped
2019-04-09T23:41:20.188Z,1554853280.188 [Default:CheckIn:E] Running Loop=1
2019-04-09T23:41:20.616Z,1554853280.616 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.354837 min 
2019-04-09T23:41:20.616Z,1554853280.616 [Default:CheckIn:E] Stopped
2019-04-09T23:41:20.616Z,1554853280.616 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T23:41:20.616Z,1554853280.616 [Default:CheckIn] Stopped
2019-04-09T23:41:20.617Z,1554853280.617 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:41:20.617Z,1554853280.617 [Default:CheckIn](INFO): Running loop #3
2019-04-09T23:41:20.617Z,1554853280.617 [Default:CheckIn] Running Loop=3
2019-04-09T23:41:20.617Z,1554853280.617 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:41:20.617Z,1554853280.617 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:41:22.177Z,1554853282.177 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:41:22.567Z,1554853282.567 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234027.00,A,3648.16873,N,12147.28599,W,0.272,143.73,090419,,,A*70
2019-04-09T23:41:22.569Z,1554853282.569 [NAL9602](INFO): GPS fix at 20190409T234027: (36.802812, -121.788100)
2019-04-09T23:41:22.604Z,1554853282.604 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:41:22.604Z,1554853282.604 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:41:24.231Z,1554853284.231 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T23:41:28.300Z,1554853288.300 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190409T232437/Courier0010.lzma
2019-04-09T23:41:29.106Z,1554853289.106 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Courier0010.lzma.bak
2019-04-09T23:41:29.106Z,1554853289.106 [DataOverHttps](INFO): SBD MOMSN=10521406
2019-04-09T23:41:29.898Z,1554853289.898 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:41:39.608Z,1554853299.608 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:41:42.066Z,1554853302.066 [DataOverHttps](INFO): Sending 821 bytes from file Logs/20190409T232437/Express0011.lzma
2019-04-09T23:41:42.870Z,1554853302.870 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0011.lzma.bak
2019-04-09T23:41:42.870Z,1554853302.870 [DataOverHttps](INFO): SBD MOMSN=10521409
2019-04-09T23:41:43.641Z,1554853303.641 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:41:43.641Z,1554853303.641 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:41:43.641Z,1554853303.641 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:41:49.297Z,1554853309.297 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:41:54.933Z,1554853314.933 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T23:41:58.989Z,1554853318.989 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:42:09.091Z,1554853329.091 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:42:19.185Z,1554853339.185 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:42:28.894Z,1554853348.894 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:42:38.990Z,1554853358.990 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:42:49.093Z,1554853369.093 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:42:59.186Z,1554853379.186 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:43:08.883Z,1554853388.883 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:43:18.982Z,1554853398.982 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:43:29.078Z,1554853409.078 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:43:39.192Z,1554853419.192 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:46:06.246Z,1554853566.246 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:46:15.942Z,1554853575.942 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:46:26.059Z,1554853586.059 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:46:35.765Z,1554853595.765 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:46:44.236Z,1554853604.236 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T23:46:44.236Z,1554853604.236 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:46:44.236Z,1554853604.236 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:46:44.236Z,1554853604.236 [Default:CheckIn:D] Running Loop=1
2019-04-09T23:46:44.655Z,1554853604.655 [Default:CheckIn:D] Stopped
2019-04-09T23:46:44.655Z,1554853604.655 [Default:CheckIn:E] Running Loop=1
2019-04-09T23:46:45.091Z,1554853605.091 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.762614 min 
2019-04-09T23:46:45.091Z,1554853605.091 [Default:CheckIn:E] Stopped
2019-04-09T23:46:45.091Z,1554853605.091 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T23:46:45.091Z,1554853605.091 [Default:CheckIn] Stopped
2019-04-09T23:46:45.092Z,1554853605.092 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:46:45.092Z,1554853605.092 [Default:CheckIn](INFO): Running loop #4
2019-04-09T23:46:45.092Z,1554853605.092 [Default:CheckIn] Running Loop=4
2019-04-09T23:46:45.092Z,1554853605.092 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:46:45.092Z,1554853605.092 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:46:45.431Z,1554853605.431 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:46:46.645Z,1554853606.645 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:46:47.043Z,1554853607.043 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234552.00,A,3648.16427,N,12147.28281,W,0.039,241.91,090419,,,A*74
2019-04-09T23:46:47.045Z,1554853607.045 [NAL9602](INFO): GPS fix at 20190409T234552: (36.802738, -121.788047)
2019-04-09T23:46:47.100Z,1554853607.100 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:46:47.100Z,1554853607.100 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:46:52.836Z,1554853612.836 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190409T232437/Courier0013.lzma
2019-04-09T23:46:53.642Z,1554853613.642 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Courier0013.lzma.bak
2019-04-09T23:46:53.642Z,1554853613.642 [DataOverHttps](INFO): SBD MOMSN=10521444
2019-04-09T23:46:55.170Z,1554853615.170 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:47:01.616Z,1554853621.616 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:47:01.616Z,1554853621.616 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:47:04.855Z,1554853624.855 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:47:05.130Z,1554853625.130 [DataOverHttps](INFO): Sending 703 bytes from file Logs/20190409T232437/Express0014.lzma
2019-04-09T23:47:05.922Z,1554853625.922 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0014.lzma.bak
2019-04-09T23:47:05.922Z,1554853625.922 [DataOverHttps](INFO): SBD MOMSN=10521447
2019-04-09T23:47:06.907Z,1554853626.907 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:47:06.907Z,1554853626.907 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:47:06.907Z,1554853626.907 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:47:14.958Z,1554853634.958 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:47:17.388Z,1554853637.388 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:47:17.388Z,1554853637.388 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:47:25.076Z,1554853645.076 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:47:35.165Z,1554853655.165 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:47:44.876Z,1554853664.876 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:47:51.705Z,1554853671.705 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T23:47:51.705Z,1554853671.705 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T23:47:54.568Z,1554853674.568 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:48:04.256Z,1554853684.256 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:48:13.956Z,1554853693.956 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:48:24.054Z,1554853704.054 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:48:35.402Z,1554853715.402 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-09T23:48:35.402Z,1554853715.402 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-3:BE,-32768,-32768,-32768,V
2019-04-09T23:48:56.400Z,1554853736.400 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-04-09T23:48:56.400Z,1554853736.400 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,       -1    +2.61,       -0.87,   9.37,  0.00
2019-04-09T23:50:14.771Z,1554853814.771 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-09T23:50:14.771Z,1554853814.771 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  92.93,  95.42,  94.92
2019-04-09T23:50:50.396Z,1554853850.396 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-04-09T23:50:55.553Z,1554853855.553 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:51:05.267Z,1554853865.267 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:51:15.354Z,1554853875.354 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:51:15.768Z,1554853875.768 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-09T23:51:15.769Z,1554853875.769 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040916590583,35.0, -0.1,448.9,  0
2019-04-09T23:51:25.039Z,1554853885.039 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:51:34.759Z,1554853894.759 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:51:44.452Z,1554853904.452 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:51:49.279Z,1554853909.279 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T23:51:54.556Z,1554853914.556 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:52:04.242Z,1554853924.242 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:52:07.509Z,1554853927.509 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T23:52:07.509Z,1554853927.509 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:52:07.510Z,1554853927.510 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:52:07.510Z,1554853927.510 [Default:CheckIn:D] Running Loop=1
2019-04-09T23:52:07.903Z,1554853927.903 [Default:CheckIn:D] Stopped
2019-04-09T23:52:07.903Z,1554853927.903 [Default:CheckIn:E] Running Loop=1
2019-04-09T23:52:08.355Z,1554853928.355 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.150090 min 
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn:E] Stopped
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn] Stopped
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn](INFO): Running loop #5
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn] Running Loop=5
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:52:08.356Z,1554853928.356 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:52:09.897Z,1554853929.897 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:52:10.282Z,1554853930.282 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235116.00,A,3648.16404,N,12147.28004,W,0.039,241.91,090419,,,A*7F
2019-04-09T23:52:10.284Z,1554853930.284 [NAL9602](INFO): GPS fix at 20190409T235116: (36.802734, -121.788001)
2019-04-09T23:52:10.315Z,1554853930.315 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:52:10.315Z,1554853930.315 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:52:13.986Z,1554853933.986 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:52:16.204Z,1554853936.204 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190409T232437/Courier0016.lzma
2019-04-09T23:52:17.010Z,1554853937.010 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Courier0016.lzma.bak
2019-04-09T23:52:17.010Z,1554853937.010 [DataOverHttps](INFO): SBD MOMSN=10521536
2019-04-09T23:52:23.703Z,1554853943.703 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:52:29.214Z,1554853949.214 [DataOverHttps](INFO): Sending 976 bytes from file Logs/20190409T232437/Express0017.lzma
2019-04-09T23:52:30.019Z,1554853950.019 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0017.lzma.bak
2019-04-09T23:52:30.019Z,1554853950.019 [DataOverHttps](INFO): SBD MOMSN=10521539
2019-04-09T23:52:30.976Z,1554853950.976 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:52:30.976Z,1554853950.976 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:52:30.976Z,1554853950.976 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:52:33.388Z,1554853953.388 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:52:42.655Z,1554853962.655 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T23:52:43.493Z,1554853963.493 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:52:53.178Z,1554853973.178 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:53:03.278Z,1554853983.278 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:53:12.994Z,1554853992.994 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:54:10.373Z,1554854050.373 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-09T23:54:10.373Z,1554854050.373 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-3276,V
2019-04-09T23:55:41.929Z,1554854141.929 [CommandLine](IMPORTANT): got command show stack
2019-04-09T23:55:41.930Z,1554854141.930 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-09T23:55:41.930Z,1554854141.930 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-04-09T23:55:41.931Z,1554854141.931 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-04-09T23:55:44.074Z,1554854144.074 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:55:47.997Z,1554854147.997 [CommandLine](IMPORTANT): got command show variable range
2019-04-09T23:55:47.000Z,1554854148.000 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-04-09T23:55:48.193Z,1554854148.193 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T23:55:48.195Z,1554854148.195 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-04-09T23:55:48.195Z,1554854148.195 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-04-09T23:55:48.198Z,1554854148.198 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-04-09T23:55:48.198Z,1554854148.198 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-04-09T23:55:48.199Z,1554854148.199 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-04-09T23:55:48.199Z,1554854148.199 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-04-09T23:55:48.521Z,1554854148.521 [BPC1](INFO): Calculating totals. Valid battery stick count: 52. Valid reserve battery stick count: 4.
2019-04-09T23:55:48.524Z,1554854148.524 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2019-04-09T23:55:54.583Z,1554854154.583 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-09T23:55:54.583Z,1554854154.583 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,  2.00
2019-04-09T23:55:55.562Z,1554854155.562 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-04-09T23:56:05.946Z,1554854165.946 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:56:05.946Z,1554854165.946 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:56:06.001Z,1554854166.001 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T23:56:06.013Z,1554854166.013 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T23:56:06.021Z,1554854166.021 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T23:56:06.029Z,1554854166.029 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T23:56:06.037Z,1554854166.037 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T23:56:06.038Z,1554854166.038 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T23:56:06.044Z,1554854166.044 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T23:56:06.072Z,1554854166.072 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T23:56:06.097Z,1554854166.097 [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-09T23:56:06.105Z,1554854166.105 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:56:06.299Z,1554854166.299 [Default] Stopped
2019-04-09T23:56:06.299Z,1554854166.299 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T23:56:06.299Z,1554854166.299 [Default:B.GoToSurface] Stopped
2019-04-09T23:56:06.299Z,1554854166.299 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:56:06.300Z,1554854166.300 [Default:CheckIn] Stopped
2019-04-09T23:56:06.300Z,1554854166.300 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:56:06.300Z,1554854166.300 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:56:06.300Z,1554854166.300 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:56:06.300Z,1554854166.300 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T23:56:06.300Z,1554854166.300 [DUSBL] Running Loop=1
2019-04-09T23:56:06.300Z,1554854166.300 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:C] Running Loop=1
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:56:06.301Z,1554854166.301 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:56:06.302Z,1554854166.302 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:56:06.302Z,1554854166.302 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:56:06.302Z,1554854166.302 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:56:06.302Z,1554854166.302 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:56:06.302Z,1554854166.302 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:56:06.303Z,1554854166.303 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-09T23:56:06.304Z,1554854166.304 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-09T23:56:06.304Z,1554854166.304 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:56:06.304Z,1554854166.304 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:56:07.892Z,1554854167.892 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:08.301Z,1554854168.301 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190409235605.823710,06,263,12,0092,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,205,-0.05,-999,9760,4000*7F

2019-04-09T23:56:11.927Z,1554854171.927 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:12.345Z,1554854172.345 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:56:12.356Z,1554854172.356 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:12.497Z,1554854172.497 [Reporter](INFO): acoustic_contact_range 79.320007 m
2019-04-09T23:56:16.389Z,1554854176.389 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:16.463Z,1554854176.463 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T23:56:16.463Z,1554854176.463 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:56:16.463Z,1554854176.463 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:56:16.464Z,1554854176.464 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T23:56:16.464Z,1554854176.464 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:56:16.464Z,1554854176.464 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:56:16.464Z,1554854176.464 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:56:16.464Z,1554854176.464 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:56:16.464Z,1554854176.464 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T23:56:16.464Z,1554854176.464 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T23:56:16.469Z,1554854176.469 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:56:16.469Z,1554854176.469 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:56:16.469Z,1554854176.469 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:56:16.469Z,1554854176.469 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:56:16.469Z,1554854176.469 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:56:16.775Z,1554854176.775 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:20.813Z,1554854180.813 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:21.219Z,1554854181.219 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:56:21.221Z,1554854181.221 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:21.266Z,1554854181.266 [Reporter](INFO): acoustic_contact_range 6.900000 m
2019-04-09T23:56:25.267Z,1554854185.267 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:25.679Z,1554854185.679 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:56:25.681Z,1554854185.681 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:25.710Z,1554854185.710 [Micromodem](ERROR): Response from modem unexpected: $CADQF,201,1*53

2019-04-09T23:56:25.712Z,1554854185.712 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-04-09T23:56:25.788Z,1554854185.788 [Reporter](INFO): acoustic_contact_range 46.380001 m
2019-04-09T23:56:26.088Z,1554854186.088 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190409235623.618734,06,123,14,0091,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,201,-0.05,-999,9760,4000*7E

2019-04-09T23:56:26.904Z,1554854186.904 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T23:56:26.904Z,1554854186.904 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:56:26.904Z,1554854186.904 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:56:26.904Z,1554854186.904 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater] Running Loop=3
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:56:26.905Z,1554854186.905 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:56:29.434Z,1554854189.434 [CommandLine](IMPORTANT): got command stop
2019-04-09T23:56:29.434Z,1554854189.434 [CommandLine](IMPORTANT): Scheduling is paused
2019-04-09T23:56:29.435Z,1554854189.435 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-09T23:56:29.711Z,1554854189.711 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:56:29.804Z,1554854189.804 [MissionManager](INFO): MissionManager is completed.
2019-04-09T23:56:29.805Z,1554854189.805 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL] Stopped
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL:A.Pitch] Stopped
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL:B.SetSpeed] Stopped
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL:C] Stopped
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:56:29.805Z,1554854189.805 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:56:29.806Z,1554854189.806 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:56:29.806Z,1554854189.806 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:56:29.806Z,1554854189.806 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:56:30.144Z,1554854190.144 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T23:56:30.144Z,1554854190.144 [Default] Running Loop=1
2019-04-09T23:56:30.144Z,1554854190.144 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T23:56:30.144Z,1554854190.144 [Default:B.GoToSurface] Running Loop=1
2019-04-09T23:56:30.144Z,1554854190.144 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:56:30.145Z,1554854190.145 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:56:30.145Z,1554854190.145 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:56:30.145Z,1554854190.145 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:56:30.146Z,1554854190.146 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:56:30.146Z,1554854190.146 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:56:30.146Z,1554854190.146 [Default:A.Wait] Running Loop=1
2019-04-09T23:56:30.146Z,1554854190.146 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:56:31.748Z,1554854191.748 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-09T23:56:31.748Z,1554854191.748 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040917042183,35.0, -0.1,   0.0  0
2019-04-09T23:56:43.480Z,1554854203.480 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T23:56:43.480Z,1554854203.480 [Default:A.Wait] Stopped
2019-04-09T23:56:43.480Z,1554854203.480 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:56:43.872Z,1554854203.872 [Default:CheckIn] Running Loop=1
2019-04-09T23:56:43.872Z,1554854203.872 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:56:43.872Z,1554854203.872 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:56:45.481Z,1554854205.481 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:56:45.879Z,1554854205.879 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235552.00,A,3648.16736,N,12147.28164,W,0.117,241.91,090419,,,A*73
2019-04-09T23:56:45.881Z,1554854205.881 [NAL9602](INFO): GPS fix at 20190409T235552: (36.802789, -121.788027)
2019-04-09T23:56:45.912Z,1554854205.912 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:56:45.912Z,1554854205.912 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:56:48.113Z,1554854208.113 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190409T232437/Courier0019.lzma
2019-04-09T23:56:48.726Z,1554854208.726 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Courier0019.lzma.bak
2019-04-09T23:56:48.726Z,1554854208.726 [DataOverHttps](INFO): SBD MOMSN=10521543
2019-04-09T23:57:00.787Z,1554854220.787 [DataOverHttps](INFO): Sending 1281 bytes from file Logs/20190409T232437/Express0020.lzma
2019-04-09T23:57:01.590Z,1554854221.590 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0020.lzma.bak
2019-04-09T23:57:01.590Z,1554854221.590 [DataOverHttps](INFO): SBD MOMSN=10521546
2019-04-09T23:57:02.659Z,1554854222.659 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:57:02.659Z,1554854222.659 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:57:02.660Z,1554854222.660 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:57:16.342Z,1554854236.342 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-04-09T23:57:16.422Z,1554854236.422 [NAL9602](FAULT): received: 
+CSQ:0

OK58, 2, 0, 0, 0

OK
2019-04-09T23:57:16.422Z,1554854236.422 [NAL9602] Data Fault, FailCount= 1
2019-04-09T23:57:16.422Z,1554854236.422 [NAL9602](ERROR): Data Fault
2019-04-09T23:57:16.469Z,1554854236.469 [CBIT](ERROR): Data Fault in component: NAL9602
2019-04-09T23:57:16.743Z,1554854236.743 [NAL9602](INFO): Powering down
2019-04-09T23:57:17.592Z,1554854237.592 [CBIT](INFO): Clearing failed state for component NAL9602
2019-04-09T23:57:17.592Z,1554854237.592 [NAL9602] No Fault, FailCount= 1
2019-04-09T23:57:47.043Z,1554854267.043 [NAL9602](INFO): Powering up NAL9602
2019-04-09T23:57:57.951Z,1554854277.951 [NAL9602](INFO): NAL9602 initialized
2019-04-09T23:58:29.111Z,1554854309.111 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T23:59:06.793Z,1554854346.793 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:59:06.794Z,1554854346.794 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:59:06.838Z,1554854346.838 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T23:59:06.840Z,1554854346.840 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T23:59:06.842Z,1554854346.842 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T23:59:06.845Z,1554854346.845 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T23:59:06.847Z,1554854346.847 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T23:59:06.848Z,1554854346.848 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T23:59:06.852Z,1554854346.852 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T23:59:06.860Z,1554854346.860 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T23:59:06.864Z,1554854346.864 [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-09T23:59:06.866Z,1554854346.866 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:59:07.104Z,1554854347.104 [Default] Stopped
2019-04-09T23:59:07.104Z,1554854347.104 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T23:59:07.105Z,1554854347.105 [Default:B.GoToSurface] Stopped
2019-04-09T23:59:07.105Z,1554854347.105 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:59:07.105Z,1554854347.105 [Default:CheckIn] Stopped
2019-04-09T23:59:07.105Z,1554854347.105 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:59:07.105Z,1554854347.105 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:59:07.105Z,1554854347.105 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:59:07.105Z,1554854347.105 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T23:59:07.105Z,1554854347.105 [DUSBL] Running Loop=1
2019-04-09T23:59:07.106Z,1554854347.106 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T23:59:07.106Z,1554854347.106 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:59:07.106Z,1554854347.106 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T23:59:07.106Z,1554854347.106 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:59:07.106Z,1554854347.106 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T23:59:07.106Z,1554854347.106 [DUSBL:C] Running Loop=1
2019-04-09T23:59:07.106Z,1554854347.106 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T23:59:07.107Z,1554854347.107 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:59:07.107Z,1554854347.107 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:59:07.107Z,1554854347.107 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:59:07.107Z,1554854347.107 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:59:07.107Z,1554854347.107 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:59:07.107Z,1554854347.107 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:59:07.108Z,1554854347.108 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:59:07.108Z,1554854347.108 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-09T23:59:07.109Z,1554854347.109 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-09T23:59:07.109Z,1554854347.109 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:59:07.109Z,1554854347.109 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:59:08.655Z,1554854348.655 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:59:08.657Z,1554854348.657 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:59:08.770Z,1554854348.770 [Reporter](INFO): acoustic_contact_range 13.619998 m
2019-04-09T23:59:11.079Z,1554854351.079 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:59:11.082Z,1554854351.082 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:59:11.188Z,1554854351.188 [Reporter](INFO): acoustic_contact_range 13.439999 m
2019-04-09T23:59:13.502Z,1554854353.502 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:59:13.504Z,1554854353.504 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:59:13.631Z,1554854353.631 [Reporter](INFO): acoustic_contact_range 9.540000 m
2019-04-09T23:59:15.927Z,1554854355.927 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:59:15.929Z,1554854355.929 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:59:15.990Z,1554854355.990 [Reporter](INFO): acoustic_contact_range 1130.520020 m
2019-04-09T23:59:16.761Z,1554854356.761 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-04-09T23:59:17.172Z,1554854357.172 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T23:59:17.172Z,1554854357.172 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:59:17.172Z,1554854357.172 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:59:17.173Z,1554854357.173 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:59:17.174Z,1554854357.174 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:59:17.174Z,1554854357.174 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:59:17.174Z,1554854357.174 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:59:18.370Z,1554854358.370 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:59:18.373Z,1554854358.373 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:59:18.504Z,1554854358.504 [Reporter](INFO): acoustic_contact_range 76.620003 m
2019-04-09T23:59:18.673Z,1554854358.673 [CommandLine](IMPORTANT): got command stop
2019-04-09T23:59:18.673Z,1554854358.673 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-09T23:59:18.781Z,1554854358.781 [MissionManager](INFO): MissionManager is completed.
2019-04-09T23:59:18.781Z,1554854358.781 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T23:59:18.781Z,1554854358.781 [DUSBL] Stopped
2019-04-09T23:59:18.781Z,1554854358.781 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T23:59:18.781Z,1554854358.781 [DUSBL:A.Pitch] Stopped
2019-04-09T23:59:18.781Z,1554854358.781 [DUSBL:B.SetSpeed] Stopped
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:C] Stopped
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:59:18.782Z,1554854358.782 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:59:19.183Z,1554854359.183 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T23:59:19.184Z,1554854359.184 [Default] Running Loop=1
2019-04-09T23:59:19.184Z,1554854359.184 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T23:59:19.184Z,1554854359.184 [Default:B.GoToSurface] Running Loop=1
2019-04-09T23:59:19.184Z,1554854359.184 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:59:19.184Z,1554854359.184 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:59:19.185Z,1554854359.185 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:59:19.185Z,1554854359.185 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:59:19.185Z,1554854359.185 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:59:19.186Z,1554854359.186 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:59:19.186Z,1554854359.186 [Default:A.Wait] Running Loop=1
2019-04-09T23:59:19.186Z,1554854359.186 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:59:32.533Z,1554854372.533 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T23:59:32.533Z,1554854372.533 [Default:A.Wait] Stopped
2019-04-09T23:59:32.533Z,1554854372.533 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:59:32.916Z,1554854372.916 [Default:CheckIn] Running Loop=1
2019-04-09T23:59:32.917Z,1554854372.917 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:59:32.917Z,1554854372.917 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:59:34.517Z,1554854374.517 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:59:34.921Z,1554854374.921 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235840.00,A,3648.16598,N,12147.28857,W,0.272,0.00,090419,,,A*7D
2019-04-09T23:59:34.923Z,1554854374.923 [NAL9602](INFO): GPS fix at 20190409T235840: (36.802766, -121.788143)
2019-04-09T23:59:34.952Z,1554854374.952 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:59:34.952Z,1554854374.952 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:59:40.776Z,1554854380.776 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190409T232437/Courier0022.lzma
2019-04-09T23:59:41.582Z,1554854381.582 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Courier0022.lzma.bak
2019-04-09T23:59:41.583Z,1554854381.583 [DataOverHttps](INFO): SBD MOMSN=10521645
2019-04-09T23:59:53.814Z,1554854393.815 [DataOverHttps](INFO): Sending 657 bytes from file Logs/20190409T232437/Express0023.lzma
2019-04-09T23:59:54.618Z,1554854394.618 [DataOverHttps](INFO): Moved sent file to Logs/20190409T232437/Express0023.lzma.bak
2019-04-09T23:59:54.619Z,1554854394.619 [DataOverHttps](INFO): SBD MOMSN=10521648
2019-04-09T23:59:55.984Z,1554854395.984 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:59:55.984Z,1554854395.984 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:59:55.984Z,1554854395.984 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:00:06.173Z,1554854406.173 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:00:06.174Z,1554854406.174 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:00:06.215Z,1554854406.215 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-10T00:00:06.223Z,1554854406.223 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-10T00:00:06.245Z,1554854406.245 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-10T00:00:06.247Z,1554854406.247 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-10T00:00:06.258Z,1554854406.258 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-10T00:00:06.259Z,1554854406.259 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-10T00:00:06.268Z,1554854406.268 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-10T00:00:06.300Z,1554854406.300 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-10T00:00:06.312Z,1554854406.312 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

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

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-04-10T00:00:06.322Z,1554854406.322 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-10T00:00:06.464Z,1554854406.464 [Default] Stopped
2019-04-10T00:00:06.464Z,1554854406.464 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-10T00:00:06.464Z,1554854406.464 [Default:B.GoToSurface] Stopped
2019-04-10T00:00:06.465Z,1554854406.465 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-10T00:00:06.465Z,1554854406.465 [Default:CheckIn] Stopped
2019-04-10T00:00:06.465Z,1554854406.465 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-10T00:00:06.465Z,1554854406.465 [Default:CheckIn:C.Wait] Stopped
2019-04-10T00:00:06.465Z,1554854406.465 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:00:06.465Z,1554854406.465 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-10T00:00:06.465Z,1554854406.465 [DUSBL] Running Loop=1
2019-04-10T00:00:06.465Z,1554854406.465 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-10T00:00:06.466Z,1554854406.466 [DUSBL:A.Pitch] Running Loop=1
2019-04-10T00:00:06.466Z,1554854406.466 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-10T00:00:06.466Z,1554854406.466 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-10T00:00:06.466Z,1554854406.466 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-10T00:00:06.466Z,1554854406.466 [DUSBL:C] Running Loop=1
2019-04-10T00:00:06.466Z,1554854406.466 [DUSBL:RequestRepeater] Running Loop=1
2019-04-10T00:00:06.467Z,1554854406.467 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:00:06.467Z,1554854406.467 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:00:06.467Z,1554854406.467 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:00:06.467Z,1554854406.467 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:00:06.467Z,1554854406.467 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:00:06.467Z,1554854406.467 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:00:06.467Z,1554854406.467 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:00:06.468Z,1554854406.468 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-10T00:00:06.477Z,1554854406.477 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-10T00:00:06.477Z,1554854406.477 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-10T00:00:06.478Z,1554854406.478 [DUSBL:A.Pitch] Running Loop=1
2019-04-10T00:00:08.043Z,1554854408.043 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:08.049Z,1554854408.049 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:08.212Z,1554854408.212 [Reporter](INFO): acoustic_contact_range 1107.420044 m
2019-04-10T00:00:10.467Z,1554854410.467 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:10.469Z,1554854410.469 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:10.585Z,1554854410.585 [Reporter](INFO): acoustic_contact_range 11.520001 m
2019-04-10T00:00:14.511Z,1554854414.511 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:14.911Z,1554854414.911 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:14.913Z,1554854414.913 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:14.958Z,1554854414.958 [Reporter](INFO): acoustic_contact_range 17.219997 m
2019-04-10T00:00:16.573Z,1554854416.573 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:00:16.573Z,1554854416.573 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:00:16.573Z,1554854416.573 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater] Running Loop=2
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:00:16.574Z,1554854416.574 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:00:16.575Z,1554854416.575 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:00:16.575Z,1554854416.575 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:00:18.955Z,1554854418.955 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:19.359Z,1554854419.359 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:19.362Z,1554854419.362 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:19.415Z,1554854419.415 [Reporter](INFO): acoustic_contact_range 72.300003 m
2019-04-10T00:00:23.401Z,1554854423.401 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:23.801Z,1554854423.801 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:23.803Z,1554854423.803 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:23.886Z,1554854423.886 [Reporter](INFO): acoustic_contact_range 20.700001 m
2019-04-10T00:00:27.058Z,1554854427.058 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:00:27.058Z,1554854427.058 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:00:27.058Z,1554854427.058 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:00:27.059Z,1554854427.059 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:00:27.059Z,1554854427.059 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:00:27.059Z,1554854427.059 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:00:27.059Z,1554854427.059 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:00:27.059Z,1554854427.059 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:00:27.059Z,1554854427.059 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-10T00:00:27.060Z,1554854427.060 [DUSBL:RequestRepeater] Running Loop=3
2019-04-10T00:00:27.060Z,1554854427.060 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:00:27.060Z,1554854427.060 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:00:27.060Z,1554854427.060 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:00:27.060Z,1554854427.060 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:00:27.060Z,1554854427.060 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:00:27.839Z,1554854427.839 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:28.247Z,1554854428.247 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:28.249Z,1554854428.249 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:28.290Z,1554854428.290 [Reporter](INFO): acoustic_contact_range 86.280006 m
2019-04-10T00:00:29.086Z,1554854429.086 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CATRC,RECV,IDEM, 523,Missed start of FSK packet

2019-04-10T00:00:30.264Z,1554854430.264 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-10T00:00:30.264Z,1554854430.264 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-10T00:00:32.293Z,1554854432.293 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:32.691Z,1554854432.691 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:32.693Z,1554854432.693 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:32.773Z,1554854432.773 [Reporter](INFO): acoustic_contact_range 11.579999 m
2019-04-10T00:00:36.725Z,1554854436.725 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:37.135Z,1554854437.135 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:37.137Z,1554854437.137 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:37.218Z,1554854437.218 [Reporter](INFO): acoustic_contact_range 11.640002 m
2019-04-10T00:00:37.571Z,1554854437.571 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:00:37.572Z,1554854437.572 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:00:37.572Z,1554854437.572 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater] Running Loop=4
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:00:37.573Z,1554854437.573 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:00:37.574Z,1554854437.574 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:00:37.574Z,1554854437.574 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:00:37.574Z,1554854437.574 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:00:41.171Z,1554854441.171 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:41.574Z,1554854441.574 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:41.576Z,1554854441.576 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:41.709Z,1554854441.709 [Reporter](INFO): acoustic_contact_range 86.340004 m
2019-04-10T00:00:45.615Z,1554854445.615 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:46.023Z,1554854446.023 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:46.033Z,1554854446.033 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:46.106Z,1554854446.106 [Reporter](INFO): acoustic_contact_range 11.520001 m
2019-04-10T00:00:48.076Z,1554854448.076 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:00:48.076Z,1554854448.076 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:00:48.076Z,1554854448.076 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:00:48.077Z,1554854448.077 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:00:48.077Z,1554854448.077 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:00:48.077Z,1554854448.077 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:00:48.077Z,1554854448.077 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:00:48.077Z,1554854448.077 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:00:48.077Z,1554854448.077 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-10T00:00:48.077Z,1554854448.077 [DUSBL:RequestRepeater] Running Loop=5
2019-04-10T00:00:48.078Z,1554854448.078 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:00:48.078Z,1554854448.078 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:00:48.078Z,1554854448.078 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:00:48.078Z,1554854448.078 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:00:48.078Z,1554854448.078 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:00:50.063Z,1554854450.063 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:50.467Z,1554854450.467 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:50.469Z,1554854450.469 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:50.553Z,1554854450.553 [Reporter](INFO): acoustic_contact_range 34.799999 m
2019-04-10T00:00:54.507Z,1554854454.507 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:54.911Z,1554854454.911 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-10T00:00:54.913Z,1554854454.913 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-10T00:00:54.918Z,1554854454.918 [Micromodem](ERROR): Response from modem unexpected: $CADQF,203,1*51

2019-04-10T00:00:54.919Z,1554854454.919 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-04-10T00:00:54.962Z,1554854454.962 [Reporter](INFO): acoustic_contact_range 15.540001 m
2019-04-10T00:00:55.318Z,1554854455.318 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190410000052.945709,06,347,13,0094,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-.,999,-9.99,203,-0.05,99,960,00*78

2019-04-10T00:00:58.430Z,1554854458.430 [CommandLine](IMPORTANT): got command stop
2019-04-10T00:00:58.431Z,1554854458.431 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-10T00:00:58.584Z,1554854458.584 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-10T00:00:58.585Z,1554854458.585 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:00:58.585Z,1554854458.585 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:00:58.585Z,1554854458.585 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-10T00:00:58.585Z,1554854458.585 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:00:58.585Z,1554854458.585 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater] Running Loop=6
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-10T00:00:58.586Z,1554854458.586 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:00:58.587Z,1554854458.587 [MissionManager](INFO): MissionManager is completed.
2019-04-10T00:00:58.587Z,1554854458.587 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-10T00:00:58.587Z,1554854458.587 [DUSBL] Stopped
2019-04-10T00:00:58.587Z,1554854458.587 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-10T00:00:58.587Z,1554854458.587 [DUSBL:A.Pitch] Stopped
2019-04-10T00:00:58.587Z,1554854458.587 [DUSBL:B.SetSpeed] Stopped
2019-04-10T00:00:58.587Z,1554854458.587 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-10T00:00:58.588Z,1554854458.588 [DUSBL:C] Stopped
2019-04-10T00:00:58.588Z,1554854458.588 [DUSBL:RequestRepeater] Stopped
2019-04-10T00:00:58.588Z,1554854458.588 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-10T00:00:58.588Z,1554854458.588 [DUSBL:RequestRepeater:A] Stopped
2019-04-10T00:00:58.588Z,1554854458.588 [DUSBL:RequestRepeater:B] Stopped
2019-04-10T00:00:58.588Z,1554854458.588 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-10T00:00:58.588Z,1554854458.588 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:00:58.979Z,1554854458.979 [MissionManager](IMPORTANT): Started mission Default
2019-04-10T00:00:58.980Z,1554854458.980 [Default] Running Loop=1
2019-04-10T00:00:58.980Z,1554854458.980 [Default](DEBUG): Aggregate::initialize Default
2019-04-10T00:00:58.980Z,1554854458.980 [Default:B.GoToSurface] Running Loop=1
2019-04-10T00:00:58.980Z,1554854458.980 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-10T00:00:58.980Z,1554854458.980 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-10T00:00:58.981Z,1554854458.981 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-10T00:00:58.981Z,1554854458.981 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-10T00:00:58.981Z,1554854458.981 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-10T00:00:58.982Z,1554854458.982 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-10T00:00:58.982Z,1554854458.982 [Default:A.Wait] Running Loop=1
2019-04-10T00:00:58.982Z,1554854458.982 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-10T00:01:02.462Z,1554854462.462 [CommandLine](IMPORTANT): got command restart application
2019-04-10T00:01:03.469Z,1554854463.469 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:03.469Z,1554854463.469 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:03.565Z,1554854463.565 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-04-10T00:01:03.565Z,1554854463.565 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:03.566Z,1554854463.566 [CommandLine](INFO): Join timeout helper Thread ID is 1726
2019-04-10T00:01:03.566Z,1554854463.566 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-04-10T00:01:03.567Z,1554854463.567 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:03.567Z,1554854463.567 [NavChartDb](INFO): Join timeout helper Thread ID is 1727
2019-04-10T00:01:03.641Z,1554854463.641 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:03.641Z,1554854463.641 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:03.645Z,1554854463.645 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-04-10T00:01:03.645Z,1554854463.645 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:03.645Z,1554854463.645 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1728
2019-04-10T00:01:03.933Z,1554854463.933 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:03.933Z,1554854463.933 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-10T00:01:03.934Z,1554854463.934 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:03.953Z,1554854463.953 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-04-10T00:01:03.953Z,1554854463.953 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:03.953Z,1554854463.953 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1729
2019-04-10T00:01:04.037Z,1554854464.037 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:04.038Z,1554854464.038 [CTD_NeilBrown](INFO): Powering down
2019-04-10T00:01:04.053Z,1554854464.053 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.057Z,1554854464.057 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-04-10T00:01:04.057Z,1554854464.057 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.057Z,1554854464.057 [Radio_Surface](INFO): Join timeout helper Thread ID is 1730
2019-04-10T00:01:04.353Z,1554854464.353 [Radio_Surface](INFO): Powering down
2019-04-10T00:01:04.356Z,1554854464.356 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:04.357Z,1554854464.357 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.361Z,1554854464.361 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-04-10T00:01:04.362Z,1554854464.362 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.363Z,1554854464.363 [DataOverHttps](INFO): Join timeout helper Thread ID is 1731
2019-04-10T00:01:04.561Z,1554854464.561 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:04.561Z,1554854464.561 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.581Z,1554854464.581 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-04-10T00:01:04.581Z,1554854464.581 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.582Z,1554854464.582 [logger](INFO): Join timeout helper Thread ID is 1732
2019-04-10T00:01:04.637Z,1554854464.637 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:04.637Z,1554854464.637 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.641Z,1554854464.641 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-04-10T00:01:04.642Z,1554854464.642 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.642Z,1554854464.642 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-04-10T00:01:04.642Z,1554854464.642 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:04.642Z,1554854464.642 [controlThread](INFO): Join timeout helper Thread ID is 1733
2019-04-10T00:01:04.657Z,1554854464.657 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-10T00:01:04.657Z,1554854464.657 [controlThread](DEBUG): Uninitializing ControlThread
2019-04-10T00:01:04.657Z,1554854464.657 [AHRS_M2](INFO): Powering down
2019-04-10T00:01:04.729Z,1554854464.729 [DUSBL_Hydroid](INFO): Powering down
2019-04-10T00:01:04.801Z,1554854464.801 [Micromodem](INFO): Powering down
2019-04-10T00:01:04.897Z,1554854464.897 [NAL9602](INFO): Powering down
2019-04-10T00:01:04.969Z,1554854464.969 [RDI_Pathfinder](INFO): Powering down
2019-04-10T00:01:04.970Z,1554854464.970 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-04-10T00:01:04.971Z,1554854464.971 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-04-10T00:01:04.971Z,1554854464.971 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-04-10T00:01:04.972Z,1554854464.972 [MissionManager](INFO): Uninitializing Mission Default
2019-04-10T00:01:04.972Z,1554854464.972 [Default] Stopped
2019-04-10T00:01:04.972Z,1554854464.972 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-10T00:01:04.972Z,1554854464.972 [Default:A.Wait] Stopped
2019-04-10T00:01:04.972Z,1554854464.972 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-10T00:01:04.972Z,1554854464.972 [Default:B.GoToSurface] Stopped
2019-04-10T00:01:04.972Z,1554854464.972 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-10T00:01:04.975Z,1554854464.975 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-04-10T00:01:04.975Z,1554854464.975 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-04-10T00:01:04.975Z,1554854464.975 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-04-10T00:01:04.976Z,1554854464.976 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-04-10T00:01:04.976Z,1554854464.976 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-04-10T00:01:04.976Z,1554854464.976 [BuoyancyServo](INFO): Powering down
2019-04-10T00:01:04.989Z,1554854464.989 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-04-10T00:01:04.989Z,1554854464.989 [ElevatorServo](INFO): Powering down
2019-04-10T00:01:04.990Z,1554854464.990 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-04-10T00:01:04.990Z,1554854464.990 [MassServo](INFO): Powering down
2019-04-10T00:01:04.991Z,1554854464.991 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-10T00:01:04.991Z,1554854464.991 [RudderServo](INFO): Powering down
2019-04-10T00:01:04.991Z,1554854464.991 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-04-10T00:01:04.992Z,1554854464.992 [ThrusterServo](INFO): Powering down
2019-04-10T00:01:04.992Z,1554854464.992 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-04-10T00:01:04.993Z,1554854464.993 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-04-10T00:01:04.993Z,1554854464.993 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-04-10T00:01:04.993Z,1554854464.993 [CBIT](DEBUG): Powering off loads.
2019-04-10T00:01:05.005Z,1554854465.005 [CBIT](DEBUG): Disabling WDT.
2019-04-10T00:01:05.016Z,1554854465.016 [CBIT](DEBUG): Opening all GF detection circuits.
2019-04-10T00:01:05.018Z,1554854465.018 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:05.076Z,1554854465.076 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:05.086Z,1554854465.086 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:05.130Z,1554854465.130 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:05.132Z,1554854465.132 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:05.187Z,1554854465.187 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-10T00:01:05.258Z,1554854465.258 [logger ThreadHandler](INFO): Thread cancelled.