2019-05-07T04:58:06.108Z,1557205086.108 [Supervisor](DEBUG): Initializing supervisor.
2019-05-07T04:58:06.111Z,1557205086.111 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-07T04:58:06.112Z,1557205086.112 [SyncHandler](INFO): Protected caller Thread ID is 2140
2019-05-07T04:58:06.113Z,1557205086.113 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-07T04:58:06.114Z,1557205086.114 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-07T04:58:06.114Z,1557205086.114 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2141
2019-05-07T04:58:06.117Z,1557205086.117 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-07T04:58:06.130Z,1557205086.130 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-07T04:58:06.131Z,1557205086.131 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-07T04:58:06.131Z,1557205086.131 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2142
2019-05-07T04:58:06.132Z,1557205086.132 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-07T04:58:06.133Z,1557205086.133 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-07T04:58:06.133Z,1557205086.133 [logger ThreadHandler](INFO): Protected caller Thread ID is 2143
2019-05-07T04:58:06.135Z,1557205086.135 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-07T04:58:06.136Z,1557205086.136 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-07T04:58:06.137Z,1557205086.137 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-07T04:58:06.561Z,1557205086.561 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-07T04:58:06.562Z,1557205086.562 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-07T04:58:06.660Z,1557205086.660 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-07T04:58:06.660Z,1557205086.660 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-07T04:58:06.987Z,1557205086.987 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-07T04:58:06.987Z,1557205086.987 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-07T04:58:07.130Z,1557205087.130 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-07T04:58:07.130Z,1557205087.130 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-07T04:58:07.322Z,1557205087.322 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-07T04:58:07.323Z,1557205087.323 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-07T04:58:07.795Z,1557205087.795 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-07T04:58:07.796Z,1557205087.796 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-07T04:58:08.087Z,1557205088.087 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-07T04:58:08.087Z,1557205088.087 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-07T04:58:08.234Z,1557205088.234 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-07T04:58:08.235Z,1557205088.235 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-07T04:58:08.429Z,1557205088.429 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-07T04:58:08.430Z,1557205088.430 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-07T04:58:08.526Z,1557205088.526 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-07T04:58:08.527Z,1557205088.527 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-07T04:58:08.852Z,1557205088.852 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-07T04:58:08.853Z,1557205088.853 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-07T04:58:08.933Z,1557205088.933 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-07T04:58:09.037Z,1557205089.037 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-07T04:58:09.037Z,1557205089.037 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-07T04:58:09.615Z,1557205089.615 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-07T04:58:09.616Z,1557205089.616 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-07T04:58:10.009Z,1557205090.009 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-07T04:58:10.012Z,1557205090.012 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-07T04:58:10.012Z,1557205090.012 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-07T04:58:10.222Z,1557205090.222 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-07T04:58:10.323Z,1557205090.323 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-07T04:58:10.421Z,1557205090.421 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-07T04:58:10.648Z,1557205090.648 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-07T04:58:10.648Z,1557205090.648 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-07T04:58:10.733Z,1557205090.733 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-07T04:58:10.827Z,1557205090.827 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-07T04:58:10.924Z,1557205090.924 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-07T04:58:11.006Z,1557205091.006 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-07T04:58:11.115Z,1557205091.115 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-07T04:58:11.285Z,1557205091.285 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-07T04:58:11.417Z,1557205091.417 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-07T04:58:11.418Z,1557205091.418 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-07T04:58:11.431Z,1557205091.431 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-07T04:58:11.815Z,1557205091.815 [AHRS_M2] Loaded
2019-05-07T04:58:11.815Z,1557205091.815 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-07T04:58:11.888Z,1557205091.888 [DataOverHttps] Loaded
2019-05-07T04:58:11.888Z,1557205091.888 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-07T04:58:11.889Z,1557205091.889 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-07T04:58:11.890Z,1557205091.890 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2222
2019-05-07T04:58:11.903Z,1557205091.903 [Depth_Keller] Loaded
2019-05-07T04:58:11.903Z,1557205091.903 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-07T04:58:11.908Z,1557205091.908 [DropWeight] Loaded
2019-05-07T04:58:11.908Z,1557205091.908 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-07T04:58:11.964Z,1557205091.964 [DUSBL_Hydroid] Loaded
2019-05-07T04:58:11.964Z,1557205091.964 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-07T04:58:12.004Z,1557205092.004 [Micromodem] Loaded
2019-05-07T04:58:12.004Z,1557205092.004 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-07T04:58:12.102Z,1557205092.102 [NAL9602] Loaded
2019-05-07T04:58:12.102Z,1557205092.102 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-07T04:58:12.118Z,1557205092.118 [Onboard] Loaded
2019-05-07T04:58:12.118Z,1557205092.118 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-07T04:58:12.124Z,1557205092.124 [PowerOnly] Loaded
2019-05-07T04:58:12.124Z,1557205092.124 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-07T04:58:12.131Z,1557205092.131 [Radio_Surface] Loaded
2019-05-07T04:58:12.131Z,1557205092.131 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-07T04:58:12.132Z,1557205092.132 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-07T04:58:12.132Z,1557205092.132 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2223
2019-05-07T04:58:12.176Z,1557205092.176 [RDI_Pathfinder] Loaded
2019-05-07T04:58:12.177Z,1557205092.177 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-07T04:58:14.180Z,1557205094.180 [BPC1] Loaded
2019-05-07T04:58:14.181Z,1557205094.181 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-07T04:58:14.181Z,1557205094.181 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-07T04:58:14.182Z,1557205094.182 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-07T04:58:14.194Z,1557205094.194 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-07T04:58:14.195Z,1557205094.195 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-07T04:58:14.300Z,1557205094.300 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-07T04:58:14.300Z,1557205094.300 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-07T04:58:14.320Z,1557205094.320 [NavChart] Loaded
2019-05-07T04:58:14.321Z,1557205094.321 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-07T04:58:14.325Z,1557205094.325 [UniversalFixResidualReporter] Loaded
2019-05-07T04:58:14.325Z,1557205094.325 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-07T04:58:14.325Z,1557205094.325 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-07T04:58:14.326Z,1557205094.326 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-07T04:58:14.434Z,1557205094.434 [BuoyancyServo] Loaded
2019-05-07T04:58:14.434Z,1557205094.434 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-07T04:58:14.449Z,1557205094.449 [ElevatorServo] Loaded
2019-05-07T04:58:14.450Z,1557205094.450 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-07T04:58:14.465Z,1557205094.465 [MassServo] Loaded
2019-05-07T04:58:14.465Z,1557205094.465 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-07T04:58:14.480Z,1557205094.480 [RudderServo] Loaded
2019-05-07T04:58:14.480Z,1557205094.480 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-07T04:58:14.494Z,1557205094.494 [ThrusterServo] Loaded
2019-05-07T04:58:14.495Z,1557205094.495 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-07T04:58:14.495Z,1557205094.495 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-07T04:58:14.496Z,1557205094.496 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-07T04:58:14.742Z,1557205094.742 [CTD_NeilBrown] Loaded
2019-05-07T04:58:14.742Z,1557205094.742 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-07T04:58:14.744Z,1557205094.744 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-07T04:58:14.744Z,1557205094.744 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2224
2019-05-07T04:58:14.788Z,1557205094.788 [WetLabsSeaOWL_UV_A] Loaded
2019-05-07T04:58:14.788Z,1557205094.788 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-07T04:58:14.789Z,1557205094.789 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-07T04:58:14.789Z,1557205094.789 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 2225
2019-05-07T04:58:14.790Z,1557205094.790 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-07T04:58:14.791Z,1557205094.791 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-07T04:58:15.081Z,1557205095.081 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-07T04:58:15.082Z,1557205095.082 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-07T04:58:15.121Z,1557205095.121 [DepthRateCalculator] Loaded
2019-05-07T04:58:15.122Z,1557205095.122 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-07T04:58:15.127Z,1557205095.127 [PitchRateCalculator] Loaded
2019-05-07T04:58:15.128Z,1557205095.128 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-07T04:58:15.140Z,1557205095.140 [SpeedCalculator] Loaded
2019-05-07T04:58:15.140Z,1557205095.140 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-07T04:58:15.161Z,1557205095.161 [TempGradientCalculator] Loaded
2019-05-07T04:58:15.161Z,1557205095.161 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-07T04:58:15.167Z,1557205095.167 [YawRateCalculator] Loaded
2019-05-07T04:58:15.167Z,1557205095.167 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-07T04:58:15.207Z,1557205095.207 [ElevatorOffsetCalculator] Loaded
2019-05-07T04:58:15.208Z,1557205095.208 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-07T04:58:15.208Z,1557205095.208 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-07T04:58:15.209Z,1557205095.209 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-07T04:58:15.344Z,1557205095.344 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-07T04:58:15.377Z,1557205095.377 [SBIT] Loaded
2019-05-07T04:58:15.377Z,1557205095.377 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-07T04:58:15.378Z,1557205095.378 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-07T04:58:15.389Z,1557205095.389 [IBIT] Loaded
2019-05-07T04:58:15.390Z,1557205095.390 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-07T04:58:15.393Z,1557205095.393 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-07T04:58:15.530Z,1557205095.530 [CBIT] Loaded
2019-05-07T04:58:15.530Z,1557205095.530 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-07T04:58:15.531Z,1557205095.531 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-07T04:58:15.531Z,1557205095.531 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-07T04:58:15.601Z,1557205095.601 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-07T04:58:15.602Z,1557205095.602 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-07T04:58:15.700Z,1557205095.700 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-07T04:58:15.700Z,1557205095.700 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-07T04:58:15.766Z,1557205095.766 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-07T04:58:15.850Z,1557205095.850 [VerticalControl] Loaded
2019-05-07T04:58:15.850Z,1557205095.850 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-07T04:58:15.851Z,1557205095.851 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-07T04:58:15.909Z,1557205095.909 [HorizontalControl] Loaded
2019-05-07T04:58:15.909Z,1557205095.909 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-07T04:58:15.910Z,1557205095.910 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-07T04:58:15.911Z,1557205095.911 [SpeedControl] Loaded
2019-05-07T04:58:15.912Z,1557205095.912 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-07T04:58:15.912Z,1557205095.912 [LoopControl](DEBUG): Construct LoopControl.
2019-05-07T04:58:15.913Z,1557205095.913 [LoopControl] Loaded
2019-05-07T04:58:15.913Z,1557205095.913 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-07T04:58:15.914Z,1557205095.914 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-07T04:58:15.914Z,1557205095.914 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-07T04:58:15.940Z,1557205095.940 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-07T04:58:15.944Z,1557205095.944 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-07T04:58:15.945Z,1557205095.945 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-07T04:58:15.952Z,1557205095.952 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-07T04:58:15.953Z,1557205095.953 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-07T04:58:15.953Z,1557205095.953 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2226
2019-05-07T04:58:15.958Z,1557205095.958 [Supervisor](INFO): Main Thread ID is 802
2019-05-07T04:58:15.958Z,1557205095.958 [Supervisor](DEBUG): Running supervisor.
2019-05-07T04:58:15.959Z,1557205095.959 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2227
2019-05-07T04:58:15.961Z,1557205095.961 [controlThread ThreadHandler](INFO): Handler Thread ID is 2228
2019-05-07T04:58:15.961Z,1557205095.961 [controlThread](DEBUG): Initializing ControlThread
2019-05-07T04:58:15.969Z,1557205095.969 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-07T04:58:15.970Z,1557205095.970 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-07T04:58:15.971Z,1557205095.971 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-07T04:58:15.971Z,1557205095.971 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-07T04:58:15.972Z,1557205095.972 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-07T04:58:15.972Z,1557205095.972 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-07T04:58:15.972Z,1557205095.972 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-07T04:58:15.973Z,1557205095.973 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-07T04:58:15.973Z,1557205095.973 [SBIT](INFO): Initialize SBIT Component.
2019-05-07T04:58:15.974Z,1557205095.974 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-07T04:58:15.974Z,1557205095.974 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-07T04:58:15.974Z,1557205095.974 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-07T04:58:15.975Z,1557205095.975 [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-07T04:58:15.977Z,1557205095.977 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-07T04:58:15.977Z,1557205095.977 [IBIT](INFO): Initialize IBIT Component.
2019-05-07T04:58:15.978Z,1557205095.978 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-07T04:58:15.979Z,1557205095.979 [logger ThreadHandler](INFO): Handler Thread ID is 2229
2019-05-07T04:58:15.990Z,1557205095.990 [CBIT](DEBUG): Initialized mux pins.
2019-05-07T04:58:15.990Z,1557205095.990 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-07T04:58:15.999Z,1557205095.999 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2230
2019-05-07T04:58:15.000Z,1557205096.000 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-07T04:58:16.011Z,1557205096.011 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2231
2019-05-07T04:58:16.014Z,1557205096.014 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-07T04:58:16.014Z,1557205096.014 [CBIT](DEBUG): Initializing heartbeat.
2019-05-07T04:58:16.031Z,1557205096.031 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2232
2019-05-07T04:58:16.031Z,1557205096.031 [CTD_NeilBrown](INFO): Powering down
2019-05-07T04:58:16.067Z,1557205096.067 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 2233
2019-05-07T04:58:16.067Z,1557205096.067 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T04:58:16.086Z,1557205096.086 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-07T04:58:16.086Z,1557205096.086 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-07T04:58:16.095Z,1557205096.095 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2234
2019-05-07T04:58:16.098Z,1557205096.098 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-07T04:58:16.098Z,1557205096.098 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-07T04:58:16.099Z,1557205096.099 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-07T04:58:16.099Z,1557205096.099 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-07T04:58:16.099Z,1557205096.099 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-07T04:58:16.099Z,1557205096.099 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-07T04:58:16.099Z,1557205096.099 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-07T04:58:16.100Z,1557205096.100 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-07T04:58:16.100Z,1557205096.100 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-07T04:58:16.100Z,1557205096.100 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-07T04:58:16.100Z,1557205096.100 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-07T04:58:16.100Z,1557205096.100 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-07T04:58:16.100Z,1557205096.100 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-07T04:58:16.101Z,1557205096.101 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-07T04:58:16.101Z,1557205096.101 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-07T04:58:16.101Z,1557205096.101 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-07T04:58:16.122Z,1557205096.122 [CBIT](DEBUG): Backplane powered.
2019-05-07T04:58:16.123Z,1557205096.123 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-07T04:58:16.124Z,1557205096.124 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-07T04:58:16.125Z,1557205096.125 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-07T04:58:16.125Z,1557205096.125 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-07T04:58:16.126Z,1557205096.126 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-07T04:58:16.136Z,1557205096.136 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T04:58:16.152Z,1557205096.152 [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-07T04:58:16.153Z,1557205096.153 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-07T04:58:16.224Z,1557205096.224 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-07T04:58:16.225Z,1557205096.225 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-07T04:58:16.227Z,1557205096.227 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T04:58:16.270Z,1557205096.270 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-07T04:58:16.272Z,1557205096.272 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-07T04:58:16.306Z,1557205096.306 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-07T04:58:16.309Z,1557205096.309 [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-07T04:58:16.314Z,1557205096.314 [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-07T04:58:16.326Z,1557205096.326 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-07T04:58:16.380Z,1557205096.380 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-07T04:58:16.381Z,1557205096.381 [DUSBL_Hydroid](INFO): Powering up
2019-05-07T04:58:16.381Z,1557205096.381 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-07T04:58:16.414Z,1557205096.414 [Radio_Surface](INFO): Powering up
2019-05-07T04:58:16.455Z,1557205096.455 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-07T04:58:16.472Z,1557205096.472 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:58:16.479Z,1557205096.479 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-07T04:58:16.480Z,1557205096.480 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:58:16.488Z,1557205096.488 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-07T04:58:16.489Z,1557205096.489 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:58:16.503Z,1557205096.503 [MassServo](DEBUG): Initializing MassServo.
2019-05-07T04:58:16.503Z,1557205096.503 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:58:16.511Z,1557205096.511 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T04:58:16.511Z,1557205096.511 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:58:16.519Z,1557205096.519 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-07T04:58:16.841Z,1557205096.841 [Micromodem](INFO): Powering up
2019-05-07T04:58:16.842Z,1557205096.842 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-07T04:58:17.486Z,1557205097.486 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-07T04:58:17.486Z,1557205097.486 [RudderServo](FAULT): Rudder failed to initialize
2019-05-07T04:58:17.487Z,1557205097.487 [RudderServo] Communications Fault, FailCount= 1
2019-05-07T04:58:17.487Z,1557205097.487 [RudderServo](ERROR): Communications Fault
2019-05-07T04:58:17.598Z,1557205097.598 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-07T04:58:17.755Z,1557205097.755 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T04:58:17.756Z,1557205097.756 [RudderServo](INFO): Powering down
2019-05-07T04:58:18.442Z,1557205098.442 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T04:58:18.563Z,1557205098.563 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T04:58:18.568Z,1557205098.568 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-07T04:58:18.568Z,1557205098.568 [RudderServo] No Fault, FailCount= 1
2019-05-07T04:58:29.787Z,1557205109.787 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T04:58:34.200Z,1557205114.200 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-07T04:58:42.277Z,1557205122.277 [NAL9602](INFO): Powering up NAL9602
2019-05-07T04:58:53.193Z,1557205133.193 [NAL9602](INFO): NAL9602 initialized
2019-05-07T04:58:54.006Z,1557205134.006 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:00.489Z,1557205140.489 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-07T04:59:00.493Z,1557205140.493 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-07T04:59:10.638Z,1557205150.638 [NAL9602](INFO): SBD MO Status=0, MOMSN=3829, MT Status=0, MTMSN=0
2019-05-07T04:59:10.639Z,1557205150.639 [NAL9602](INFO): No messages in MT queue
2019-05-07T04:59:11.454Z,1557205151.454 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:11.531Z,1557205151.531 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.023048
CHAN A1 (24V): -0.026121
CHAN A2 (12V): -0.006723
CHAN A3 (5V): -0.002133
CHAN B0 (3.3V): 0.000428
CHAN B1 (3.15aV): -0.000179
CHAN B2 (3.15bV): 0.000281
CHAN B3 (GND): 0.001822
OPEN: 0.006586
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-07T04:59:13.882Z,1557205153.882 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:16.874Z,1557205156.874 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:19.690Z,1557205159.690 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:22.926Z,1557205162.926 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:25.750Z,1557205165.750 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:28.982Z,1557205168.982 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:31.810Z,1557205171.810 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:35.042Z,1557205175.042 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:37.870Z,1557205177.870 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:41.106Z,1557205181.106 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:44.006Z,1557205184.006 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:46.838Z,1557205186.838 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:50.074Z,1557205190.074 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:52.902Z,1557205192.902 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:53.755Z,1557205193.755 [SBIT](IMPORTANT): SBIT PASSED
2019-05-07T04:59:53.804Z,1557205193.804 [CommandLine](IMPORTANT): got command configSet list
2019-05-07T04:59:53.804Z,1557205193.804 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-07T04:59:53.805Z,1557205193.805 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-07T04:59:53.805Z,1557205193.805 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-07T04:59:53.805Z,1557205193.805 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-07T04:59:53.805Z,1557205193.805 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-07T04:59:53.805Z,1557205193.805 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-07T04:59:53.806Z,1557205193.806 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-07T04:59:53.806Z,1557205193.806 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-07T04:59:53.806Z,1557205193.806 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-07T04:59:53.806Z,1557205193.806 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-07T04:59:53.807Z,1557205193.807 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-07T04:59:53.807Z,1557205193.807 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-07T04:59:53.807Z,1557205193.807 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-07T04:59:53.807Z,1557205193.807 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-07T04:59:54.123Z,1557205194.123 [MissionManager](IMPORTANT): Started mission Startup
2019-05-07T04:59:54.124Z,1557205194.124 [Startup] Running Loop=1
2019-05-07T04:59:54.124Z,1557205194.124 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-07T04:59:54.124Z,1557205194.124 [Startup:A.GoToSurface] Running Loop=1
2019-05-07T04:59:54.124Z,1557205194.124 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T04:59:54.125Z,1557205194.125 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T04:59:54.125Z,1557205194.125 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T04:59:54.125Z,1557205194.125 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T04:59:54.126Z,1557205194.126 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T04:59:54.126Z,1557205194.126 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T04:59:54.128Z,1557205194.128 [Startup:StartupSatComms] Running Loop=1
2019-05-07T04:59:54.128Z,1557205194.128 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-07T04:59:54.128Z,1557205194.128 [Startup:StartupSatComms:A] Running Loop=1
2019-05-07T04:59:54.528Z,1557205194.528 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-07T04:59:56.134Z,1557205196.134 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:59:58.958Z,1557205198.958 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:02.190Z,1557205202.190 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:05.014Z,1557205205.014 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:07.842Z,1557205207.842 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:11.074Z,1557205211.074 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:13.906Z,1557205213.906 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:17.138Z,1557205217.138 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:19.982Z,1557205219.982 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:22.790Z,1557205222.790 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:26.026Z,1557205226.026 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:28.850Z,1557205228.850 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:32.086Z,1557205232.086 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:34.910Z,1557205234.910 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:38.146Z,1557205238.146 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:40.970Z,1557205240.970 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:42.144Z,1557205242.144 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004803
2019-05-07T05:00:43.802Z,1557205243.802 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:47.034Z,1557205247.034 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:49.862Z,1557205249.862 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:53.102Z,1557205253.102 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:54.317Z,1557205254.317 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-07T04:59:54.1Z
2019-05-07T05:00:54.317Z,1557205254.317 [Startup:StartupSatComms:A] Stopped
2019-05-07T05:00:54.317Z,1557205254.317 [Startup:StartupSatComms:B] Running Loop=1
2019-05-07T05:00:54.742Z,1557205254.742 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T05:00:55.926Z,1557205255.926 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:00:59.154Z,1557205259.154 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:00.114Z,1557205260.114 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190507T044752/Courier0013.lzma
2019-05-07T05:01:00.920Z,1557205260.920 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Courier0013.lzma.bak
2019-05-07T05:01:00.920Z,1557205260.920 [DataOverHttps](INFO): SBD MOMSN=10950175
2019-05-07T05:01:01.978Z,1557205261.978 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:04.810Z,1557205264.810 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:08.042Z,1557205268.042 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:10.870Z,1557205270.870 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:12.390Z,1557205272.390 [DataOverHttps](INFO): Sending 335 bytes from file Logs/20190507T044752/Express0011.lzma
2019-05-07T05:01:13.196Z,1557205273.196 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Express0011.lzma.bak
2019-05-07T05:01:13.196Z,1557205273.196 [DataOverHttps](INFO): SBD MOMSN=10950177
2019-05-07T05:01:14.098Z,1557205274.098 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:16.131Z,1557205276.131 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-07T05:01:16.131Z,1557205276.131 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T05:01:16.145Z,1557205276.145 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T05:01:16.708Z,1557205276.708 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T05:01:16.708Z,1557205276.708 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-07T05:01:16.930Z,1557205276.931 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:19.770Z,1557205279.770 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:21.778Z,1557205281.778 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:24.731Z,1557205284.731 [DataOverHttps](INFO): Sending 289 bytes from file Logs/20190507T044752/Express0014.lzma
2019-05-07T05:01:25.018Z,1557205285.018 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:25.536Z,1557205285.536 [DataOverHttps](INFO): Moved sent file to Logs/20190507T044752/Express0014.lzma.bak
2019-05-07T05:01:25.536Z,1557205285.536 [DataOverHttps](INFO): SBD MOMSN=10950184
2019-05-07T05:01:27.838Z,1557205287.838 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:31.074Z,1557205291.074 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:33.906Z,1557205293.906 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:36.864Z,1557205296.864 [DataOverHttps](INFO): Sending 1338 bytes from file Logs/20190507T045806/Express0001.lzma
2019-05-07T05:01:37.126Z,1557205297.126 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:37.668Z,1557205297.668 [DataOverHttps](INFO): Moved sent file to Logs/20190507T045806/Express0001.lzma.bak
2019-05-07T05:01:37.668Z,1557205297.668 [DataOverHttps](INFO): SBD MOMSN=10950188
2019-05-07T05:01:38.791Z,1557205298.791 [Startup:StartupSatComms:B] Stopped
2019-05-07T05:01:38.792Z,1557205298.792 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-07T05:01:38.792Z,1557205298.792 [Startup:StartupSatComms] Stopped
2019-05-07T05:01:38.792Z,1557205298.792 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-07T05:01:38.792Z,1557205298.792 [Startup](INFO): Completed Startup
2019-05-07T05:01:38.793Z,1557205298.793 [MissionManager](INFO): Startup is completed.
2019-05-07T05:01:38.793Z,1557205298.793 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-07T05:01:38.793Z,1557205298.793 [Startup] Stopped
2019-05-07T05:01:38.793Z,1557205298.793 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-07T05:01:38.793Z,1557205298.793 [Startup:A.GoToSurface] Stopped
2019-05-07T05:01:38.793Z,1557205298.793 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T05:01:39.183Z,1557205299.183 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T05:01:39.184Z,1557205299.184 [Default] Running Loop=1
2019-05-07T05:01:39.184Z,1557205299.184 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T05:01:39.184Z,1557205299.184 [Default:B.GoToSurface] Running Loop=1
2019-05-07T05:01:39.184Z,1557205299.184 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T05:01:39.184Z,1557205299.184 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T05:01:39.184Z,1557205299.184 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T05:01:39.185Z,1557205299.185 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T05:01:39.185Z,1557205299.185 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T05:01:39.185Z,1557205299.185 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T05:01:39.186Z,1557205299.186 [Default:A.Wait] Running Loop=1
2019-05-07T05:01:39.186Z,1557205299.186 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:01:39.958Z,1557205299.958 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:42.782Z,1557205302.782 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:45.226Z,1557205305.226 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:48.034Z,1557205308.034 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:51.274Z,1557205311.274 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:52.501Z,1557205312.501 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T05:01:52.501Z,1557205312.501 [Default:A.Wait] Stopped
2019-05-07T05:01:52.501Z,1557205312.501 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:01:52.931Z,1557205312.931 [Default:CheckIn] Running Loop=1
2019-05-07T05:01:52.931Z,1557205312.931 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T05:01:52.931Z,1557205312.931 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T05:01:53.300Z,1557205313.300 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-07T05:01:54.098Z,1557205314.098 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:56.926Z,1557205316.926 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:01:59.774Z,1557205319.774 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:01.774Z,1557205321.774 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:05.018Z,1557205325.018 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:07.838Z,1557205327.838 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:11.066Z,1557205331.066 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:13.890Z,1557205333.890 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:17.122Z,1557205337.122 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:19.950Z,1557205339.950 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:21.607Z,1557205341.607 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T05:02:22.782Z,1557205342.782 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:26.014Z,1557205346.014 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:28.842Z,1557205348.842 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:32.070Z,1557205352.070 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:34.898Z,1557205354.898 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:37.730Z,1557205357.730 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:39.746Z,1557205359.746 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:41.778Z,1557205361.778 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:45.002Z,1557205365.002 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:47.826Z,1557205367.826 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:51.058Z,1557205371.058 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:53.886Z,1557205373.886 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:57.119Z,1557205377.119 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:02:59.950Z,1557205379.950 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:03.178Z,1557205383.178 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:06.010Z,1557205386.010 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:09.242Z,1557205389.242 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:12.082Z,1557205392.082 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:15.302Z,1557205395.302 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:18.138Z,1557205398.138 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:20.954Z,1557205400.954 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:23.782Z,1557205403.782 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:27.014Z,1557205407.014 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:29.855Z,1557205409.855 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:33.082Z,1557205413.082 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:35.906Z,1557205415.906 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:39.142Z,1557205419.142 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:41.970Z,1557205421.970 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:45.194Z,1557205425.194 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:48.022Z,1557205428.022 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:51.254Z,1557205431.254 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:54.086Z,1557205434.086 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:56.910Z,1557205436.910 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:03:59.738Z,1557205439.738 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:01.758Z,1557205441.758 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:04.998Z,1557205444.998 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:07.822Z,1557205447.822 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:11.054Z,1557205451.054 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:13.882Z,1557205453.882 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:17.110Z,1557205457.110 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:17.136Z,1557205457.136 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-05-07T05:04:17.136Z,1557205457.136 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T05:04:17.175Z,1557205457.175 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T05:04:17.548Z,1557205457.548 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T05:04:17.548Z,1557205457.548 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-05-07T05:04:19.954Z,1557205459.954 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:23.174Z,1557205463.174 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:26.002Z,1557205466.002 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:28.842Z,1557205468.842 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:32.062Z,1557205472.062 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:34.890Z,1557205474.890 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:38.122Z,1557205478.122 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:40.946Z,1557205480.946 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:44.182Z,1557205484.182 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:47.006Z,1557205487.006 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:49.838Z,1557205489.838 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:53.066Z,1557205493.066 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:55.898Z,1557205495.898 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:04:59.130Z,1557205499.130 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:01.954Z,1557205501.954 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:05.190Z,1557205505.190 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:08.014Z,1557205508.014 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:10.846Z,1557205510.846 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:14.074Z,1557205514.074 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:16.922Z,1557205516.922 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:20.138Z,1557205520.138 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:22.974Z,1557205522.974 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:26.198Z,1557205526.198 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:29.026Z,1557205529.026 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:31.850Z,1557205531.850 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:35.086Z,1557205535.086 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:37.919Z,1557205537.919 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:41.146Z,1557205541.146 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:43.974Z,1557205543.974 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:46.806Z,1557205546.806 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:50.038Z,1557205550.038 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:53.266Z,1557205553.266 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:56.090Z,1557205556.090 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:05:58.926Z,1557205558.926 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:02.150Z,1557205562.150 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:04.719Z,1557205564.719 [CommandLine](IMPORTANT): got command show variable range
2019-05-07T05:06:04.722Z,1557205564.722 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-07T05:06:04.824Z,1557205564.824 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-07T05:06:04.825Z,1557205564.825 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-07T05:06:04.841Z,1557205564.841 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-07T05:06:04.843Z,1557205564.843 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-07T05:06:04.843Z,1557205564.843 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-07T05:06:04.846Z,1557205564.846 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-07T05:06:04.847Z,1557205564.847 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-07T05:06:04.847Z,1557205564.847 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-07T05:06:04.848Z,1557205564.848 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-07T05:06:04.978Z,1557205564.978 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:08.210Z,1557205568.210 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:11.038Z,1557205571.038 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:13.663Z,1557205573.663 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-07T05:06:13.874Z,1557205573.874 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:17.102Z,1557205577.102 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:17.199Z,1557205577.199 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T05:06:17.199Z,1557205577.199 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T05:06:17.250Z,1557205577.250 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T05:06:17.254Z,1557205577.254 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T05:06:17.258Z,1557205577.258 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T05:06:17.261Z,1557205577.261 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T05:06:17.265Z,1557205577.265 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T05:06:17.266Z,1557205577.266 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T05:06:17.273Z,1557205577.273 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T05:06:17.303Z,1557205577.303 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T05:06:17.307Z,1557205577.307 [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-05-07T05:06:17.309Z,1557205577.309 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T05:06:17.539Z,1557205577.539 [Default] Stopped
2019-05-07T05:06:17.539Z,1557205577.539 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T05:06:17.539Z,1557205577.539 [Default:B.GoToSurface] Stopped
2019-05-07T05:06:17.539Z,1557205577.539 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T05:06:17.539Z,1557205577.539 [Default:CheckIn] Stopped
2019-05-07T05:06:17.540Z,1557205577.540 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T05:06:17.540Z,1557205577.540 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T05:06:17.540Z,1557205577.540 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T05:06:17.540Z,1557205577.540 [DUSBL] Running Loop=1
2019-05-07T05:06:17.540Z,1557205577.540 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T05:06:17.540Z,1557205577.540 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T05:06:17.540Z,1557205577.540 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:C] Running Loop=1
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:06:17.541Z,1557205577.541 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:06:17.542Z,1557205577.542 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:06:17.542Z,1557205577.542 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:06:17.543Z,1557205577.543 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T05:06:17.544Z,1557205577.544 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T05:06:17.544Z,1557205577.544 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T05:06:17.544Z,1557205577.544 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T05:06:19.104Z,1557205579.104 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:06:19.104Z,1557205579.104 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:06:19.105Z,1557205579.105 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:06:19.512Z,1557205579.512 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:19.512Z,1557205579.512 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:19.938Z,1557205579.938 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:20.320Z,1557205580.320 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:06:20.320Z,1557205580.320 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:06:20.320Z,1557205580.320 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:20.321Z,1557205580.321 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:06:20.335Z,1557205580.335 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:22.354Z,1557205582.354 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:25.178Z,1557205585.178 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.073486
2019-05-07T05:06:25.179Z,1557205585.179 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:06:25.179Z,1557205585.179 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:06:25.179Z,1557205585.179 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:06:25.194Z,1557205585.194 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:25.587Z,1557205585.587 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:25.589Z,1557205585.589 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:26.784Z,1557205586.784 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:06:26.784Z,1557205586.784 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:06:26.784Z,1557205586.784 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:26.784Z,1557205586.784 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:06:26.799Z,1557205586.799 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:27.652Z,1557205587.652 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:06:27.652Z,1557205587.652 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:06:27.652Z,1557205587.652 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:06:27.652Z,1557205587.652 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:06:27.652Z,1557205587.652 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:06:27.653Z,1557205587.653 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:06:28.006Z,1557205588.006 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:29.227Z,1557205589.227 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-07T05:06:29.230Z,1557205589.230 [BPC1](INFO): Received data from all battery sticks.
2019-05-07T05:06:31.234Z,1557205591.234 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054936
2019-05-07T05:06:31.235Z,1557205591.235 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:06:31.235Z,1557205591.235 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:06:31.235Z,1557205591.235 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:06:31.256Z,1557205591.256 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:31.632Z,1557205591.632 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:31.632Z,1557205591.632 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:32.436Z,1557205592.436 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:06:32.436Z,1557205592.436 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:06:32.436Z,1557205592.436 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:32.437Z,1557205592.437 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:06:32.451Z,1557205592.451 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:34.070Z,1557205594.070 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:36.894Z,1557205596.894 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:06:37.294Z,1557205597.294 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058974
2019-05-07T05:06:37.295Z,1557205597.295 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:06:37.295Z,1557205597.295 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:06:37.295Z,1557205597.295 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:06:37.303Z,1557205597.303 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,050510.00,A,3648.16964,N,12147.28098,W,0.136,0.00,070519,,,A*7C
2019-05-07T05:06:37.307Z,1557205597.307 [NAL9602](INFO): GPS fix at 20190507T050510: (36.802827, -121.788016)
2019-05-07T05:06:37.696Z,1557205597.696 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:37.696Z,1557205597.696 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:38.152Z,1557205598.152 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:06:38.153Z,1557205598.153 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:06:38.153Z,1557205598.153 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:06:38.153Z,1557205598.153 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:06:38.153Z,1557205598.153 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:06:38.153Z,1557205598.153 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:06:38.154Z,1557205598.154 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:06:38.155Z,1557205598.155 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:06:38.504Z,1557205598.504 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:06:38.504Z,1557205598.504 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:06:38.504Z,1557205598.504 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:38.504Z,1557205598.504 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:06:38.523Z,1557205598.523 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:43.362Z,1557205603.362 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.066908
2019-05-07T05:06:43.362Z,1557205603.362 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:06:43.363Z,1557205603.363 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:06:43.363Z,1557205603.363 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:06:43.755Z,1557205603.755 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:43.756Z,1557205603.756 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:44.572Z,1557205604.572 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:06:44.573Z,1557205604.573 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:06:44.573Z,1557205604.573 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:44.575Z,1557205604.575 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:06:44.588Z,1557205604.588 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:48.761Z,1557205608.761 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:06:48.761Z,1557205608.761 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:06:48.761Z,1557205608.761 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:06:48.762Z,1557205608.762 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:06:48.763Z,1557205608.763 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:06:48.763Z,1557205608.763 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:06:48.763Z,1557205608.763 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:06:49.467Z,1557205609.467 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.103668
2019-05-07T05:06:49.467Z,1557205609.467 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:06:49.467Z,1557205609.467 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:06:49.468Z,1557205609.468 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:06:49.844Z,1557205609.844 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:49.846Z,1557205609.846 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:50.245Z,1557205610.245 [Micromodem](ERROR): Response from modem unexpected: $CADQF,204,1*56

2019-05-07T05:06:50.250Z,1557205610.250 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T05:06:50.660Z,1557205610.660 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:06:50.660Z,1557205610.660 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:06:50.660Z,1557205610.660 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:50.660Z,1557205610.660 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:06:50.680Z,1557205610.680 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507050648.059835,06,402,14,0096,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,204,0.00,-999,9760,4000*5C

2019-05-07T05:06:55.522Z,1557205615.522 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054568
2019-05-07T05:06:55.523Z,1557205615.523 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:06:55.523Z,1557205615.523 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:06:55.524Z,1557205615.524 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:06:55.915Z,1557205615.915 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:55.916Z,1557205615.916 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:56.708Z,1557205616.708 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:06:56.708Z,1557205616.708 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:06:56.708Z,1557205616.708 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:06:56.708Z,1557205616.708 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:06:56.723Z,1557205616.723 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:06:59.161Z,1557205619.161 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:06:59.161Z,1557205619.161 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:06:59.161Z,1557205619.161 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:06:59.162Z,1557205619.162 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater] Running Loop=5
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:06:59.163Z,1557205619.163 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:07:01.576Z,1557205621.576 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.051816
2019-05-07T05:07:01.576Z,1557205621.576 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:01.577Z,1557205621.577 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:01.578Z,1557205621.578 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:01.959Z,1557205621.959 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:01.960Z,1557205621.960 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:02.767Z,1557205622.767 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:07:02.768Z,1557205622.768 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:07:02.768Z,1557205622.768 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:02.768Z,1557205622.768 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:07:02.783Z,1557205622.783 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:07.627Z,1557205627.627 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.048887
2019-05-07T05:07:07.627Z,1557205627.627 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:07.627Z,1557205627.627 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:07.627Z,1557205627.627 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:08.019Z,1557205628.019 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:08.020Z,1557205628.020 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:09.718Z,1557205629.718 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:07:09.718Z,1557205629.718 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:07:09.718Z,1557205629.718 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:07:09.727Z,1557205629.727 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:07:09.727Z,1557205629.727 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:07:09.727Z,1557205629.727 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:07:09.727Z,1557205629.727 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:07:09.727Z,1557205629.727 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:07:09.727Z,1557205629.727 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-07T05:07:09.727Z,1557205629.727 [DUSBL:RequestRepeater] Running Loop=6
2019-05-07T05:07:09.728Z,1557205629.728 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:07:09.728Z,1557205629.728 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:07:09.728Z,1557205629.728 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:07:09.728Z,1557205629.728 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:07:09.728Z,1557205629.728 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:07:10.040Z,1557205630.040 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T05:07:13.686Z,1557205633.686 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058951
2019-05-07T05:07:13.687Z,1557205633.687 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:13.687Z,1557205633.687 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:13.687Z,1557205633.687 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:14.079Z,1557205634.079 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:14.080Z,1557205634.080 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:14.888Z,1557205634.888 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:07:14.888Z,1557205634.888 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:07:14.888Z,1557205634.888 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:14.888Z,1557205634.888 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:07:14.903Z,1557205634.903 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:19.750Z,1557205639.750 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062935
2019-05-07T05:07:19.751Z,1557205639.751 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:19.751Z,1557205639.751 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:19.751Z,1557205639.751 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:20.143Z,1557205640.143 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:20.144Z,1557205640.144 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:20.274Z,1557205640.274 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:07:20.274Z,1557205640.274 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:07:20.274Z,1557205640.274 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:07:20.296Z,1557205640.296 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:07:20.296Z,1557205640.296 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:07:20.298Z,1557205640.298 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:07:20.308Z,1557205640.308 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:07:20.308Z,1557205640.308 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:07:20.310Z,1557205640.310 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-07T05:07:20.320Z,1557205640.320 [DUSBL:RequestRepeater] Running Loop=7
2019-05-07T05:07:20.320Z,1557205640.320 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:07:20.321Z,1557205640.321 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:07:20.322Z,1557205640.322 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:07:20.326Z,1557205640.326 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:07:20.326Z,1557205640.326 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:07:25.806Z,1557205645.806 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054920
2019-05-07T05:07:25.806Z,1557205645.806 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:25.807Z,1557205645.807 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:25.807Z,1557205645.807 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:26.203Z,1557205646.203 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:26.205Z,1557205646.205 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:27.005Z,1557205647.005 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:07:27.005Z,1557205647.005 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:07:27.006Z,1557205647.006 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:27.006Z,1557205647.006 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:07:27.019Z,1557205647.019 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:30.836Z,1557205650.836 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:07:30.836Z,1557205650.836 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:07:30.836Z,1557205650.836 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:07:31.025Z,1557205651.025 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:07:31.025Z,1557205651.025 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:07:31.025Z,1557205651.025 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:07:31.025Z,1557205651.025 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:07:31.025Z,1557205651.025 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:07:31.026Z,1557205651.026 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-07T05:07:31.026Z,1557205651.026 [DUSBL:RequestRepeater] Running Loop=8
2019-05-07T05:07:31.026Z,1557205651.026 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:07:31.026Z,1557205651.026 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:07:31.026Z,1557205651.026 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:07:31.026Z,1557205651.026 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:07:31.026Z,1557205651.026 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:07:31.902Z,1557205651.902 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.095114
2019-05-07T05:07:31.903Z,1557205651.903 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:31.903Z,1557205651.903 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:31.904Z,1557205651.904 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:32.295Z,1557205652.295 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:32.296Z,1557205652.296 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:33.104Z,1557205653.104 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:07:33.104Z,1557205653.104 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:07:33.104Z,1557205653.104 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:33.105Z,1557205653.105 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:07:33.123Z,1557205653.123 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:37.962Z,1557205657.962 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058844
2019-05-07T05:07:37.963Z,1557205657.963 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:37.963Z,1557205657.963 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:37.963Z,1557205657.963 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:38.355Z,1557205658.355 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:38.360Z,1557205658.360 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:39.164Z,1557205659.164 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:07:39.164Z,1557205659.164 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:07:39.164Z,1557205659.164 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:39.164Z,1557205659.164 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:07:39.197Z,1557205659.197 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:41.213Z,1557205661.213 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:07:41.213Z,1557205661.213 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:07:41.213Z,1557205661.213 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:07:41.214Z,1557205661.214 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:07:41.214Z,1557205661.214 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:07:41.214Z,1557205661.214 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:07:41.214Z,1557205661.214 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater] Running Loop=9
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:07:41.215Z,1557205661.215 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:07:44.022Z,1557205664.022 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059135
2019-05-07T05:07:44.023Z,1557205664.023 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:44.023Z,1557205664.023 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:44.028Z,1557205664.028 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:50.086Z,1557205670.086 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.057663
2019-05-07T05:07:50.086Z,1557205670.086 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:50.087Z,1557205670.087 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:50.087Z,1557205670.087 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:50.480Z,1557205670.480 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:50.483Z,1557205670.483 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:07:50.881Z,1557205670.881 [Micromodem](ERROR): Response from modem unexpected: $CADQF,202,1*50

2019-05-07T05:07:50.883Z,1557205670.883 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T05:07:51.284Z,1557205671.284 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T05:07:51.284Z,1557205671.284 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T05:07:51.285Z,1557205671.285 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:51.285Z,1557205671.285 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,P
2019-05-07T05:07:51.304Z,1557205671.304 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507050748.771426,06,112,14,0100,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,202,0.00,-999,9760,4000*52

2019-05-07T05:07:51.741Z,1557205671.741 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:07:51.741Z,1557205671.741 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:07:51.741Z,1557205671.741 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:07:51.742Z,1557205671.742 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:07:51.742Z,1557205671.742 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:07:51.742Z,1557205671.742 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:07:51.742Z,1557205671.742 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:07:51.742Z,1557205671.742 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:07:51.742Z,1557205671.742 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-07T05:07:51.743Z,1557205671.743 [DUSBL:RequestRepeater] Running Loop=10
2019-05-07T05:07:51.743Z,1557205671.743 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T05:07:51.743Z,1557205671.743 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T05:07:51.743Z,1557205671.743 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T05:07:51.743Z,1557205671.743 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T05:07:51.743Z,1557205671.743 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:07:56.154Z,1557205676.154 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.067029
2019-05-07T05:07:56.155Z,1557205676.155 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:07:56.155Z,1557205676.155 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:07:56.156Z,1557205676.156 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:07:56.543Z,1557205676.543 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-07T05:07:56.544Z,1557205676.544 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-07T05:08:02.206Z,1557205682.206 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.050571
2019-05-07T05:08:02.206Z,1557205682.206 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T05:08:02.206Z,1557205682.206 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T05:08:02.208Z,1557205682.208 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T05:08:02.245Z,1557205682.245 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T05:08:02.245Z,1557205682.245 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T05:08:02.245Z,1557205682.245 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:08:02.246Z,1557205682.246 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T05:08:02.246Z,1557205682.246 [DUSBL:RequestRepeater] Stopped
2019-05-07T05:08:02.246Z,1557205682.246 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T05:08:02.246Z,1557205682.246 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T05:08:02.247Z,1557205682.247 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T05:08:02.247Z,1557205682.247 [DUSBL](INFO): Completed DUSBL
2019-05-07T05:08:02.247Z,1557205682.247 [MissionManager](INFO): DUSBL is completed.
2019-05-07T05:08:02.248Z,1557205682.248 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T05:08:02.248Z,1557205682.248 [DUSBL] Stopped
2019-05-07T05:08:02.248Z,1557205682.248 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T05:08:02.248Z,1557205682.248 [DUSBL:A.Pitch] Stopped
2019-05-07T05:08:02.248Z,1557205682.248 [DUSBL:B.SetSpeed] Stopped
2019-05-07T05:08:02.248Z,1557205682.248 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T05:08:02.248Z,1557205682.248 [DUSBL:C] Stopped
2019-05-07T05:08:02.645Z,1557205682.645 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T05:08:02.645Z,1557205682.645 [Default] Running Loop=1
2019-05-07T05:08:02.646Z,1557205682.645 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T05:08:02.646Z,1557205682.646 [Default:B.GoToSurface] Running Loop=1
2019-05-07T05:08:02.646Z,1557205682.646 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T05:08:02.646Z,1557205682.646 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T05:08:02.650Z,1557205682.650 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T05:08:02.651Z,1557205682.651 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T05:08:02.651Z,1557205682.651 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T05:08:02.651Z,1557205682.651 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T05:08:02.652Z,1557205682.652 [Default:A.Wait] Running Loop=1
2019-05-07T05:08:02.652Z,1557205682.652 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:08:15.965Z,1557205695.965 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T05:08:15.965Z,1557205695.965 [Default:A.Wait] Stopped
2019-05-07T05:08:15.965Z,1557205695.965 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:08:16.370Z,1557205696.370 [Default:CheckIn] Running Loop=1
2019-05-07T05:08:16.370Z,1557205696.370 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T05:08:16.370Z,1557205696.370 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T05:08:17.966Z,1557205697.966 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:08:17.985Z,1557205697.985 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T05:08:17.985Z,1557205697.985 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T05:08:18.358Z,1557205698.358 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,050652.00,A,3648.16899,N,12147.28355,W,0.369,0.00,070519,,,A*70
2019-05-07T05:08:18.360Z,1557205698.360 [NAL9602](INFO): GPS fix at 20190507T050652: (36.802816, -121.788059)
2019-05-07T05:08:18.413Z,1557205698.413 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T05:08:18.414Z,1557205698.414 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T05:08:18.823Z,1557205698.823 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T05:08:24.078Z,1557205704.078 [DataOverHttps](INFO): Sending 300 bytes from file Logs/20190507T045806/Courier0004.lzma
2019-05-07T05:08:24.884Z,1557205704.884 [DataOverHttps](INFO): Moved sent file to Logs/20190507T045806/Courier0004.lzma.bak
2019-05-07T05:08:24.884Z,1557205704.884 [DataOverHttps](INFO): SBD MOMSN=10950224
2019-05-07T05:08:36.577Z,1557205716.577 [DataOverHttps](INFO): Sending 1333 bytes from file Logs/20190507T045806/Express0005.lzma
2019-05-07T05:08:37.380Z,1557205717.380 [DataOverHttps](INFO): Moved sent file to Logs/20190507T045806/Express0005.lzma.bak
2019-05-07T05:08:37.380Z,1557205717.380 [DataOverHttps](INFO): SBD MOMSN=10950230
2019-05-07T05:08:38.310Z,1557205718.310 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T05:08:38.310Z,1557205718.310 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T05:08:38.314Z,1557205718.314 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:08:43.955Z,1557205723.955 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T05:08:43.955Z,1557205723.955 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T05:09:07.372Z,1557205747.372 [NAL9602](INFO): SBD MO Status=2, MOMSN=3830, MT Status=2, MTMSN=0
2019-05-07T05:09:07.372Z,1557205747.372 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T05:09:41.729Z,1557205781.729 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T05:09:50.205Z,1557205790.205 [NAL9602](INFO): SBD MO Status=0, MOMSN=3830, MT Status=0, MTMSN=0
2019-05-07T05:09:50.205Z,1557205790.205 [NAL9602](INFO): No messages in MT queue
2019-05-07T05:10:10.016Z,1557205810.016 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T05:10:20.909Z,1557205820.909 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T05:12:19.311Z,1557205939.311 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T05:12:19.312Z,1557205939.312 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T05:13:38.901Z,1557206018.901 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T05:13:38.901Z,1557206018.901 [Default:CheckIn:C.Wait] Stopped
2019-05-07T05:13:38.901Z,1557206018.901 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:13:38.901Z,1557206018.901 [Default:CheckIn:D] Running Loop=1
2019-05-07T05:13:39.297Z,1557206019.297 [Default:CheckIn:D] Stopped
2019-05-07T05:13:39.297Z,1557206019.297 [Default:CheckIn:E] Running Loop=1
2019-05-07T05:13:39.708Z,1557206019.708 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.610864 min 
2019-05-07T05:13:39.708Z,1557206019.708 [Default:CheckIn:E] Stopped
2019-05-07T05:13:39.708Z,1557206019.708 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T05:13:39.708Z,1557206019.708 [Default:CheckIn] Stopped
2019-05-07T05:13:39.708Z,1557206019.708 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T05:13:39.708Z,1557206019.708 [Default:CheckIn](INFO): Running loop #2
2019-05-07T05:13:39.708Z,1557206019.708 [Default:CheckIn] Running Loop=2
2019-05-07T05:13:39.709Z,1557206019.709 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T05:13:39.709Z,1557206019.709 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T05:13:41.314Z,1557206021.314 [NAL9602](DEBUG): Fix Requested
2019-05-07T05:13:41.687Z,1557206021.687 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,051215.00,A,3648.16120,N,12147.28269,W,0.019,0.00,070519,,,A*77
2019-05-07T05:13:41.689Z,1557206021.689 [NAL9602](INFO): GPS fix at 20190507T051215: (36.802687, -121.788045)
2019-05-07T05:13:41.735Z,1557206021.735 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T05:13:41.735Z,1557206021.735 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T05:13:47.597Z,1557206027.597 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T045806/Courier0007.lzma
2019-05-07T05:13:48.396Z,1557206028.396 [DataOverHttps](INFO): Moved sent file to Logs/20190507T045806/Courier0007.lzma.bak
2019-05-07T05:13:48.396Z,1557206028.396 [DataOverHttps](INFO): SBD MOMSN=10950297
2019-05-07T05:14:00.625Z,1557206040.625 [DataOverHttps](INFO): Sending 652 bytes from file Logs/20190507T045806/Express0008.lzma
2019-05-07T05:14:01.428Z,1557206041.428 [DataOverHttps](INFO): Moved sent file to Logs/20190507T045806/Express0008.lzma.bak
2019-05-07T05:14:01.428Z,1557206041.428 [DataOverHttps](INFO): SBD MOMSN=10950300
2019-05-07T05:14:02.331Z,1557206042.331 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T05:14:02.331Z,1557206042.331 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T05:14:02.331Z,1557206042.331 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T05:14:10.795Z,1557206050.795 [RDI_Pathfinder](ERROR): Failed to parse:
:R,        +0.00,        +0.00,        +0.00,   0.00,939.96
2019-05-07T05:15:38.452Z,1557206138.452 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190507051530.319625,06,498,14,0090,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,191,-0.05,-999,9760,40.0.46*43

2019-05-07T05:15:45.310Z,1557206145.310 [NAL9602](INFO): SBD MO Status=2, MOMSN=3831, MT Status=2, MTMSN=0
2019-05-07T05:15:45.310Z,1557206145.310 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T05:16:11.169Z,1557206171.169 [NAL9602](INFO): SBD MO Status=0, MOMSN=3831, MT Status=0, MTMSN=0
2019-05-07T05:16:11.169Z,1557206171.169 [NAL9602](INFO): No messages in MT queue
2019-05-07T05:16:41.868Z,1557206201.868 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T05:17:42.364Z,1557206262.364 [CommandLine](IMPORTANT): got command show stack
2019-05-07T05:17:42.364Z,1557206262.364 [CommandLine](IMPORTANT): Behavior Stack:

2019-05-07T05:17:42.364Z,1557206262.364 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-05-07T05:17:42.365Z,1557206262.365 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-05-07T05:17:51.124Z,1557206271.124 [CommandLine](IMPORTANT): got command restart application
2019-05-07T05:17:52.130Z,1557206272.130 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-07T05:17:52.131Z,1557206272.131 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:52.131Z,1557206272.131 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:52.298Z,1557206272.298 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-07T05:17:52.298Z,1557206272.298 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:52.299Z,1557206272.299 [CommandLine](INFO): Join timeout helper Thread ID is 2295
2019-05-07T05:17:52.300Z,1557206272.300 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-07T05:17:52.300Z,1557206272.300 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:52.300Z,1557206272.300 [NavChartDb](INFO): Join timeout helper Thread ID is 2296
2019-05-07T05:17:52.655Z,1557206272.655 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:52.655Z,1557206272.655 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:52.674Z,1557206272.674 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-07T05:17:52.674Z,1557206272.674 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:52.675Z,1557206272.675 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 2297
2019-05-07T05:17:53.050Z,1557206273.050 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:53.051Z,1557206273.051 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T05:17:53.051Z,1557206273.051 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.054Z,1557206273.054 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-07T05:17:53.054Z,1557206273.054 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.055Z,1557206273.055 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2298
2019-05-07T05:17:53.146Z,1557206273.146 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:53.147Z,1557206273.147 [CTD_NeilBrown](INFO): Powering down
2019-05-07T05:17:53.158Z,1557206273.158 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.162Z,1557206273.162 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-07T05:17:53.162Z,1557206273.162 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.163Z,1557206273.163 [Radio_Surface](INFO): Join timeout helper Thread ID is 2299
2019-05-07T05:17:53.466Z,1557206273.466 [Radio_Surface](INFO): Powering down
2019-05-07T05:17:53.467Z,1557206273.467 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:53.467Z,1557206273.467 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.475Z,1557206273.475 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-07T05:17:53.475Z,1557206273.475 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.476Z,1557206273.476 [DataOverHttps](INFO): Join timeout helper Thread ID is 2300
2019-05-07T05:17:53.614Z,1557206273.614 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:53.615Z,1557206273.615 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.623Z,1557206273.623 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-07T05:17:53.623Z,1557206273.623 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.623Z,1557206273.623 [logger](INFO): Join timeout helper Thread ID is 2301
2019-05-07T05:17:53.666Z,1557206273.666 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:53.667Z,1557206273.667 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.683Z,1557206273.683 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-07T05:17:53.683Z,1557206273.683 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.683Z,1557206273.683 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-07T05:17:53.683Z,1557206273.683 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:53.684Z,1557206273.684 [controlThread](INFO): Join timeout helper Thread ID is 2302
2019-05-07T05:17:53.762Z,1557206273.762 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T05:17:53.763Z,1557206273.763 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-07T05:17:53.763Z,1557206273.763 [AHRS_M2](INFO): Powering down
2019-05-07T05:17:53.835Z,1557206273.835 [DUSBL_Hydroid](INFO): Powering down
2019-05-07T05:17:53.907Z,1557206273.907 [Micromodem](INFO): Powering down
2019-05-07T05:17:54.003Z,1557206274.003 [NAL9602](INFO): Powering down
2019-05-07T05:17:54.074Z,1557206274.074 [RDI_Pathfinder](INFO): Powering down
2019-05-07T05:17:54.076Z,1557206274.076 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-07T05:17:54.077Z,1557206274.077 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-07T05:17:54.077Z,1557206274.077 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-07T05:17:54.077Z,1557206274.077 [MissionManager](INFO): Uninitializing Mission Default
2019-05-07T05:17:54.078Z,1557206274.078 [Default] Stopped
2019-05-07T05:17:54.078Z,1557206274.078 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T05:17:54.078Z,1557206274.078 [Default:B.GoToSurface] Stopped
2019-05-07T05:17:54.078Z,1557206274.078 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T05:17:54.078Z,1557206274.078 [Default:CheckIn] Stopped
2019-05-07T05:17:54.078Z,1557206274.078 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T05:17:54.078Z,1557206274.078 [Default:CheckIn:C.Wait] Stopped
2019-05-07T05:17:54.078Z,1557206274.078 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T05:17:54.081Z,1557206274.081 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-07T05:17:54.081Z,1557206274.081 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-07T05:17:54.081Z,1557206274.081 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-07T05:17:54.081Z,1557206274.081 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-07T05:17:54.082Z,1557206274.082 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-07T05:17:54.082Z,1557206274.082 [BuoyancyServo](INFO): Powering down
2019-05-07T05:17:54.094Z,1557206274.094 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-07T05:17:54.094Z,1557206274.094 [ElevatorServo](INFO): Powering down
2019-05-07T05:17:54.095Z,1557206274.095 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-07T05:17:54.095Z,1557206274.095 [MassServo](INFO): Powering down
2019-05-07T05:17:54.096Z,1557206274.096 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T05:17:54.096Z,1557206274.096 [RudderServo](INFO): Powering down
2019-05-07T05:17:54.097Z,1557206274.097 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-07T05:17:54.097Z,1557206274.097 [ThrusterServo](INFO): Powering down
2019-05-07T05:17:54.098Z,1557206274.098 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-07T05:17:54.098Z,1557206274.098 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-07T05:17:54.099Z,1557206274.099 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-07T05:17:54.099Z,1557206274.099 [CBIT](DEBUG): Powering off loads.
2019-05-07T05:17:54.110Z,1557206274.110 [CBIT](DEBUG): Disabling WDT.
2019-05-07T05:17:54.122Z,1557206274.122 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-07T05:17:54.123Z,1557206274.123 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:54.179Z,1557206274.179 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:54.187Z,1557206274.187 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:54.239Z,1557206274.239 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:54.242Z,1557206274.242 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:54.296Z,1557206274.296 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T05:17:54.363Z,1557206274.363 [logger ThreadHandler](INFO): Thread cancelled.