2019-05-28T23:09:04.016Z,1559084944.016 [Supervisor](DEBUG): Initializing supervisor.
2019-05-28T23:09:04.019Z,1559084944.019 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-28T23:09:04.020Z,1559084944.020 [SyncHandler](INFO): Protected caller Thread ID is 3359
2019-05-28T23:09:04.021Z,1559084944.021 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-28T23:09:04.022Z,1559084944.022 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-28T23:09:04.022Z,1559084944.022 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3360
2019-05-28T23:09:04.025Z,1559084944.025 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-28T23:09:04.037Z,1559084944.037 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-28T23:09:04.038Z,1559084944.038 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-28T23:09:04.038Z,1559084944.038 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3361
2019-05-28T23:09:04.039Z,1559084944.039 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-28T23:09:04.040Z,1559084944.040 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-28T23:09:04.040Z,1559084944.040 [logger ThreadHandler](INFO): Protected caller Thread ID is 3362
2019-05-28T23:09:04.042Z,1559084944.042 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-28T23:09:04.043Z,1559084944.043 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-28T23:09:04.044Z,1559084944.044 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-28T23:09:04.531Z,1559084944.531 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-28T23:09:04.531Z,1559084944.531 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-28T23:09:04.632Z,1559084944.632 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-28T23:09:04.632Z,1559084944.632 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-28T23:09:04.957Z,1559084944.957 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-28T23:09:04.958Z,1559084944.958 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-28T23:09:05.100Z,1559084945.100 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-28T23:09:05.101Z,1559084945.101 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-28T23:09:05.293Z,1559084945.293 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-28T23:09:05.294Z,1559084945.294 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-28T23:09:05.749Z,1559084945.749 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-28T23:09:05.750Z,1559084945.750 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-28T23:09:05.960Z,1559084945.960 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-28T23:09:05.961Z,1559084945.961 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-28T23:09:06.108Z,1559084946.108 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-28T23:09:06.108Z,1559084946.108 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-28T23:09:06.303Z,1559084946.303 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-28T23:09:06.303Z,1559084946.303 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-28T23:09:06.400Z,1559084946.400 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-28T23:09:06.401Z,1559084946.401 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-28T23:09:06.722Z,1559084946.722 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-28T23:09:06.723Z,1559084946.723 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-28T23:09:06.805Z,1559084946.805 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-28T23:09:06.910Z,1559084946.910 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-28T23:09:06.911Z,1559084946.911 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-28T23:09:07.492Z,1559084947.492 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-28T23:09:07.493Z,1559084947.493 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-28T23:09:08.515Z,1559084948.515 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-28T23:09:08.517Z,1559084948.517 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-28T23:09:08.518Z,1559084948.518 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-28T23:09:08.727Z,1559084948.727 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-28T23:09:08.828Z,1559084948.828 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-28T23:09:08.927Z,1559084948.927 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-28T23:09:09.155Z,1559084949.155 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-28T23:09:09.155Z,1559084949.155 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-28T23:09:09.241Z,1559084949.241 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-28T23:09:09.335Z,1559084949.335 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-28T23:09:09.433Z,1559084949.433 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-28T23:09:09.517Z,1559084949.517 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-28T23:09:09.627Z,1559084949.627 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-28T23:09:09.798Z,1559084949.798 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-28T23:09:09.932Z,1559084949.932 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-28T23:09:09.932Z,1559084949.932 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-28T23:09:09.948Z,1559084949.948 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-28T23:09:10.318Z,1559084950.318 [AHRS_M2] Loaded
2019-05-28T23:09:10.318Z,1559084950.318 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-28T23:09:10.389Z,1559084950.389 [DataOverHttps] Loaded
2019-05-28T23:09:10.389Z,1559084950.389 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-28T23:09:10.391Z,1559084950.391 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-28T23:09:10.391Z,1559084950.391 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3441
2019-05-28T23:09:10.404Z,1559084950.404 [Depth_Keller] Loaded
2019-05-28T23:09:10.404Z,1559084950.404 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-28T23:09:10.409Z,1559084950.409 [DropWeight] Loaded
2019-05-28T23:09:10.409Z,1559084950.409 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-28T23:09:10.465Z,1559084950.465 [DUSBL_Hydroid] Loaded
2019-05-28T23:09:10.466Z,1559084950.466 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-28T23:09:10.505Z,1559084950.505 [Micromodem] Loaded
2019-05-28T23:09:10.505Z,1559084950.505 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-28T23:09:10.603Z,1559084950.603 [NAL9602] Loaded
2019-05-28T23:09:10.603Z,1559084950.603 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-28T23:09:10.619Z,1559084950.619 [Onboard] Loaded
2019-05-28T23:09:10.619Z,1559084950.619 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-28T23:09:10.625Z,1559084950.625 [PowerOnly] Loaded
2019-05-28T23:09:10.625Z,1559084950.625 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-28T23:09:10.631Z,1559084950.631 [Radio_Surface] Loaded
2019-05-28T23:09:10.631Z,1559084950.631 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-28T23:09:10.632Z,1559084950.632 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-28T23:09:10.633Z,1559084950.633 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3442
2019-05-28T23:09:10.676Z,1559084950.676 [RDI_Pathfinder] Loaded
2019-05-28T23:09:10.677Z,1559084950.677 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-28T23:09:12.152Z,1559084952.152 [BPC1] Loaded
2019-05-28T23:09:12.152Z,1559084952.152 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-28T23:09:12.152Z,1559084952.152 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-28T23:09:12.153Z,1559084952.153 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-28T23:09:12.166Z,1559084952.166 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-28T23:09:12.166Z,1559084952.166 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-28T23:09:12.271Z,1559084952.271 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-28T23:09:12.271Z,1559084952.271 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-28T23:09:12.291Z,1559084952.291 [NavChart] Loaded
2019-05-28T23:09:12.292Z,1559084952.292 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-28T23:09:12.296Z,1559084952.296 [UniversalFixResidualReporter] Loaded
2019-05-28T23:09:12.296Z,1559084952.296 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-28T23:09:12.296Z,1559084952.296 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-28T23:09:12.297Z,1559084952.297 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-28T23:09:12.404Z,1559084952.404 [BuoyancyServo] Loaded
2019-05-28T23:09:12.404Z,1559084952.404 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-28T23:09:12.419Z,1559084952.419 [ElevatorServo] Loaded
2019-05-28T23:09:12.420Z,1559084952.420 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-28T23:09:12.434Z,1559084952.434 [MassServo] Loaded
2019-05-28T23:09:12.434Z,1559084952.434 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-28T23:09:12.449Z,1559084952.449 [RudderServo] Loaded
2019-05-28T23:09:12.449Z,1559084952.449 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-28T23:09:12.464Z,1559084952.464 [ThrusterServo] Loaded
2019-05-28T23:09:12.464Z,1559084952.464 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-28T23:09:12.464Z,1559084952.464 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-28T23:09:12.465Z,1559084952.465 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-28T23:09:12.710Z,1559084952.710 [CTD_NeilBrown] Loaded
2019-05-28T23:09:12.710Z,1559084952.710 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-28T23:09:12.711Z,1559084952.711 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-28T23:09:12.711Z,1559084952.711 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3443
2019-05-28T23:09:12.755Z,1559084952.755 [WetLabsSeaOWL_UV_A] Loaded
2019-05-28T23:09:12.755Z,1559084952.755 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-28T23:09:12.756Z,1559084952.756 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-28T23:09:12.757Z,1559084952.757 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3444
2019-05-28T23:09:12.757Z,1559084952.757 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-28T23:09:12.758Z,1559084952.758 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-28T23:09:13.558Z,1559084953.558 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-28T23:09:13.559Z,1559084953.559 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-28T23:09:13.734Z,1559084953.734 [DepthRateCalculator] Loaded
2019-05-28T23:09:13.735Z,1559084953.735 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-28T23:09:13.740Z,1559084953.740 [PitchRateCalculator] Loaded
2019-05-28T23:09:13.740Z,1559084953.740 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-28T23:09:13.753Z,1559084953.753 [SpeedCalculator] Loaded
2019-05-28T23:09:13.753Z,1559084953.753 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-28T23:09:13.774Z,1559084953.774 [TempGradientCalculator] Loaded
2019-05-28T23:09:13.774Z,1559084953.774 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-28T23:09:13.779Z,1559084953.779 [YawRateCalculator] Loaded
2019-05-28T23:09:13.780Z,1559084953.780 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-28T23:09:13.819Z,1559084953.819 [ElevatorOffsetCalculator] Loaded
2019-05-28T23:09:13.819Z,1559084953.819 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-28T23:09:13.820Z,1559084953.820 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-28T23:09:13.820Z,1559084953.820 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-28T23:09:13.952Z,1559084953.952 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-28T23:09:13.974Z,1559084953.974 [SBIT] Loaded
2019-05-28T23:09:13.974Z,1559084953.974 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-28T23:09:13.975Z,1559084953.975 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-28T23:09:13.986Z,1559084953.986 [IBIT] Loaded
2019-05-28T23:09:13.986Z,1559084953.986 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-28T23:09:13.990Z,1559084953.990 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-28T23:09:14.125Z,1559084954.125 [CBIT] Loaded
2019-05-28T23:09:14.125Z,1559084954.125 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-28T23:09:14.126Z,1559084954.126 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-28T23:09:14.126Z,1559084954.126 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-28T23:09:14.206Z,1559084954.206 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-28T23:09:14.206Z,1559084954.206 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-28T23:09:14.303Z,1559084954.303 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-28T23:09:14.304Z,1559084954.304 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-28T23:09:14.369Z,1559084954.369 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-28T23:09:14.452Z,1559084954.452 [VerticalControl] Loaded
2019-05-28T23:09:14.452Z,1559084954.452 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-28T23:09:14.453Z,1559084954.453 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-28T23:09:14.510Z,1559084954.510 [HorizontalControl] Loaded
2019-05-28T23:09:14.510Z,1559084954.510 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-28T23:09:14.511Z,1559084954.511 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-28T23:09:14.513Z,1559084954.513 [SpeedControl] Loaded
2019-05-28T23:09:14.513Z,1559084954.513 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-28T23:09:14.514Z,1559084954.514 [LoopControl](DEBUG): Construct LoopControl.
2019-05-28T23:09:14.514Z,1559084954.514 [LoopControl] Loaded
2019-05-28T23:09:14.514Z,1559084954.514 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-28T23:09:14.515Z,1559084954.515 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-28T23:09:14.515Z,1559084954.515 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-28T23:09:14.542Z,1559084954.542 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-28T23:09:14.545Z,1559084954.545 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-28T23:09:14.546Z,1559084954.546 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-28T23:09:14.553Z,1559084954.553 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-28T23:09:14.554Z,1559084954.554 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD54E0
2019-05-28T23:09:14.554Z,1559084954.554 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3445
2019-05-28T23:09:14.559Z,1559084954.559 [Supervisor](INFO): Main Thread ID is 2626
2019-05-28T23:09:14.559Z,1559084954.559 [Supervisor](DEBUG): Running supervisor.
2019-05-28T23:09:14.559Z,1559084954.559 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3446
2019-05-28T23:09:14.562Z,1559084954.562 [controlThread ThreadHandler](INFO): Handler Thread ID is 3447
2019-05-28T23:09:14.562Z,1559084954.562 [controlThread](DEBUG): Initializing ControlThread
2019-05-28T23:09:14.568Z,1559084954.568 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-28T23:09:14.568Z,1559084954.568 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-28T23:09:14.570Z,1559084954.570 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-28T23:09:14.570Z,1559084954.570 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-28T23:09:14.571Z,1559084954.571 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-28T23:09:14.571Z,1559084954.571 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-28T23:09:14.571Z,1559084954.571 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-28T23:09:14.572Z,1559084954.572 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-28T23:09:14.572Z,1559084954.572 [SBIT](INFO): Initialize SBIT Component.
2019-05-28T23:09:14.573Z,1559084954.573 [SBIT](IMPORTANT): git: 2019-05-22
2019-05-28T23:09:14.573Z,1559084954.573 [SBIT](INFO): git hash: b146eb58452ebd2f190c0e5bc4ac3eb35807c4ac
2019-05-28T23:09:14.573Z,1559084954.573 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-28T23:09:14.575Z,1559084954.575 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-05-28T23:09:14.576Z,1559084954.576 [SBIT](INFO): Beginning SBIT in 39.000000 seconds.
2019-05-28T23:09:14.576Z,1559084954.576 [IBIT](INFO): Initialize IBIT Component.
2019-05-28T23:09:14.577Z,1559084954.577 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-28T23:09:14.578Z,1559084954.578 [logger ThreadHandler](INFO): Handler Thread ID is 3448
2019-05-28T23:09:14.589Z,1559084954.589 [CBIT](DEBUG): Initialized mux pins.
2019-05-28T23:09:14.589Z,1559084954.589 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-28T23:09:14.597Z,1559084954.597 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3449
2019-05-28T23:09:14.598Z,1559084954.598 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-28T23:09:14.609Z,1559084954.609 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3450
2019-05-28T23:09:14.613Z,1559084954.613 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-28T23:09:14.613Z,1559084954.613 [CBIT](DEBUG): Initializing heartbeat.
2019-05-28T23:09:14.625Z,1559084954.625 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3451
2019-05-28T23:09:14.626Z,1559084954.626 [CTD_NeilBrown](INFO): Powering down
2019-05-28T23:09:14.654Z,1559084954.654 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3452
2019-05-28T23:09:14.655Z,1559084954.655 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-28T23:09:14.685Z,1559084954.685 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-28T23:09:14.685Z,1559084954.685 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-28T23:09:14.697Z,1559084954.697 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3453
2019-05-28T23:09:14.700Z,1559084954.700 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-28T23:09:14.700Z,1559084954.700 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-28T23:09:14.701Z,1559084954.701 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-28T23:09:14.701Z,1559084954.701 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-28T23:09:14.701Z,1559084954.701 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-28T23:09:14.701Z,1559084954.701 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-28T23:09:14.701Z,1559084954.701 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-28T23:09:14.702Z,1559084954.702 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-28T23:09:14.702Z,1559084954.702 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-28T23:09:14.702Z,1559084954.702 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-28T23:09:14.702Z,1559084954.702 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-28T23:09:14.702Z,1559084954.702 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-28T23:09:14.703Z,1559084954.703 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-28T23:09:14.703Z,1559084954.703 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-28T23:09:14.703Z,1559084954.703 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-28T23:09:14.703Z,1559084954.703 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-28T23:09:14.721Z,1559084954.721 [CBIT](DEBUG): Backplane powered.
2019-05-28T23:09:14.721Z,1559084954.721 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-28T23:09:14.723Z,1559084954.723 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-28T23:09:14.723Z,1559084954.723 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-28T23:09:14.724Z,1559084954.724 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-28T23:09:14.725Z,1559084954.725 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-28T23:09:14.734Z,1559084954.734 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-28T23:09:14.761Z,1559084954.761 [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-05-28T23:09:14.762Z,1559084954.762 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-28T23:09:14.825Z,1559084954.825 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-28T23:09:14.826Z,1559084954.826 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-28T23:09:14.828Z,1559084954.828 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-28T23:09:14.871Z,1559084954.871 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-28T23:09:14.873Z,1559084954.873 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-28T23:09:14.895Z,1559084954.895 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-28T23:09:14.898Z,1559084954.898 [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-05-28T23:09:14.909Z,1559084954.909 [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-05-28T23:09:14.921Z,1559084954.921 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-28T23:09:15.002Z,1559084955.002 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-28T23:09:15.003Z,1559084955.003 [DUSBL_Hydroid](INFO): Powering up
2019-05-28T23:09:15.003Z,1559084955.003 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-28T23:09:15.013Z,1559084955.013 [Radio_Surface](INFO): Powering up
2019-05-28T23:09:15.081Z,1559084955.081 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-28T23:09:15.099Z,1559084955.099 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:09:15.105Z,1559084955.105 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-28T23:09:15.106Z,1559084955.106 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:09:15.113Z,1559084955.113 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-28T23:09:15.114Z,1559084955.114 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:09:15.121Z,1559084955.121 [MassServo](DEBUG): Initializing MassServo.
2019-05-28T23:09:15.122Z,1559084955.122 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:09:15.129Z,1559084955.129 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-28T23:09:15.130Z,1559084955.130 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:09:15.141Z,1559084955.141 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-28T23:09:15.335Z,1559084955.335 [Micromodem](INFO): Powering up
2019-05-28T23:09:15.335Z,1559084955.335 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-28T23:09:15.369Z,1559084955.369 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-28T23:09:16.053Z,1559084956.053 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-28T23:09:16.053Z,1559084956.053 [RudderServo](FAULT): Rudder failed to initialize
2019-05-28T23:09:16.053Z,1559084956.053 [RudderServo] Communications Fault, FailCount= 1
2019-05-28T23:09:16.053Z,1559084956.053 [RudderServo](ERROR): Communications Fault
2019-05-28T23:09:16.165Z,1559084956.165 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-28T23:09:16.326Z,1559084956.326 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-28T23:09:16.326Z,1559084956.326 [RudderServo](INFO): Powering down
2019-05-28T23:09:17.008Z,1559084957.008 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:09:17.130Z,1559084957.130 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-28T23:09:17.134Z,1559084957.134 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-28T23:09:17.134Z,1559084957.134 [RudderServo] No Fault, FailCount= 1
2019-05-28T23:09:28.321Z,1559084968.321 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-28T23:09:33.142Z,1559084973.142 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-28T23:09:40.019Z,1559084980.019 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,230938,COROC,0.10.0.46*4

2019-05-28T23:09:40.827Z,1559084980.827 [NAL9602](INFO): Powering up NAL9602
2019-05-28T23:09:51.735Z,1559084991.735 [NAL9602](INFO): NAL9602 initialized
2019-05-28T23:09:52.557Z,1559084992.557 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:09:54.246Z,1559084994.246 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-28T23:09:54.254Z,1559084994.254 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-28T23:10:05.445Z,1559085005.445 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.011018
CHAN A1 (24V): -0.026136
CHAN A2 (12V): -0.006191
CHAN A3 (5V): -0.001753
CHAN B0 (3.3V): 0.000049
CHAN B1 (3.15aV): 0.000052
CHAN B2 (3.15bV): -0.000045
CHAN B3 (GND): 0.001944
OPEN: 0.007628
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-28T23:10:23.182Z,1559085023.182 [CommandLine](IMPORTANT): got command show stack
2019-05-28T23:10:23.183Z,1559085023.183 [CommandLine](IMPORTANT): Behavior Stack:

2019-05-28T23:10:23.183Z,1559085023.183 [MissionManager](IMPORTANT): Mission loaded, but not running.
2019-05-28T23:10:47.935Z,1559085047.935 [SBIT](IMPORTANT): SBIT PASSED
2019-05-28T23:10:48.021Z,1559085048.021 [CommandLine](IMPORTANT): got command configSet list
2019-05-28T23:10:48.021Z,1559085048.021 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-28T23:10:48.022Z,1559085048.022 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-28T23:10:48.022Z,1559085048.022 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-28T23:10:48.022Z,1559085048.022 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=25 count;

2019-05-28T23:10:48.022Z,1559085048.022 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_chlorophyll_in_sea_water 5.000000 microgram_per_liter;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): Express none mass_concentration_of_oxygen_in_sea_water;

2019-05-28T23:10:48.023Z,1559085048.023 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-28T23:10:48.024Z,1559085048.024 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-28T23:10:48.024Z,1559085048.024 [CommandLine](IMPORTANT): VerticalControl.massDefault=5 millimeter;

2019-05-28T23:10:48.430Z,1559085048.430 [MissionManager](IMPORTANT): Started mission Startup
2019-05-28T23:10:48.430Z,1559085048.430 [Startup] Running Loop=1
2019-05-28T23:10:48.430Z,1559085048.430 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-28T23:10:48.430Z,1559085048.430 [Startup:A.GoToSurface] Running Loop=1
2019-05-28T23:10:48.431Z,1559085048.431 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T23:10:48.431Z,1559085048.431 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T23:10:48.432Z,1559085048.432 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T23:10:48.432Z,1559085048.432 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T23:10:48.432Z,1559085048.432 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T23:10:48.437Z,1559085048.437 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T23:10:48.441Z,1559085048.441 [Startup:StartupSatComms] Running Loop=1
2019-05-28T23:10:48.441Z,1559085048.441 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-28T23:10:48.442Z,1559085048.442 [Startup:StartupSatComms:A] Running Loop=1
2019-05-28T23:10:48.857Z,1559085048.857 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-28T23:11:40.787Z,1559085100.787 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004854
2019-05-28T23:11:48.553Z,1559085108.553 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-28T23:10:48.4Z
2019-05-28T23:11:48.553Z,1559085108.553 [Startup:StartupSatComms:A] Stopped
2019-05-28T23:11:48.553Z,1559085108.553 [Startup:StartupSatComms:B] Running Loop=1
2019-05-28T23:11:48.949Z,1559085108.949 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-28T23:11:54.044Z,1559085114.044 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190528T175203/Courier0121.lzma
2019-05-28T23:11:54.854Z,1559085114.854 [DataOverHttps](INFO): Moved sent file to Logs/20190528T175203/Courier0121.lzma.bak
2019-05-28T23:11:54.854Z,1559085114.854 [DataOverHttps](INFO): SBD MOMSN=11208478
2019-05-28T23:12:11.936Z,1559085131.936 [NAL9602](INFO): SBD MO Status=2, MOMSN=5511, MT Status=2, MTMSN=0
2019-05-28T23:12:11.936Z,1559085131.936 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-28T23:12:14.805Z,1559085134.805 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-28T23:12:14.805Z,1559085134.805 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-28T23:12:14.830Z,1559085134.830 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-28T23:12:15.266Z,1559085135.266 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-28T23:12:15.266Z,1559085135.266 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-28T23:12:18.542Z,1559085138.542 [DataOverHttps](INFO): Sending 380 bytes from file Logs/20190528T175203/Express0122.lzma
2019-05-28T23:12:19.347Z,1559085139.347 [DataOverHttps](INFO): Moved sent file to Logs/20190528T175203/Express0122.lzma.bak
2019-05-28T23:12:19.347Z,1559085139.347 [DataOverHttps](INFO): SBD MOMSN=11208480
2019-05-28T23:12:37.687Z,1559085157.687 [DataOverHttps](INFO): Sending 1463 bytes from file Logs/20190528T230903/Express0001.lzma
2019-05-28T23:12:38.490Z,1559085158.490 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Express0001.lzma.bak
2019-05-28T23:12:38.490Z,1559085158.490 [DataOverHttps](INFO): SBD MOMSN=11208486
2019-05-28T23:12:39.438Z,1559085159.438 [Startup:StartupSatComms:B] Stopped
2019-05-28T23:12:39.438Z,1559085159.438 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-28T23:12:39.439Z,1559085159.439 [Startup:StartupSatComms] Stopped
2019-05-28T23:12:39.439Z,1559085159.439 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-28T23:12:39.439Z,1559085159.439 [Startup](INFO): Completed Startup
2019-05-28T23:12:39.439Z,1559085159.439 [MissionManager](INFO): Startup is completed.
2019-05-28T23:12:39.440Z,1559085159.440 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-28T23:12:39.440Z,1559085159.440 [Startup] Stopped
2019-05-28T23:12:39.440Z,1559085159.440 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-28T23:12:39.440Z,1559085159.440 [Startup:A.GoToSurface] Stopped
2019-05-28T23:12:39.440Z,1559085159.440 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T23:12:39.846Z,1559085159.846 [MissionManager](IMPORTANT): Started mission Default
2019-05-28T23:12:39.846Z,1559085159.846 [Default] Running Loop=1
2019-05-28T23:12:39.846Z,1559085159.846 [Default](DEBUG): Aggregate::initialize Default
2019-05-28T23:12:39.846Z,1559085159.846 [Default:B.GoToSurface] Running Loop=1
2019-05-28T23:12:39.846Z,1559085159.846 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T23:12:39.846Z,1559085159.846 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T23:12:39.847Z,1559085159.847 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T23:12:39.847Z,1559085159.847 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T23:12:39.847Z,1559085159.847 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T23:12:39.848Z,1559085159.848 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T23:12:39.848Z,1559085159.848 [Default:A.Wait] Running Loop=1
2019-05-28T23:12:39.848Z,1559085159.848 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:12:46.277Z,1559085166.277 [NAL9602](INFO): SBD MO Status=2, MOMSN=5511, MT Status=2, MTMSN=0
2019-05-28T23:12:46.277Z,1559085166.277 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-28T23:12:53.175Z,1559085173.175 [Default:A.Wait](INFO): Done Waiting.
2019-05-28T23:12:53.175Z,1559085173.175 [Default:A.Wait] Stopped
2019-05-28T23:12:53.175Z,1559085173.175 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:12:53.584Z,1559085173.584 [Default:CheckIn] Running Loop=1
2019-05-28T23:12:53.584Z,1559085173.584 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-28T23:12:53.584Z,1559085173.584 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-28T23:12:53.998Z,1559085173.998 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-28T23:13:13.344Z,1559085193.344 [NAL9602](INFO): SBD MO Status=2, MOMSN=5511, MT Status=2, MTMSN=0
2019-05-28T23:13:13.345Z,1559085193.345 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-28T23:13:29.909Z,1559085209.909 [NAL9602](INFO): SBD MO Status=0, MOMSN=5511, MT Status=0, MTMSN=0
2019-05-28T23:13:29.909Z,1559085209.909 [NAL9602](INFO): No messages in MT queue
2019-05-28T23:13:30.741Z,1559085210.741 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:13:31.126Z,1559085211.126 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231331.00,A,3648.16950,N,12147.27898,W,0.156,0.00,280519,,,A*77
2019-05-28T23:13:31.130Z,1559085211.130 [NAL9602](INFO): GPS fix at 20190528T231331: (36.802825, -121.787983)
2019-05-28T23:13:31.176Z,1559085211.176 [Default:CheckIn:Read_GPS] Stopped
2019-05-28T23:13:31.176Z,1559085211.176 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-28T23:13:31.591Z,1559085211.591 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-28T23:13:39.681Z,1559085219.681 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190528T230903/Courier0004.lzma
2019-05-28T23:13:40.502Z,1559085220.502 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Courier0004.lzma.bak
2019-05-28T23:13:40.503Z,1559085220.503 [DataOverHttps](INFO): SBD MOMSN=11208518
2019-05-28T23:13:54.461Z,1559085234.461 [DataOverHttps](INFO): Sending 384 bytes from file Logs/20190528T230903/Express0005.lzma
2019-05-28T23:13:55.266Z,1559085235.266 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Express0005.lzma.bak
2019-05-28T23:13:55.266Z,1559085235.266 [DataOverHttps](INFO): SBD MOMSN=11208523
2019-05-28T23:13:56.308Z,1559085236.308 [Default:CheckIn:Read_Iridium] Stopped
2019-05-28T23:13:56.308Z,1559085236.308 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-28T23:13:56.308Z,1559085236.308 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:14:03.458Z,1559085243.458 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-28T23:16:42.279Z,1559085402.279 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-28T23:16:42.298Z,1559085402.298 [BPC1](INFO): Received data from all battery sticks.
2019-05-28T23:18:56.797Z,1559085536.797 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-28T23:18:56.797Z,1559085536.797 [Default:CheckIn:C.Wait] Stopped
2019-05-28T23:18:56.798Z,1559085536.798 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:18:56.798Z,1559085536.798 [Default:CheckIn:D] Running Loop=1
2019-05-28T23:18:57.236Z,1559085537.236 [Default:CheckIn:D] Stopped
2019-05-28T23:18:57.236Z,1559085537.236 [Default:CheckIn:E] Running Loop=1
2019-05-28T23:18:57.609Z,1559085537.609 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.289836 min 
2019-05-28T23:18:57.609Z,1559085537.609 [Default:CheckIn:E] Stopped
2019-05-28T23:18:57.609Z,1559085537.609 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-28T23:18:57.609Z,1559085537.609 [Default:CheckIn] Stopped
2019-05-28T23:18:57.609Z,1559085537.609 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-28T23:18:57.609Z,1559085537.609 [Default:CheckIn](INFO): Running loop #2
2019-05-28T23:18:57.610Z,1559085537.610 [Default:CheckIn] Running Loop=2
2019-05-28T23:18:57.610Z,1559085537.610 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-28T23:18:57.610Z,1559085537.610 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-28T23:18:59.217Z,1559085539.217 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:18:59.604Z,1559085539.604 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231859.00,A,3648.16711,N,12147.27990,W,0.156,0.00,280519,,,A*70
2019-05-28T23:18:59.607Z,1559085539.607 [NAL9602](INFO): GPS fix at 20190528T231859: (36.802785, -121.787998)
2019-05-28T23:18:59.631Z,1559085539.631 [Default:CheckIn:Read_GPS] Stopped
2019-05-28T23:18:59.631Z,1559085539.631 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-28T23:19:05.437Z,1559085545.437 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190528T230903/Courier0007.lzma
2019-05-28T23:19:06.242Z,1559085546.242 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Courier0007.lzma.bak
2019-05-28T23:19:06.242Z,1559085546.242 [DataOverHttps](INFO): SBD MOMSN=11208561
2019-05-28T23:19:17.709Z,1559085557.709 [DataOverHttps](INFO): Sending 643 bytes from file Logs/20190528T230903/Express0008.lzma
2019-05-28T23:19:18.514Z,1559085558.514 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Express0008.lzma.bak
2019-05-28T23:19:18.514Z,1559085558.514 [DataOverHttps](INFO): SBD MOMSN=11208564
2019-05-28T23:19:19.456Z,1559085559.456 [Default:CheckIn:Read_Iridium] Stopped
2019-05-28T23:19:19.456Z,1559085559.456 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-28T23:19:19.456Z,1559085559.456 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:20:47.473Z,1559085647.473 [NAL9602](INFO): SBD MO Status=2, MOMSN=5512, MT Status=2, MTMSN=0
2019-05-28T23:20:47.473Z,1559085647.473 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-28T23:21:18.980Z,1559085678.980 [NAL9602](INFO): SBD MO Status=2, MOMSN=5512, MT Status=2, MTMSN=0
2019-05-28T23:21:18.980Z,1559085678.980 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-28T23:22:34.541Z,1559085754.541 [NAL9602](INFO): SBD MO Status=2, MOMSN=5512, MT Status=2, MTMSN=0
2019-05-28T23:22:34.541Z,1559085754.541 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-28T23:22:55.577Z,1559085775.577 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-28T23:22:55.578Z,1559085775.578 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00
2019-05-28T23:24:01.391Z,1559085841.391 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-28T23:24:19.787Z,1559085859.787 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:24:19.787Z,1559085859.787 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:24:19.817Z,1559085859.817 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-28T23:24:19.820Z,1559085859.820 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-28T23:24:19.824Z,1559085859.824 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-28T23:24:19.828Z,1559085859.828 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-28T23:24:19.831Z,1559085859.831 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-28T23:24:19.832Z,1559085859.832 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-28T23:24:19.843Z,1559085859.843 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-28T23:24:19.852Z,1559085859.852 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-28T23:24:19.857Z,1559085859.857 [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>90</Value></Setting>
          </Guidance:Wait>
      </Aggregate>    
</Mission>


2019-05-28T23:24:19.859Z,1559085859.859 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:24:19.996Z,1559085859.996 [Default] Stopped
2019-05-28T23:24:19.996Z,1559085859.996 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-28T23:24:19.996Z,1559085859.996 [Default:B.GoToSurface] Stopped
2019-05-28T23:24:19.996Z,1559085859.996 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T23:24:19.996Z,1559085859.996 [Default:CheckIn] Stopped
2019-05-28T23:24:19.996Z,1559085859.996 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-28T23:24:19.996Z,1559085859.996 [Default:CheckIn:C.Wait] Stopped
2019-05-28T23:24:19.996Z,1559085859.996 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:24:19.996Z,1559085859.996 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-28T23:24:19.997Z,1559085859.997 [DUSBL] Running Loop=1
2019-05-28T23:24:19.997Z,1559085859.997 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-28T23:24:19.997Z,1559085859.997 [DUSBL:A.Pitch] Running Loop=1
2019-05-28T23:24:19.997Z,1559085859.997 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-28T23:24:19.997Z,1559085859.997 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:C] Running Loop=1
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:RequestRepeater] Running Loop=1
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-28T23:24:19.998Z,1559085859.998 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:24:19.999Z,1559085859.999 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:24:19.999Z,1559085859.999 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:24:19.000Z,1559085860.000 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-28T23:24:20.000Z,1559085860.000 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-28T23:24:20.000Z,1559085860.000 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-28T23:24:20.005Z,1559085860.005 [DUSBL:A.Pitch] Running Loop=1
2019-05-28T23:24:30.074Z,1559085870.074 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-05-28T23:24:32.091Z,1559085872.091 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-28T23:24:37.750Z,1559085877.750 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:24:41.786Z,1559085881.786 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:24:46.230Z,1559085886.230 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:24:47.846Z,1559085887.846 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-05-28T23:24:51.890Z,1559085891.890 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:24:58.431Z,1559085898.431 [CommandLine](IMPORTANT): got command stop
2019-05-28T23:24:58.431Z,1559085898.431 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-28T23:24:58.431Z,1559085898.431 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-28T23:24:58.781Z,1559085898.781 [MissionManager](INFO): MissionManager is completed.
2019-05-28T23:24:58.781Z,1559085898.781 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-28T23:24:58.781Z,1559085898.781 [DUSBL] Stopped
2019-05-28T23:24:58.781Z,1559085898.781 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-28T23:24:58.781Z,1559085898.781 [DUSBL:A.Pitch] Stopped
2019-05-28T23:24:58.781Z,1559085898.781 [DUSBL:B.SetSpeed] Stopped
2019-05-28T23:24:58.781Z,1559085898.781 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-28T23:24:58.782Z,1559085898.782 [DUSBL:C] Stopped
2019-05-28T23:24:58.782Z,1559085898.782 [DUSBL:RequestRepeater] Stopped
2019-05-28T23:24:58.782Z,1559085898.782 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-28T23:24:58.782Z,1559085898.782 [DUSBL:RequestRepeater:A] Stopped
2019-05-28T23:24:58.782Z,1559085898.782 [DUSBL:RequestRepeater:B] Stopped
2019-05-28T23:24:58.782Z,1559085898.782 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-28T23:24:58.782Z,1559085898.782 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:24:59.204Z,1559085899.204 [MissionManager](IMPORTANT): Started mission Default
2019-05-28T23:24:59.204Z,1559085899.204 [Default] Running Loop=1
2019-05-28T23:24:59.204Z,1559085899.204 [Default](DEBUG): Aggregate::initialize Default
2019-05-28T23:24:59.204Z,1559085899.204 [Default:B.GoToSurface] Running Loop=1
2019-05-28T23:24:59.204Z,1559085899.204 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T23:24:59.204Z,1559085899.204 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T23:24:59.205Z,1559085899.205 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T23:24:59.205Z,1559085899.205 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T23:24:59.206Z,1559085899.206 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T23:24:59.206Z,1559085899.206 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T23:24:59.206Z,1559085899.206 [Default:A.Wait] Running Loop=1
2019-05-28T23:24:59.206Z,1559085899.206 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:25:01.605Z,1559085901.605 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-28T23:25:01.605Z,1559085901.605 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-28T23:25:12.535Z,1559085912.535 [Default:A.Wait](INFO): Done Waiting.
2019-05-28T23:25:12.535Z,1559085912.535 [Default:A.Wait] Stopped
2019-05-28T23:25:12.535Z,1559085912.535 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:25:12.935Z,1559085912.935 [Default:CheckIn] Running Loop=1
2019-05-28T23:25:12.935Z,1559085912.935 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-28T23:25:12.936Z,1559085912.936 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-28T23:25:14.545Z,1559085914.545 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:25:14.916Z,1559085914.916 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,232515.00,A,3648.16752,N,12147.28000,W,0.097,0.00,280519,,,A*72
2019-05-28T23:25:14.919Z,1559085914.919 [NAL9602](INFO): GPS fix at 20190528T232515: (36.802792, -121.788000)
2019-05-28T23:25:14.942Z,1559085914.942 [Default:CheckIn:Read_GPS] Stopped
2019-05-28T23:25:14.942Z,1559085914.942 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-28T23:25:23.628Z,1559085923.628 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190528T230903/Courier0010.lzma
2019-05-28T23:25:24.434Z,1559085924.434 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Courier0010.lzma.bak
2019-05-28T23:25:24.435Z,1559085924.435 [DataOverHttps](INFO): SBD MOMSN=11208568
2019-05-28T23:25:37.774Z,1559085937.774 [DataOverHttps](INFO): Sending 1037 bytes from file Logs/20190528T230903/Express0011.lzma
2019-05-28T23:25:38.578Z,1559085938.578 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Express0011.lzma.bak
2019-05-28T23:25:38.578Z,1559085938.578 [DataOverHttps](INFO): SBD MOMSN=11208571
2019-05-28T23:25:39.680Z,1559085939.680 [Default:CheckIn:Read_Iridium] Stopped
2019-05-28T23:25:39.680Z,1559085939.680 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-28T23:25:39.680Z,1559085939.680 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:25:44.571Z,1559085944.571 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.detectionThreshold 45.000000 count persist
2019-05-28T23:25:45.707Z,1559085945.707 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-28T23:25:45.785Z,1559085945.785 [NAL9602](FAULT): received: 
+CSQ:0

OK12, 2, 0, 0, 0

OK
2019-05-28T23:25:45.785Z,1559085945.785 [NAL9602] Data Fault, FailCount= 1
2019-05-28T23:25:45.785Z,1559085945.785 [NAL9602](ERROR): Data Fault
2019-05-28T23:25:45.873Z,1559085945.873 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-28T23:25:46.107Z,1559085946.107 [NAL9602](INFO): Powering down
2019-05-28T23:25:46.997Z,1559085946.997 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-28T23:25:46.997Z,1559085946.997 [NAL9602] No Fault, FailCount= 1
2019-05-28T23:26:02.874Z,1559085962.874 [CommandLine](IMPORTANT): got command failComponent hardware DUSBL_Hydroid
2019-05-28T23:26:02.875Z,1559085962.875 [DUSBL_Hydroid] Hardware Fault, FailCount= 1
2019-05-28T23:26:02.875Z,1559085962.875 [DUSBL_Hydroid](ERROR): Hardware Fault
2019-05-28T23:26:02.875Z,1559085962.875 [CommandLine](IMPORTANT): DUSBL_Hydroid failureMode is Hardware Fault
2019-05-28T23:26:03.074Z,1559085963.074 [DUSBL_Hydroid](INFO): Powering down
2019-05-28T23:26:03.224Z,1559085963.224 [CBIT](ERROR): Hardware Fault in component: DUSBL_Hydroid
2019-05-28T23:26:03.914Z,1559085963.914 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-05-28T23:26:03.914Z,1559085963.914 [DUSBL_Hydroid] No Fault, FailCount= 1
2019-05-28T23:26:06.310Z,1559085966.310 [DUSBL_Hydroid](INFO): Powering up
2019-05-28T23:26:06.310Z,1559085966.310 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-28T23:26:09.561Z,1559085969.561 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-28T23:26:09.561Z,1559085969.561 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  93.93,  93.26,   0.00
2019-05-28T23:26:16.407Z,1559085976.407 [NAL9602](INFO): Powering up NAL9602
2019-05-28T23:26:24.486Z,1559085984.486 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-28T23:26:27.322Z,1559085987.322 [NAL9602](INFO): NAL9602 initialized
2019-05-28T23:26:44.222Z,1559086004.222 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:26:44.223Z,1559086004.223 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:26:44.248Z,1559086004.248 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-28T23:26:44.250Z,1559086004.250 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-28T23:26:44.252Z,1559086004.252 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-28T23:26:44.254Z,1559086004.254 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-28T23:26:44.256Z,1559086004.256 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-28T23:26:44.257Z,1559086004.257 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-28T23:26:44.261Z,1559086004.261 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-28T23:26:44.339Z,1559086004.339 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-28T23:26:44.352Z,1559086004.352 [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>90</Value></Setting>
          </Guidance:Wait>
      </Aggregate>    
</Mission>


2019-05-28T23:26:44.354Z,1559086004.354 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:26:44.379Z,1559086004.379 [Default] Stopped
2019-05-28T23:26:44.379Z,1559086004.379 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-28T23:26:44.379Z,1559086004.379 [Default:B.GoToSurface] Stopped
2019-05-28T23:26:44.379Z,1559086004.379 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T23:26:44.379Z,1559086004.379 [Default:CheckIn] Stopped
2019-05-28T23:26:44.380Z,1559086004.380 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-28T23:26:44.380Z,1559086004.380 [Default:CheckIn:C.Wait] Stopped
2019-05-28T23:26:44.380Z,1559086004.380 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:26:44.380Z,1559086004.380 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-28T23:26:44.389Z,1559086004.389 [DUSBL] Running Loop=1
2019-05-28T23:26:44.389Z,1559086004.389 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-28T23:26:44.389Z,1559086004.389 [DUSBL:A.Pitch] Running Loop=1
2019-05-28T23:26:44.389Z,1559086004.389 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-28T23:26:44.389Z,1559086004.389 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-28T23:26:44.389Z,1559086004.389 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-28T23:26:44.389Z,1559086004.389 [DUSBL:C] Running Loop=1
2019-05-28T23:26:44.390Z,1559086004.390 [DUSBL:RequestRepeater] Running Loop=1
2019-05-28T23:26:44.390Z,1559086004.390 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-28T23:26:44.390Z,1559086004.390 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:26:44.390Z,1559086004.390 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:26:44.390Z,1559086004.390 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-28T23:26:44.390Z,1559086004.390 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:26:44.391Z,1559086004.391 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:26:44.391Z,1559086004.391 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:26:44.392Z,1559086004.392 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-28T23:26:44.392Z,1559086004.392 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-28T23:26:44.407Z,1559086004.407 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-28T23:26:44.407Z,1559086004.407 [DUSBL:A.Pitch] Running Loop=1
2019-05-28T23:26:53.185Z,1559086013.185 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:26:58.427Z,1559086018.427 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-28T23:27:25.085Z,1559086045.085 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:27:36.635Z,1559086056.635 [CommandLine](IMPORTANT): got command report touch 
2019-05-28T23:27:36.636Z,1559086056.636 [CommandLine](FAULT): Incomplete syntax. Try: help report
2019-05-28T23:27:43.670Z,1559086063.670 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:27:51.350Z,1559086071.350 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:28:12.186Z,1559086092.186 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-28T23:28:12.354Z,1559086092.354 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:28:14.010Z,1559086094.010 [Reporter](INFO): acoustic_contact_range 7.680000 m
2019-05-28T23:28:14.416Z,1559086094.416 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-28T23:28:14.416Z,1559086094.416 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-28T23:28:14.416Z,1559086094.416 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:28:14.417Z,1559086094.417 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-28T23:28:14.417Z,1559086094.417 [DUSBL:RequestRepeater] Stopped
2019-05-28T23:28:14.417Z,1559086094.417 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-28T23:28:14.417Z,1559086094.417 [DUSBL:RequestRepeater:A] Stopped
2019-05-28T23:28:14.417Z,1559086094.417 [DUSBL:RequestRepeater:B] Stopped
2019-05-28T23:28:14.418Z,1559086094.418 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-28T23:28:14.418Z,1559086094.418 [DUSBL:RequestRepeater] Running Loop=2
2019-05-28T23:28:14.418Z,1559086094.418 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-28T23:28:14.418Z,1559086094.418 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:28:14.418Z,1559086094.418 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:28:14.418Z,1559086094.418 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-28T23:28:14.418Z,1559086094.418 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:28:17.646Z,1559086097.646 [Reporter](INFO): acoustic_contact_range 7.740000 m
2019-05-28T23:28:21.290Z,1559086101.290 [Reporter](INFO): acoustic_contact_range 7.619999 m
2019-05-28T23:28:27.303Z,1559086107.303 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:28:31.342Z,1559086111.342 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:28:33.002Z,1559086113.002 [Reporter](INFO): acoustic_contact_range 41.700001 m
2019-05-28T23:28:36.633Z,1559086116.633 [Reporter](INFO): acoustic_contact_range 7.680000 m
2019-05-28T23:28:40.286Z,1559086120.286 [Reporter](INFO): acoustic_contact_range 7.919999 m
2019-05-28T23:28:43.914Z,1559086123.914 [Reporter](INFO): acoustic_contact_range 21.959997 m
2019-05-28T23:28:47.558Z,1559086127.558 [Reporter](INFO): acoustic_contact_range 7.859998 m
2019-05-28T23:28:51.198Z,1559086131.198 [Reporter](INFO): acoustic_contact_range 7.680000 m
2019-05-28T23:28:54.846Z,1559086134.846 [Reporter](INFO): acoustic_contact_range 7.619999 m
2019-05-28T23:28:58.475Z,1559086138.475 [Reporter](INFO): acoustic_contact_range 7.559999 m
2019-05-28T23:29:02.114Z,1559086142.114 [Reporter](INFO): acoustic_contact_range 7.559999 m
2019-05-28T23:29:05.725Z,1559086145.725 [Reporter](INFO): acoustic_contact_range 7.979999 m
2019-05-28T23:29:09.366Z,1559086149.366 [Reporter](INFO): acoustic_contact_range 18.240002 m
2019-05-28T23:29:12.196Z,1559086152.196 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-28T23:29:12.196Z,1559086152.196 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   -18,    +7,    E,   -18,    +7,    -7,A
2019-05-28T23:29:12.555Z,1559086152.555 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-28T23:29:12.562Z,1559086152.562 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190528232911.320236,06,338,13,0092,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,193,-0.05,-999,9760,4000*7B

2019-05-28T23:29:12.998Z,1559086152.998 [Reporter](INFO): acoustic_contact_range 18.179998 m
2019-05-28T23:29:16.629Z,1559086156.629 [Reporter](INFO): acoustic_contact_range 22.379997 m
2019-05-28T23:29:23.055Z,1559086163.055 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:29:24.743Z,1559086164.743 [Reporter](INFO): acoustic_contact_range 7.559999 m
2019-05-28T23:29:28.348Z,1559086168.348 [Reporter](INFO): acoustic_contact_range 7.559999 m
2019-05-28T23:29:31.986Z,1559086171.986 [Reporter](INFO): acoustic_contact_range 7.680000 m
2019-05-28T23:29:35.626Z,1559086175.626 [Reporter](INFO): acoustic_contact_range 8.219998 m
2019-05-28T23:29:39.270Z,1559086179.270 [Reporter](INFO): acoustic_contact_range 7.619999 m
2019-05-28T23:29:44.908Z,1559086184.908 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-28T23:29:44.908Z,1559086184.908 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-28T23:29:44.908Z,1559086184.908 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:29:44.911Z,1559086184.911 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater] Stopped
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater:A] Stopped
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater:B] Stopped
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater] Running Loop=3
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:29:44.912Z,1559086184.912 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:29:44.913Z,1559086184.913 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-28T23:29:44.913Z,1559086184.913 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:29:45.275Z,1559086185.275 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:29:46.946Z,1559086186.946 [Reporter](INFO): acoustic_contact_range 7.619999 m
2019-05-28T23:29:52.954Z,1559086192.954 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:29:54.673Z,1559086194.673 [Reporter](INFO): acoustic_contact_range 8.820000 m
2019-05-28T23:29:58.247Z,1559086198.247 [Reporter](INFO): acoustic_contact_range 7.380000 m
2019-05-28T23:30:04.266Z,1559086204.266 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:30:08.306Z,1559086208.306 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-05-28T23:30:09.342Z,1559086209.342 [CommandLine](IMPORTANT): got command stop
2019-05-28T23:30:09.343Z,1559086209.343 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-28T23:30:09.561Z,1559086209.561 [MissionManager](INFO): MissionManager is completed.
2019-05-28T23:30:09.561Z,1559086209.561 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-28T23:30:09.561Z,1559086209.561 [DUSBL] Stopped
2019-05-28T23:30:09.561Z,1559086209.561 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-28T23:30:09.561Z,1559086209.561 [DUSBL:A.Pitch] Stopped
2019-05-28T23:30:09.561Z,1559086209.561 [DUSBL:B.SetSpeed] Stopped
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:C] Stopped
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:RequestRepeater] Stopped
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:RequestRepeater:A] Stopped
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:RequestRepeater:B] Stopped
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-28T23:30:09.562Z,1559086209.562 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:30:09.960Z,1559086209.960 [MissionManager](IMPORTANT): Started mission Default
2019-05-28T23:30:09.960Z,1559086209.960 [Default] Running Loop=1
2019-05-28T23:30:09.961Z,1559086209.961 [Default](DEBUG): Aggregate::initialize Default
2019-05-28T23:30:09.961Z,1559086209.961 [Default:B.GoToSurface] Running Loop=1
2019-05-28T23:30:09.961Z,1559086209.961 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T23:30:09.961Z,1559086209.961 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T23:30:09.961Z,1559086209.961 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T23:30:09.962Z,1559086209.962 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T23:30:09.962Z,1559086209.962 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T23:30:09.962Z,1559086209.962 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T23:30:09.963Z,1559086209.963 [Default:A.Wait] Running Loop=1
2019-05-28T23:30:09.963Z,1559086209.963 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:30:11.557Z,1559086211.557 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-28T23:30:11.557Z,1559086211.557 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19052816394050,35.0, -0.1,   0.0,1448.9A,  0.00,  98.25,  92.26,  88.94,  56.33
2019-05-28T23:30:23.307Z,1559086223.307 [Default:A.Wait](INFO): Done Waiting.
2019-05-28T23:30:23.307Z,1559086223.307 [Default:A.Wait] Stopped
2019-05-28T23:30:23.307Z,1559086223.307 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:30:23.684Z,1559086223.684 [Default:CheckIn] Running Loop=1
2019-05-28T23:30:23.684Z,1559086223.684 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-28T23:30:23.684Z,1559086223.684 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-28T23:30:25.285Z,1559086225.285 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:30:25.681Z,1559086225.681 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,233024.00,A,3648.16936,N,12147.27971,W,0.233,0.00,280519,,,A*74
2019-05-28T23:30:25.683Z,1559086225.683 [NAL9602](INFO): GPS fix at 20190528T233024: (36.802823, -121.787995)
2019-05-28T23:30:25.716Z,1559086225.716 [Default:CheckIn:Read_GPS] Stopped
2019-05-28T23:30:25.716Z,1559086225.716 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-28T23:30:27.171Z,1559086227.171 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-28T23:30:27.554Z,1559086227.554 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.detectionThreshold 35.000000 count persist
2019-05-28T23:30:31.668Z,1559086231.668 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190528T230903/Courier0013.lzma
2019-05-28T23:30:32.474Z,1559086232.474 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Courier0013.lzma.bak
2019-05-28T23:30:32.475Z,1559086232.475 [DataOverHttps](INFO): SBD MOMSN=11208585
2019-05-28T23:30:38.307Z,1559086238.307 [CommandLine](IMPORTANT): got command failComponent hardware DUSBL_Hydroid
2019-05-28T23:30:38.307Z,1559086238.307 [DUSBL_Hydroid] Hardware Fault, FailCount= 1
2019-05-28T23:30:38.307Z,1559086238.307 [DUSBL_Hydroid](ERROR): Hardware Fault
2019-05-28T23:30:38.307Z,1559086238.307 [CommandLine](IMPORTANT): DUSBL_Hydroid failureMode is Hardware Fault
2019-05-28T23:30:38.497Z,1559086238.497 [DUSBL_Hydroid](INFO): Powering down
2019-05-28T23:30:38.632Z,1559086238.632 [CBIT](ERROR): Hardware Fault in component: DUSBL_Hydroid
2019-05-28T23:30:39.347Z,1559086239.347 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-05-28T23:30:39.347Z,1559086239.347 [DUSBL_Hydroid] No Fault, FailCount= 1
2019-05-28T23:30:41.714Z,1559086241.714 [DUSBL_Hydroid](INFO): Powering up
2019-05-28T23:30:41.714Z,1559086241.714 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-28T23:30:45.487Z,1559086245.487 [DataOverHttps](INFO): Sending 1358 bytes from file Logs/20190528T230903/Express0014.lzma
2019-05-28T23:30:46.291Z,1559086246.291 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Express0014.lzma.bak
2019-05-28T23:30:46.291Z,1559086246.291 [DataOverHttps](INFO): SBD MOMSN=11208588
2019-05-28T23:30:47.471Z,1559086247.471 [Default:CheckIn:Read_Iridium] Stopped
2019-05-28T23:30:47.471Z,1559086247.471 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-28T23:30:47.471Z,1559086247.471 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:30:57.875Z,1559086257.875 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-28T23:30:59.894Z,1559086259.894 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-28T23:31:45.574Z,1559086305.574 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-28T23:31:45.574Z,1559086305.574 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19052816411450,35.0, -0.1,   0.0,1448.9,,  0.00,   0.00,  92.43,  88.44,  55.00
2019-05-28T23:33:43.550Z,1559086423.550 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:33:43.550Z,1559086423.550 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:33:43.615Z,1559086423.615 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-28T23:33:43.621Z,1559086423.621 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-28T23:33:43.623Z,1559086423.623 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-28T23:33:43.630Z,1559086423.630 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-28T23:33:43.632Z,1559086423.632 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-28T23:33:43.637Z,1559086423.637 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-28T23:33:43.645Z,1559086423.645 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-28T23:33:43.656Z,1559086423.656 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-28T23:33:43.679Z,1559086423.679 [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>90</Value></Setting>
          </Guidance:Wait>
      </Aggregate>    
</Mission>


2019-05-28T23:33:43.685Z,1559086423.685 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-28T23:33:43.948Z,1559086423.948 [Default] Stopped
2019-05-28T23:33:43.948Z,1559086423.948 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-28T23:33:43.948Z,1559086423.948 [Default:B.GoToSurface] Stopped
2019-05-28T23:33:43.948Z,1559086423.948 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T23:33:43.948Z,1559086423.948 [Default:CheckIn] Stopped
2019-05-28T23:33:43.948Z,1559086423.948 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-28T23:33:43.948Z,1559086423.948 [Default:CheckIn:C.Wait] Stopped
2019-05-28T23:33:43.948Z,1559086423.948 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:33:43.948Z,1559086423.948 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-28T23:33:43.949Z,1559086423.949 [DUSBL] Running Loop=1
2019-05-28T23:33:43.949Z,1559086423.949 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-28T23:33:43.949Z,1559086423.949 [DUSBL:A.Pitch] Running Loop=1
2019-05-28T23:33:43.949Z,1559086423.949 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-28T23:33:43.949Z,1559086423.949 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-28T23:33:43.949Z,1559086423.949 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-28T23:33:43.949Z,1559086423.949 [DUSBL:C] Running Loop=1
2019-05-28T23:33:43.950Z,1559086423.950 [DUSBL:RequestRepeater] Running Loop=1
2019-05-28T23:33:43.950Z,1559086423.950 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-28T23:33:43.950Z,1559086423.950 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:33:43.950Z,1559086423.950 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:33:43.950Z,1559086423.950 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-28T23:33:43.950Z,1559086423.950 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:33:43.951Z,1559086423.951 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-28T23:33:43.951Z,1559086423.951 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-28T23:33:43.952Z,1559086423.952 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-28T23:33:43.952Z,1559086423.952 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-28T23:33:43.952Z,1559086423.952 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-28T23:33:43.952Z,1559086423.952 [DUSBL:A.Pitch] Running Loop=1
2019-05-28T23:33:46.786Z,1559086426.786 [Reporter](INFO): acoustic_contact_range 7.139998 m
2019-05-28T23:33:50.430Z,1559086430.430 [Reporter](INFO): acoustic_contact_range 7.020000 m
2019-05-28T23:33:54.062Z,1559086434.062 [Reporter](INFO): acoustic_contact_range 69.600006 m
2019-05-28T23:33:57.698Z,1559086437.698 [Reporter](INFO): acoustic_contact_range 69.600006 m
2019-05-28T23:34:01.354Z,1559086441.354 [Reporter](INFO): acoustic_contact_range 7.199999 m
2019-05-28T23:34:04.990Z,1559086444.990 [Reporter](INFO): acoustic_contact_range 3.839998 m
2019-05-28T23:34:07.622Z,1559086447.622 [CommandLine](IMPORTANT): got command stop
2019-05-28T23:34:07.623Z,1559086447.623 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-28T23:34:07.808Z,1559086447.808 [MissionManager](INFO): MissionManager is completed.
2019-05-28T23:34:07.813Z,1559086447.813 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-28T23:34:07.814Z,1559086447.814 [DUSBL] Stopped
2019-05-28T23:34:07.814Z,1559086447.814 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-28T23:34:07.814Z,1559086447.814 [DUSBL:A.Pitch] Stopped
2019-05-28T23:34:07.814Z,1559086447.814 [DUSBL:B.SetSpeed] Stopped
2019-05-28T23:34:07.814Z,1559086447.814 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-28T23:34:07.814Z,1559086447.814 [DUSBL:C] Stopped
2019-0