2019-10-24T19:23:40.427Z,1571945020.427 [Supervisor](DEBUG): Initializing supervisor.
2019-10-24T19:23:40.430Z,1571945020.430 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-10-24T19:23:40.431Z,1571945020.431 [SyncHandler](INFO): Protected caller Thread ID is 1141
2019-10-24T19:23:40.431Z,1571945020.431 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-10-24T19:23:40.432Z,1571945020.432 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-10-24T19:23:40.433Z,1571945020.433 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1142
2019-10-24T19:23:40.436Z,1571945020.436 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-10-24T19:23:40.447Z,1571945020.447 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-10-24T19:23:40.448Z,1571945020.448 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-10-24T19:23:40.448Z,1571945020.448 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1143
2019-10-24T19:23:40.449Z,1571945020.449 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-10-24T19:23:40.450Z,1571945020.450 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-10-24T19:23:40.451Z,1571945020.451 [logger ThreadHandler](INFO): Protected caller Thread ID is 1144
2019-10-24T19:23:40.452Z,1571945020.452 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-10-24T19:23:40.453Z,1571945020.453 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-10-24T19:23:40.455Z,1571945020.455 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-10-24T19:23:40.852Z,1571945020.852 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-10-24T19:23:40.853Z,1571945020.853 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-10-24T19:23:40.948Z,1571945020.948 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-10-24T19:23:40.949Z,1571945020.949 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-10-24T19:23:41.244Z,1571945021.244 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-10-24T19:23:41.245Z,1571945021.245 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-10-24T19:23:41.379Z,1571945021.379 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-10-24T19:23:41.380Z,1571945021.380 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-10-24T19:23:41.562Z,1571945021.562 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-10-24T19:23:41.563Z,1571945021.563 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-10-24T19:23:42.143Z,1571945022.143 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-10-24T19:23:42.144Z,1571945022.144 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-10-24T19:23:42.339Z,1571945022.339 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-10-24T19:23:42.340Z,1571945022.340 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-10-24T19:23:42.478Z,1571945022.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-10-24T19:23:42.479Z,1571945022.479 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-10-24T19:23:42.662Z,1571945022.662 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-10-24T19:23:42.662Z,1571945022.662 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-10-24T19:23:42.755Z,1571945022.755 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-10-24T19:23:42.756Z,1571945022.756 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-10-24T19:23:43.039Z,1571945023.039 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-10-24T19:23:43.040Z,1571945023.040 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-10-24T19:23:43.119Z,1571945023.119 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-10-24T19:23:43.218Z,1571945023.218 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-10-24T19:23:43.218Z,1571945023.218 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-10-24T19:23:43.801Z,1571945023.801 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-10-24T19:23:43.801Z,1571945023.801 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-10-24T19:23:44.171Z,1571945024.171 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-10-24T19:23:44.173Z,1571945024.173 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-10-24T19:23:44.174Z,1571945024.174 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-10-24T19:23:44.366Z,1571945024.366 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-10-24T19:23:44.462Z,1571945024.462 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-10-24T19:23:44.557Z,1571945024.557 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-10-24T19:23:44.776Z,1571945024.776 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-10-24T19:23:44.777Z,1571945024.777 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-10-24T19:23:44.860Z,1571945024.860 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-10-24T19:23:44.951Z,1571945024.951 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-10-24T19:23:45.046Z,1571945025.046 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-10-24T19:23:45.127Z,1571945025.127 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-10-24T19:23:45.233Z,1571945025.233 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-10-24T19:23:45.410Z,1571945025.410 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-10-24T19:23:45.537Z,1571945025.537 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-10-24T19:23:45.542Z,1571945025.542 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-10-24T19:23:45.832Z,1571945025.832 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-10-24T19:23:45.838Z,1571945025.838 [AHRS_M2](INFO): created writer for : platform_orientation
2019-10-24T19:23:45.840Z,1571945025.840 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-10-24T19:23:45.845Z,1571945025.845 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-10-24T19:23:45.845Z,1571945025.845 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-10-24T19:23:45.850Z,1571945025.850 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-10-24T19:23:45.851Z,1571945025.851 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-10-24T19:23:45.856Z,1571945025.856 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-10-24T19:23:45.925Z,1571945025.925 [AHRS_M2] Loaded
2019-10-24T19:23:45.926Z,1571945025.926 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-10-24T19:23:45.998Z,1571945025.998 [DataOverHttps] Loaded
2019-10-24T19:23:45.998Z,1571945025.998 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-10-24T19:23:45.999Z,1571945025.999 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075C4E0
2019-10-24T19:23:45.000Z,1571945026.000 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1223
2019-10-24T19:23:46.012Z,1571945026.012 [Depth_Keller] Loaded
2019-10-24T19:23:46.013Z,1571945026.013 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-10-24T19:23:46.017Z,1571945026.017 [DropWeight] Loaded
2019-10-24T19:23:46.018Z,1571945026.018 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-10-24T19:23:46.073Z,1571945026.073 [DUSBL_Hydroid] Loaded
2019-10-24T19:23:46.074Z,1571945026.074 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-10-24T19:23:46.119Z,1571945026.119 [Micromodem] Loaded
2019-10-24T19:23:46.120Z,1571945026.120 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-10-24T19:23:46.214Z,1571945026.214 [NAL9602] Loaded
2019-10-24T19:23:46.214Z,1571945026.214 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-10-24T19:23:46.229Z,1571945026.229 [Onboard] Loaded
2019-10-24T19:23:46.230Z,1571945026.230 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-10-24T19:23:46.235Z,1571945026.235 [PowerOnly] Loaded
2019-10-24T19:23:46.236Z,1571945026.236 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-10-24T19:23:46.242Z,1571945026.242 [Radio_Surface] Loaded
2019-10-24T19:23:46.242Z,1571945026.242 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-10-24T19:23:46.243Z,1571945026.243 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078C4E0
2019-10-24T19:23:46.244Z,1571945026.244 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1224
2019-10-24T19:23:46.287Z,1571945026.287 [RDI_Pathfinder] Loaded
2019-10-24T19:23:46.287Z,1571945026.287 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-10-24T19:23:47.733Z,1571945027.733 [BPC1] Loaded
2019-10-24T19:23:47.733Z,1571945027.733 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-10-24T19:23:47.734Z,1571945027.734 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-10-24T19:23:47.734Z,1571945027.734 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-10-24T19:23:47.786Z,1571945027.786 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-10-24T19:23:47.787Z,1571945027.787 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-10-24T19:23:48.017Z,1571945028.017 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-10-24T19:23:48.017Z,1571945028.017 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-10-24T19:23:48.103Z,1571945028.103 [NavChart] Loaded
2019-10-24T19:23:48.103Z,1571945028.103 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-10-24T19:23:48.114Z,1571945028.114 [UniversalFixResidualReporter] Loaded
2019-10-24T19:23:48.114Z,1571945028.114 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-10-24T19:23:48.115Z,1571945028.115 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-10-24T19:23:48.115Z,1571945028.115 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-10-24T19:23:48.390Z,1571945028.390 [BuoyancyServo] Loaded
2019-10-24T19:23:48.390Z,1571945028.390 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-10-24T19:23:48.421Z,1571945028.421 [ElevatorServo] Loaded
2019-10-24T19:23:48.421Z,1571945028.421 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-10-24T19:23:48.456Z,1571945028.456 [MassServo] Loaded
2019-10-24T19:23:48.456Z,1571945028.456 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-10-24T19:23:48.559Z,1571945028.559 [RudderServo] Loaded
2019-10-24T19:23:48.559Z,1571945028.559 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-10-24T19:23:48.576Z,1571945028.576 [ThrusterServo] Loaded
2019-10-24T19:23:48.576Z,1571945028.576 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-10-24T19:23:48.576Z,1571945028.576 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-10-24T19:23:48.577Z,1571945028.577 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-10-24T19:23:48.827Z,1571945028.827 [CTD_NeilBrown] Loaded
2019-10-24T19:23:48.827Z,1571945028.827 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-10-24T19:23:48.828Z,1571945028.828 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D74E0
2019-10-24T19:23:48.829Z,1571945028.829 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1225
2019-10-24T19:23:48.843Z,1571945028.843 [PAR_Licor] Loaded
2019-10-24T19:23:48.843Z,1571945028.843 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-10-24T19:23:48.886Z,1571945028.886 [WetLabsSeaOWL_UV_A] Loaded
2019-10-24T19:23:48.886Z,1571945028.886 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-10-24T19:23:48.887Z,1571945028.887 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409074E0
2019-10-24T19:23:48.888Z,1571945028.888 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1226
2019-10-24T19:23:48.888Z,1571945028.888 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-10-24T19:23:48.889Z,1571945028.889 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-10-24T19:23:49.174Z,1571945029.174 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-10-24T19:23:49.174Z,1571945029.174 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-10-24T19:23:49.216Z,1571945029.216 [DepthRateCalculator] Loaded
2019-10-24T19:23:49.216Z,1571945029.216 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-10-24T19:23:49.222Z,1571945029.222 [PitchRateCalculator] Loaded
2019-10-24T19:23:49.222Z,1571945029.222 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-10-24T19:23:49.234Z,1571945029.234 [SpeedCalculator] Loaded
2019-10-24T19:23:49.234Z,1571945029.234 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-10-24T19:23:49.255Z,1571945029.255 [TempGradientCalculator] Loaded
2019-10-24T19:23:49.255Z,1571945029.255 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-10-24T19:23:49.260Z,1571945029.260 [YawRateCalculator] Loaded
2019-10-24T19:23:49.260Z,1571945029.260 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-10-24T19:23:49.299Z,1571945029.299 [ElevatorOffsetCalculator] Loaded
2019-10-24T19:23:49.299Z,1571945029.299 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-10-24T19:23:49.300Z,1571945029.300 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-10-24T19:23:49.300Z,1571945029.300 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-10-24T19:23:49.432Z,1571945029.432 [SBIT](DEBUG): Construct Startup Built In Test.
2019-10-24T19:23:49.453Z,1571945029.453 [SBIT] Loaded
2019-10-24T19:23:49.454Z,1571945029.454 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-10-24T19:23:49.454Z,1571945029.454 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-10-24T19:23:49.466Z,1571945029.466 [IBIT] Loaded
2019-10-24T19:23:49.466Z,1571945029.466 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-10-24T19:23:49.469Z,1571945029.469 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-10-24T19:23:49.602Z,1571945029.602 [CBIT] Loaded
2019-10-24T19:23:49.602Z,1571945029.602 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-10-24T19:23:49.603Z,1571945029.603 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-10-24T19:23:49.603Z,1571945029.603 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-10-24T19:23:49.686Z,1571945029.686 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-10-24T19:23:49.687Z,1571945029.687 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-10-24T19:23:49.784Z,1571945029.784 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-10-24T19:23:49.785Z,1571945029.785 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-10-24T19:23:49.851Z,1571945029.851 [VerticalControl](DEBUG): Construct VerticalControl.
2019-10-24T19:23:49.932Z,1571945029.932 [VerticalControl] Loaded
2019-10-24T19:23:49.933Z,1571945029.933 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-10-24T19:23:49.933Z,1571945029.933 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-10-24T19:23:49.988Z,1571945029.988 [HorizontalControl] Loaded
2019-10-24T19:23:49.989Z,1571945029.989 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-10-24T19:23:49.989Z,1571945029.989 [SpeedControl](DEBUG): Construct SpeedControl.
2019-10-24T19:23:49.991Z,1571945029.991 [SpeedControl] Loaded
2019-10-24T19:23:49.991Z,1571945029.991 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-10-24T19:23:49.992Z,1571945029.992 [LoopControl](DEBUG): Construct LoopControl.
2019-10-24T19:23:49.992Z,1571945029.992 [LoopControl] Loaded
2019-10-24T19:23:49.993Z,1571945029.993 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-10-24T19:23:49.993Z,1571945029.993 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-10-24T19:23:49.994Z,1571945029.994 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-10-24T19:23:50.026Z,1571945030.026 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-10-24T19:23:50.029Z,1571945030.029 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-10-24T19:23:50.030Z,1571945030.030 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-10-24T19:23:50.037Z,1571945030.037 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-10-24T19:23:50.038Z,1571945030.038 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AE44E0
2019-10-24T19:23:50.039Z,1571945030.039 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1227
2019-10-24T19:23:50.043Z,1571945030.043 [Supervisor](INFO): Main Thread ID is 802
2019-10-24T19:23:50.043Z,1571945030.043 [Supervisor](DEBUG): Running supervisor.
2019-10-24T19:23:50.044Z,1571945030.044 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1228
2019-10-24T19:23:50.046Z,1571945030.046 [controlThread ThreadHandler](INFO): Handler Thread ID is 1229
2019-10-24T19:23:50.047Z,1571945030.047 [controlThread](DEBUG): Initializing ControlThread
2019-10-24T19:23:50.052Z,1571945030.052 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-10-24T19:23:50.052Z,1571945030.052 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-10-24T19:23:50.057Z,1571945030.057 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-10-24T19:23:50.057Z,1571945030.057 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-10-24T19:23:50.058Z,1571945030.058 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-10-24T19:23:50.058Z,1571945030.058 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-10-24T19:23:50.059Z,1571945030.059 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-10-24T19:23:50.059Z,1571945030.059 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-10-24T19:23:50.059Z,1571945030.059 [SBIT](INFO): Initialize SBIT Component.
2019-10-24T19:23:50.060Z,1571945030.060 [SBIT](IMPORTANT): git: 2019-10-15
2019-10-24T19:23:50.060Z,1571945030.060 [SBIT](INFO): git hash: 5afd4984613942c073d284d94e598e25fc5569fb
2019-10-24T19:23:50.060Z,1571945030.060 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-10-24T19:23:50.062Z,1571945030.062 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #2 PREEMPT Wed May 15 08:34:03 PDT 2019
2019-10-24T19:23:50.063Z,1571945030.063 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-10-24T19:23:50.063Z,1571945030.063 [IBIT](INFO): Initialize IBIT Component.
2019-10-24T19:23:50.064Z,1571945030.064 [CBIT](DEBUG): Initialize CBIT Component.
2019-10-24T19:23:50.065Z,1571945030.065 [logger ThreadHandler](INFO): Handler Thread ID is 1230
2019-10-24T19:23:50.077Z,1571945030.077 [CBIT](DEBUG): Initialized mux pins.
2019-10-24T19:23:50.077Z,1571945030.077 [CBIT](DEBUG): Initializing the watchdog timer.
2019-10-24T19:23:50.085Z,1571945030.085 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1231
2019-10-24T19:23:50.086Z,1571945030.086 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-10-24T19:23:50.097Z,1571945030.097 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1232
2019-10-24T19:23:50.101Z,1571945030.101 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-10-24T19:23:50.101Z,1571945030.101 [CBIT](DEBUG): Initializing heartbeat.
2019-10-24T19:23:50.109Z,1571945030.109 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1233
2019-10-24T19:23:50.110Z,1571945030.110 [CTD_NeilBrown](INFO): Powering down
2019-10-24T19:23:50.129Z,1571945030.129 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1234
2019-10-24T19:23:50.130Z,1571945030.130 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-10-24T19:23:50.162Z,1571945030.162 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1235
2019-10-24T19:23:50.165Z,1571945030.165 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-10-24T19:23:50.165Z,1571945030.165 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-10-24T19:23:50.165Z,1571945030.165 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-10-24T19:23:50.165Z,1571945030.165 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-10-24T19:23:50.166Z,1571945030.166 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-10-24T19:23:50.166Z,1571945030.166 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-10-24T19:23:50.166Z,1571945030.166 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-10-24T19:23:50.166Z,1571945030.166 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-10-24T19:23:50.166Z,1571945030.166 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-10-24T19:23:50.167Z,1571945030.167 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-10-24T19:23:50.167Z,1571945030.167 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-10-24T19:23:50.167Z,1571945030.167 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-10-24T19:23:50.167Z,1571945030.167 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-10-24T19:23:50.167Z,1571945030.167 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-10-24T19:23:50.168Z,1571945030.168 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-10-24T19:23:50.168Z,1571945030.168 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-10-24T19:23:50.173Z,1571945030.173 [CBIT](DEBUG): Deactivating GF circuits.
2019-10-24T19:23:50.173Z,1571945030.173 [CBIT](DEBUG): Deactivating emergency mode.
2019-10-24T19:23:50.209Z,1571945030.209 [CBIT](DEBUG): Backplane powered.
2019-10-24T19:23:50.209Z,1571945030.209 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-10-24T19:23:50.211Z,1571945030.211 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-10-24T19:23:50.212Z,1571945030.212 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-10-24T19:23:50.212Z,1571945030.212 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-10-24T19:23:50.213Z,1571945030.213 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-10-24T19:23:50.224Z,1571945030.224 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-24T19:23:50.247Z,1571945030.247 [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-10-24T19:23:50.248Z,1571945030.248 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-10-24T19:23:50.335Z,1571945030.335 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-10-24T19:23:50.336Z,1571945030.336 [Default:A.Wait](DEBUG): Construct Wait.
2019-10-24T19:23:50.338Z,1571945030.338 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-24T19:23:50.365Z,1571945030.365 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-10-24T19:23:50.368Z,1571945030.368 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-10-24T19:23:50.389Z,1571945030.389 [Default:E.Execute](DEBUG): Construct Execute.
2019-10-24T19:23:50.405Z,1571945030.405 [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-10-24T19:23:50.410Z,1571945030.410 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,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-10-24T19:23:50.433Z,1571945030.433 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-10-24T19:23:50.468Z,1571945030.468 [DUSBL_Hydroid](INFO): Powering up
2019-10-24T19:23:50.468Z,1571945030.468 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-10-24T19:23:50.501Z,1571945030.501 [Radio_Surface](INFO): Powering up
2019-10-24T19:23:50.710Z,1571945030.710 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-10-24T19:23:50.717Z,1571945030.717 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-10-24T19:23:50.718Z,1571945030.718 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-10-24T19:23:50.725Z,1571945030.725 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-10-24T19:23:50.726Z,1571945030.726 [MassServo](DEBUG): Initializing EZServoServo.
2019-10-24T19:23:50.733Z,1571945030.733 [MassServo](DEBUG): Initializing MassServo.
2019-10-24T19:23:50.734Z,1571945030.734 [RudderServo](DEBUG): Initializing EZServoServo.
2019-10-24T19:23:50.741Z,1571945030.741 [RudderServo](DEBUG): Initializing RudderServo.
2019-10-24T19:23:50.742Z,1571945030.742 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-10-24T19:23:50.749Z,1571945030.749 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-10-24T19:23:50.916Z,1571945030.916 [Micromodem](INFO): Powering up
2019-10-24T19:23:50.916Z,1571945030.916 [Micromodem](DEBUG): Initializing Micromodem.
2019-10-24T19:23:51.593Z,1571945031.593 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-10-24T19:23:51.593Z,1571945031.593 [RudderServo](FAULT): Rudder failed to initialize
2019-10-24T19:23:51.593Z,1571945031.593 [RudderServo] Communications Fault, FailCount= 1
2019-10-24T19:23:51.593Z,1571945031.593 [RudderServo](ERROR): Communications Fault
2019-10-24T19:23:51.704Z,1571945031.704 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-10-24T19:23:51.910Z,1571945031.910 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-10-24T19:23:51.910Z,1571945031.910 [RudderServo](INFO): Powering down
2019-10-24T19:23:52.587Z,1571945032.587 [RudderServo](DEBUG): Initializing EZServoServo.
2019-10-24T19:23:52.706Z,1571945032.706 [RudderServo](DEBUG): Initializing RudderServo.
2019-10-24T19:23:52.710Z,1571945032.710 [CBIT](INFO): Clearing failed state for component RudderServo
2019-10-24T19:23:52.710Z,1571945032.710 [RudderServo] No Fault, FailCount= 1
2019-10-24T19:23:55.791Z,1571945035.791 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-10-24T19:23:55.792Z,1571945035.792 [Micromodem](INFO): Applying Homing Configuration Settings
2019-10-24T19:24:01.113Z,1571945041.113 [Micromodem](INFO): Nmea in: $CATMG,2019-10-24T19:23:59.681484Z,RTC,RTC*5F

2019-10-24T19:24:01.113Z,1571945041.113 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-10-24T19:23:59.681484Z,RTC,RTC*5F

2019-10-24T19:24:03.913Z,1571945043.913 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-10-24T19:24:07.119Z,1571945047.119 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-10-24T19:24:07.523Z,1571945047.523 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-10-24T19:24:07.523Z,1571945047.523 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-10-24T19:24:07.927Z,1571945047.927 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-10-24T19:24:07.927Z,1571945047.927 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-10-24T19:24:08.331Z,1571945048.331 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-10-24T19:24:08.346Z,1571945048.346 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-10-24T19:24:08.346Z,1571945048.346 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-10-24T19:24:08.735Z,1571945048.735 [Micromodem](INFO): Nmea in: $CACFG,BND,1*39

2019-10-24T19:24:08.735Z,1571945048.735 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-10-24T19:24:09.139Z,1571945049.139 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-10-24T19:24:09.139Z,1571945049.139 [Micromodem](INFO): Nmea out: $CCCLK,2019,10,24,19,24,09*4E

2019-10-24T19:24:10.347Z,1571945050.347 [Micromodem](INFO): Nmea in: $CACLK,2019,10,24,19,24,9*7C

2019-10-24T19:24:10.348Z,1571945050.348 [Micromodem](INFO): Nmea in: $CATMS,0,2019-10-24T19:24:10Z*74

2019-10-24T19:24:10.350Z,1571945050.350 [Micromodem](INFO): Nmea in: $CATMG,2019-10-24T19:24:10.026156Z,USER_CMD,RTC*15

2019-10-24T19:24:16.414Z,1571945056.414 [NAL9602](INFO): Powering up NAL9602
2019-10-24T19:24:18.505Z,1571945058.505 [SBIT](IMPORTANT): Beginning Startup BIT
2019-10-24T19:24:18.513Z,1571945058.513 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-24T19:24:27.315Z,1571945067.315 [NAL9602](INFO): NAL9602 initialized
2019-10-24T19:24:28.137Z,1571945068.137 [NAL9602](DEBUG): Fix Requested
2019-10-24T19:24:29.423Z,1571945069.423 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.015238
CHAN A1 (24V): -0.020065
CHAN A2 (12V): -0.004078
CHAN A3 (5V): -0.001609
CHAN B0 (3.3V): 0.000594
CHAN B1 (3.15aV): 0.000352
CHAN B2 (3.15bV): 0.000034
CHAN B3 (GND): 0.001151
OPEN: 0.005580
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-24T19:24:31.863Z,1571945071.863 [SBIT](ERROR): Could not read massPosReader_.
2019-10-24T19:24:38.676Z,1571945078.676 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-10-24T19:24:38.681Z,1571945078.681 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19102412351221,35.0, -0.1,   0.0  0
2019-10-24T19:25:12.336Z,1571945112.336 [SBIT](CRITICAL): SBIT FAILED
2019-10-24T19:25:12.374Z,1571945112.374 [CommandLine](IMPORTANT): got command configSet list
2019-10-24T19:25:12.375Z,1571945112.375 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-10-24T19:25:12.375Z,1571945112.375 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=25 count;

2019-10-24T19:25:12.375Z,1571945112.375 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=30 millisecond;

2019-10-24T19:25:12.376Z,1571945112.376 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity=3 enum;

2019-10-24T19:25:12.378Z,1571945112.378 [CommandLine](FAULT): Scheduling is paused
2019-10-24T19:25:12.378Z,1571945112.378 [CBIT](INFO): Critical error at 20191024T192512
2019-10-24T19:25:12.379Z,1571945112.379 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-10-24T19:25:12.735Z,1571945112.735 [MissionManager](IMPORTANT): Started mission Startup
2019-10-24T19:25:12.735Z,1571945112.735 [Startup] Running Loop=1
2019-10-24T19:25:12.735Z,1571945112.735 [Startup](DEBUG): Aggregate::initialize Startup
2019-10-24T19:25:12.736Z,1571945112.736 [Startup:A.GoToSurface] Running Loop=1
2019-10-24T19:25:12.736Z,1571945112.736 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-24T19:25:12.736Z,1571945112.736 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-24T19:25:12.741Z,1571945112.741 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-24T19:25:12.741Z,1571945112.741 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-24T19:25:12.742Z,1571945112.742 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-24T19:25:12.742Z,1571945112.742 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-24T19:25:12.743Z,1571945112.743 [Startup:StartupSatComms] Running Loop=1
2019-10-24T19:25:12.744Z,1571945112.744 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-10-24T19:25:12.744Z,1571945112.744 [Startup:StartupSatComms:A] Running Loop=1
2019-10-24T19:25:13.112Z,1571945113.112 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-10-24T19:26:00.337Z,1571945160.337 [NAL9602](INFO): SBD MO Status=2, MOMSN=9749, MT Status=2, MTMSN=0
2019-10-24T19:26:00.337Z,1571945160.337 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-24T19:26:12.908Z,1571945172.908 [Startup:StartupSatComms:A](INFO): Timed out from 2019-10-24T19:25:12.7Z
2019-10-24T19:26:12.908Z,1571945172.908 [Startup:StartupSatComms:A] Stopped
2019-10-24T19:26:12.908Z,1571945172.908 [Startup:StartupSatComms:B] Running Loop=1
2019-10-24T19:26:13.268Z,1571945173.268 [NAL9602](INFO): SBD MO Status=2, MOMSN=9749, MT Status=2, MTMSN=0
2019-10-24T19:26:13.268Z,1571945173.268 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-24T19:26:13.293Z,1571945173.293 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-24T19:26:50.070Z,1571945210.070 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-10-24T19:26:50.070Z,1571945210.070 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-24T19:26:50.080Z,1571945210.080 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-24T19:26:50.477Z,1571945210.477 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-24T19:26:50.477Z,1571945210.477 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-10-24T19:27:13.161Z,1571945233.161 [Startup:StartupSatComms:B](INFO): Timed out from 2019-10-24T19:26:12.9Z
2019-10-24T19:27:13.161Z,1571945233.161 [Startup:StartupSatComms:B] Stopped
2019-10-24T19:27:13.161Z,1571945233.161 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-10-24T19:27:13.161Z,1571945233.161 [Startup:StartupSatComms] Stopped
2019-10-24T19:27:13.161Z,1571945233.161 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-10-24T19:27:13.162Z,1571945233.162 [Startup](INFO): Completed Startup
2019-10-24T19:27:13.162Z,1571945233.162 [MissionManager](INFO): Startup is completed.
2019-10-24T19:27:13.163Z,1571945233.163 [MissionManager](INFO): Uninitializing Mission Startup
2019-10-24T19:27:13.163Z,1571945233.163 [Startup] Stopped
2019-10-24T19:27:13.163Z,1571945233.163 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-10-24T19:27:13.163Z,1571945233.163 [Startup:A.GoToSurface] Stopped
2019-10-24T19:27:13.163Z,1571945233.163 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-24T19:27:13.570Z,1571945233.570 [MissionManager](IMPORTANT): Started mission Default
2019-10-24T19:27:13.570Z,1571945233.570 [Default] Running Loop=1
2019-10-24T19:27:13.570Z,1571945233.570 [Default](DEBUG): Aggregate::initialize Default
2019-10-24T19:27:13.570Z,1571945233.570 [Default:B.GoToSurface] Running Loop=1
2019-10-24T19:27:13.570Z,1571945233.570 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-24T19:27:13.570Z,1571945233.570 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-24T19:27:13.571Z,1571945233.571 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-24T19:27:13.571Z,1571945233.571 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-24T19:27:13.571Z,1571945233.571 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-24T19:27:13.572Z,1571945233.572 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-24T19:27:13.572Z,1571945233.572 [Default:A.Wait] Running Loop=1
2019-10-24T19:27:13.572Z,1571945233.572 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:27:26.931Z,1571945246.931 [Default:A.Wait](INFO): Done Waiting.
2019-10-24T19:27:26.931Z,1571945246.931 [Default:A.Wait] Stopped
2019-10-24T19:27:26.931Z,1571945246.931 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:27:27.293Z,1571945247.293 [Default:CheckIn] Running Loop=1
2019-10-24T19:27:27.293Z,1571945247.293 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T19:27:27.293Z,1571945247.293 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T19:27:27.699Z,1571945247.699 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-10-24T19:27:29.507Z,1571945249.507 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004917
2019-10-24T19:28:55.741Z,1571945335.741 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-10-24T19:28:55.741Z,1571945335.741 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,       -0.65,     0.00
2019-10-24T19:29:33.272Z,1571945373.272 [NAL9602](INFO): SBD MO Status=2, MOMSN=9749, MT Status=2, MTMSN=0
2019-10-24T19:29:33.273Z,1571945373.273 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-24T19:29:33.684Z,1571945373.684 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-24T19:29:34.500Z,1571945374.500 [NAL9602](DEBUG): Fix Requested
2019-10-24T19:29:34.885Z,1571945374.885 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192829.00,A,3648.16535,N,12147.27973,W,0.194,0.00,241019,,,A*72
2019-10-24T19:29:34.888Z,1571945374.888 [NAL9602](INFO): GPS fix at 20191024T192829: (36.802756, -121.787995)
2019-10-24T19:29:34.959Z,1571945374.959 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T19:29:34.959Z,1571945374.959 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T19:29:35.376Z,1571945375.376 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-24T19:29:47.429Z,1571945387.429 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20191024T192340/Courier0000.lzma
2019-10-24T19:29:49.434Z,1571945389.434 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Courier0000.lzma.bak
2019-10-24T19:29:49.435Z,1571945389.435 [DataOverHttps](INFO): SBD MOMSN=11952010
2019-10-24T19:30:06.818Z,1571945406.818 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-24T19:30:12.977Z,1571945412.977 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20191024T192340/Courier0004.lzma
2019-10-24T19:30:14.982Z,1571945414.982 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Courier0004.lzma.bak
2019-10-24T19:30:14.982Z,1571945414.982 [DataOverHttps](INFO): SBD MOMSN=11952014
2019-10-24T19:30:42.196Z,1571945442.196 [DataOverHttps](INFO): Sending 143 bytes from file Logs/20191024T181745/Express0068.lzma
2019-10-24T19:30:44.203Z,1571945444.203 [DataOverHttps](INFO): Moved sent file to Logs/20191024T181745/Express0068.lzma.bak
2019-10-24T19:30:44.203Z,1571945444.203 [DataOverHttps](INFO): SBD MOMSN=11952025
2019-10-24T19:31:08.213Z,1571945468.213 [DataOverHttps](INFO): Sending 702 bytes from file Logs/20191024T192340/Express0001.lzma
2019-10-24T19:31:10.230Z,1571945470.230 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Express0001.lzma.bak
2019-10-24T19:31:10.231Z,1571945470.231 [DataOverHttps](INFO): SBD MOMSN=11952038
2019-10-24T19:31:14.876Z,1571945474.876 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-10-24T19:31:14.883Z,1571945474.883 [BPC1](INFO): Received data from all battery sticks.
2019-10-24T19:31:15.690Z,1571945475.690 [RDI_Pathfinder](ERROR): Failed to parse:2,A
2019-10-24T19:31:34.785Z,1571945494.785 [DataOverHttps](INFO): Sending 308 bytes from file Logs/20191024T192340/Express0005.lzma
2019-10-24T19:31:36.790Z,1571945496.790 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Express0005.lzma.bak
2019-10-24T19:31:36.791Z,1571945496.791 [DataOverHttps](INFO): SBD MOMSN=11952054
2019-10-24T19:31:43.964Z,1571945503.964 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T19:31:43.964Z,1571945503.964 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-24T19:31:43.964Z,1571945503.964 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:36:44.527Z,1571945804.527 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-24T19:36:44.527Z,1571945804.527 [Default:CheckIn:C.Wait] Stopped
2019-10-24T19:36:44.527Z,1571945804.527 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:36:44.527Z,1571945804.527 [Default:CheckIn:D] Running Loop=1
2019-10-24T19:36:44.942Z,1571945804.942 [Default:CheckIn:D] Stopped
2019-10-24T19:36:44.942Z,1571945804.942 [Default:CheckIn:E] Running Loop=1
2019-10-24T19:36:45.327Z,1571945805.327 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.522874 min 
2019-10-24T19:36:45.327Z,1571945805.327 [Default:CheckIn:E] Stopped
2019-10-24T19:36:45.327Z,1571945805.327 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-24T19:36:45.327Z,1571945805.327 [Default:CheckIn] Stopped
2019-10-24T19:36:45.327Z,1571945805.327 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T19:36:45.327Z,1571945805.327 [Default:CheckIn](INFO): Running loop #2
2019-10-24T19:36:45.327Z,1571945805.327 [Default:CheckIn] Running Loop=2
2019-10-24T19:36:45.328Z,1571945805.328 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T19:36:45.328Z,1571945805.328 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T19:36:46.933Z,1571945806.933 [NAL9602](DEBUG): Fix Requested
2019-10-24T19:36:47.325Z,1571945807.325 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193542.00,A,3648.16407,N,12147.28311,W,0.136,0.00,241019,,,A*7A
2019-10-24T19:36:47.327Z,1571945807.327 [NAL9602](INFO): GPS fix at 20191024T193542: (36.802734, -121.788052)
2019-10-24T19:36:47.351Z,1571945807.351 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T19:36:47.351Z,1571945807.351 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T19:36:55.016Z,1571945815.016 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20191024T192340/Courier0007.lzma
2019-10-24T19:36:57.026Z,1571945817.026 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Courier0007.lzma.bak
2019-10-24T19:36:57.026Z,1571945817.026 [DataOverHttps](INFO): SBD MOMSN=11952064
2019-10-24T19:37:20.560Z,1571945840.560 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20191024T192340/Express0008.lzma
2019-10-24T19:37:22.566Z,1571945842.566 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Express0008.lzma.bak
2019-10-24T19:37:22.567Z,1571945842.567 [DataOverHttps](INFO): SBD MOMSN=11952067
2019-10-24T19:37:33.985Z,1571945853.985 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T19:37:33.985Z,1571945853.985 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-24T19:37:33.985Z,1571945853.985 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:37:38.064Z,1571945858.064 [CommandLine](IMPORTANT): got command show variable range
2019-10-24T19:37:38.066Z,1571945858.066 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-10-24T19:37:38.203Z,1571945858.203 [CommandLine](IMPORTANT): BR_Ping1D.minRange (meter)
2019-10-24T19:37:38.204Z,1571945858.204 [CommandLine](IMPORTANT): BR_Ping1D.maxRange (meter)
2019-10-24T19:37:38.250Z,1571945858.250 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-10-24T19:37:38.252Z,1571945858.252 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-10-24T19:37:38.252Z,1571945858.252 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-10-24T19:37:38.293Z,1571945858.293 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-10-24T19:37:38.293Z,1571945858.293 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-10-24T19:37:38.294Z,1571945858.294 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-10-24T19:37:38.294Z,1571945858.294 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-10-24T19:37:46.718Z,1571945866.718 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.acoustic_contact_range
2019-10-24T19:37:51.463Z,1571945871.463 [CommandLine](IMPORTANT): got command show variable detection
2019-10-24T19:37:51.527Z,1571945871.527 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-10-24T19:37:57.216Z,1571945877.216 [CommandLine](IMPORTANT): got command get DUSBL_Hydroid.detectionThreshold
2019-10-24T19:37:57.217Z,1571945877.217 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold 25 count
2019-10-24T19:38:34.959Z,1571945914.959 [DataOverHttps](IMPORTANT): SBD MTMSN=20191024T193729
2019-10-24T19:38:47.553Z,1571945927.553 [DataOverHttps](INFO): Received command:load Maintenance/DUSBL_Tracking.xml;set DUSBL.TrackingUpdatePeriod 7 second;run 
2019-10-24T19:38:47.570Z,1571945927.570 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:38:47.571Z,1571945927.571 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:38:47.703Z,1571945927.703 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-10-24T19:38:47.711Z,1571945927.711 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-10-24T19:38:47.723Z,1571945927.723 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-10-24T19:38:47.739Z,1571945927.739 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-10-24T19:38:47.750Z,1571945927.750 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-10-24T19:38:47.751Z,1571945927.751 [DUSBL:A.Pitch](DEBUG): Construct.
2019-10-24T19:38:47.790Z,1571945927.790 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-10-24T19:38:48.142Z,1571945928.142 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-10-24T19:38:48.150Z,1571945928.150 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</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>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-10-24T19:38:48.151Z,1571945928.151 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:38:52.285Z,1571945932.285 [CommandLine](IMPORTANT): got command set DUSBL.TrackingUpdatePeriod 7.000000 second
2019-10-24T19:38:52.286Z,1571945932.286 [CommandLine](IMPORTANT): got command run 
2019-10-24T19:38:52.288Z,1571945932.288 [CommandLine](IMPORTANT): Running 
2019-10-24T19:38:52.396Z,1571945932.396 [Default] Stopped
2019-10-24T19:38:52.396Z,1571945932.396 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-24T19:38:52.397Z,1571945932.397 [Default:B.GoToSurface] Stopped
2019-10-24T19:38:52.401Z,1571945932.401 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-24T19:38:52.401Z,1571945932.401 [Default:CheckIn] Stopped
2019-10-24T19:38:52.401Z,1571945932.401 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T19:38:52.401Z,1571945932.401 [Default:CheckIn:C.Wait] Stopped
2019-10-24T19:38:52.401Z,1571945932.401 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:38:52.402Z,1571945932.402 [MissionManager](IMPORTANT): Started mission DUSBL
2019-10-24T19:38:52.402Z,1571945932.402 [DUSBL] Running Loop=1
2019-10-24T19:38:52.402Z,1571945932.402 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-10-24T19:38:52.402Z,1571945932.402 [DUSBL:A.Pitch] Running Loop=1
2019-10-24T19:38:52.402Z,1571945932.402 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-10-24T19:38:52.403Z,1571945932.403 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-24T19:38:52.403Z,1571945932.403 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-10-24T19:38:52.403Z,1571945932.403 [DUSBL:C.] Running Loop=1
2019-10-24T19:38:52.403Z,1571945932.403 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-10-24T19:38:52.403Z,1571945932.403 [DUSBL:RequestRepeater] Running Loop=1
2019-10-24T19:38:52.403Z,1571945932.403 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-10-24T19:38:52.404Z,1571945932.404 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-10-24T19:38:52.404Z,1571945932.404 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:38:52.404Z,1571945932.404 [DUSBL:C.] Running Loop=1
2019-10-24T19:38:52.417Z,1571945932.417 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-24T19:38:52.417Z,1571945932.417 [DUSBL:A.Pitch] Running Loop=1
2019-10-24T19:38:59.651Z,1571945939.651 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:38:59.990Z,1571945939.990 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:38:59.990Z,1571945939.990 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:38:59.990Z,1571945939.990 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 25
2019-10-24T19:38:59.991Z,1571945939.991 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:39:00.398Z,1571945940.398 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
O
2019-10-24T19:39:00.398Z,1571945940.398 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:39:00.398Z,1571945940.398 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:39:00.400Z,1571945940.400 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:39:00.801Z,1571945940.801 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:39:01.607Z,1571945941.607 [Micromodem](INFO): Nmea in: $SNTTA,,,,,193901.10*5C

2019-10-24T19:39:04.036Z,1571945944.036 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
2019-10-24T19:39:04.037Z,1571945944.037 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
2019-10-24T19:39:04.037Z,1571945944.037 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:39:06.966Z,1571945946.966 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:39:07.262Z,1571945947.262 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:39:07.262Z,1571945947.262 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:39:07.262Z,1571945947.262 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 25
2019-10-24T19:39:07.262Z,1571945947.262 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:39:07.675Z,1571945947.675 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
2019-10-24T19:39:07.675Z,1571945947.675 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:39:07.675Z,1571945947.675 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:39:07.677Z,1571945947.677 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:39:08.069Z,1571945948.069 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:39:08.883Z,1571945948.883 [Micromodem](INFO): Nmea in: $SNTTA,,,,,193908.37*50

2019-10-24T19:39:11.299Z,1571945951.299 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
2019-10-24T19:39:11.299Z,1571945951.299 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
2019-10-24T19:39:11.299Z,1571945951.299 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:39:14.181Z,1571945954.181 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:39:14.530Z,1571945954.530 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:39:14.530Z,1571945954.530 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:39:14.530Z,1571945954.530 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 25
2019-10-24T19:39:14.531Z,1571945954.531 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:39:20.606Z,1571945960.606 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.074298
2019-10-24T19:39:21.439Z,1571945961.439 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:39:21.806Z,1571945961.806 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:39:21.806Z,1571945961.806 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:39:21.806Z,1571945961.806 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 25
2019-10-24T19:39:21.807Z,1571945961.807 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:39:22.212Z,1571945962.212 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
2019-10-24T19:39:22.212Z,1571945962.212 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:39:22.212Z,1571945962.212 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:39:22.215Z,1571945962.215 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:39:22.623Z,1571945962.623 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:39:23.443Z,1571945963.443 [Micromodem](INFO): Nmea in: $SNTTA,,,,,193922.91*54

2019-10-24T19:39:25.859Z,1571945965.859 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
2019-10-24T19:39:25.859Z,1571945965.859 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
2019-10-24T19:39:25.859Z,1571945965.859 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:39:28.749Z,1571945968.749 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:39:29.072Z,1571945969.072 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:39:29.072Z,1571945969.072 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:39:29.072Z,1571945969.072 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 25
2019-10-24T19:39:29.073Z,1571945969.073 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:39:29.477Z,1571945969.477 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
2019-10-24T19:39:29.477Z,1571945969.477 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:39:29.477Z,1571945969.477 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:39:29.479Z,1571945969.479 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:39:29.885Z,1571945969.885 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:39:30.713Z,1571945970.713 [Micromodem](INFO): Nmea in: $SNTTA,,,,,193930.18*56

2019-10-24T19:39:32.541Z,1571945972.541 [CommandLine](IMPORTANT): got command stop
2019-10-24T19:39:32.541Z,1571945972.541 [CommandLine](IMPORTANT): Scheduling is paused
2019-10-24T19:39:32.541Z,1571945972.541 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-10-24T19:39:32.755Z,1571945972.755 [MissionManager](INFO): MissionManager is completed.
2019-10-24T19:39:32.755Z,1571945972.755 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-10-24T19:39:32.755Z,1571945972.755 [DUSBL] Stopped
2019-10-24T19:39:32.755Z,1571945972.755 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-10-24T19:39:32.755Z,1571945972.755 [DUSBL:A.Pitch] Stopped
2019-10-24T19:39:32.755Z,1571945972.755 [DUSBL:B.SetSpeed] Stopped
2019-10-24T19:39:32.755Z,1571945972.755 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-10-24T19:39:32.756Z,1571945972.756 [DUSBL:C.] Stopped
2019-10-24T19:39:32.756Z,1571945972.756 [DUSBL:RequestRepeater] Stopped
2019-10-24T19:39:32.756Z,1571945972.756 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-10-24T19:39:32.756Z,1571945972.756 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-10-24T19:39:32.756Z,1571945972.756 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:39:33.152Z,1571945973.152 [MissionManager](IMPORTANT): Started mission Default
2019-10-24T19:39:33.152Z,1571945973.152 [Default] Running Loop=1
2019-10-24T19:39:33.152Z,1571945973.152 [Default](DEBUG): Aggregate::initialize Default
2019-10-24T19:39:33.152Z,1571945973.152 [Default:B.GoToSurface] Running Loop=1
2019-10-24T19:39:33.152Z,1571945973.152 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-24T19:39:33.152Z,1571945973.152 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-24T19:39:33.153Z,1571945973.153 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-24T19:39:33.153Z,1571945973.153 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-24T19:39:33.154Z,1571945973.154 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-24T19:39:33.154Z,1571945973.154 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-24T19:39:33.154Z,1571945973.154 [Default:A.Wait] Running Loop=1
2019-10-24T19:39:33.154Z,1571945973.154 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:39:39.822Z,1571945979.822 [CommandLine](IMPORTANT): got command show variable detectionThresh
2019-10-24T19:39:39.884Z,1571945979.884 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-10-24T19:39:46.497Z,1571945986.497 [Default:A.Wait](INFO): Done Waiting.
2019-10-24T19:39:46.497Z,1571945986.497 [Default:A.Wait] Stopped
2019-10-24T19:39:46.497Z,1571945986.497 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:39:46.888Z,1571945986.888 [Default:CheckIn] Running Loop=1
2019-10-24T19:39:46.889Z,1571945986.889 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T19:39:46.889Z,1571945986.889 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T19:39:49.592Z,1571945989.592 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.detectionThreshold 15.000000 count persist
2019-10-24T19:39:55.607Z,1571945995.607 [CommandLine](IMPORTANT): got command failComponent hardware DUSBL_Hydroid
2019-10-24T19:39:55.608Z,1571945995.608 [DUSBL_Hydroid] Hardware Fault, FailCount= 1
2019-10-24T19:39:55.608Z,1571945995.608 [DUSBL_Hydroid](ERROR): Hardware Fault
2019-10-24T19:39:55.608Z,1571945995.608 [CommandLine](IMPORTANT): DUSBL_Hydroid failureMode is Hardware Fault
2019-10-24T19:39:55.756Z,1571945995.756 [DUSBL_Hydroid](INFO): Powering down
2019-10-24T19:39:55.887Z,1571945995.887 [CBIT](ERROR): Hardware Fault in component: DUSBL_Hydroid
2019-10-24T19:39:56.625Z,1571945996.625 [CBIT](INFO): Clearing failed state for component DUSBL_Hydroid
2019-10-24T19:39:56.625Z,1571945996.625 [DUSBL_Hydroid] No Fault, FailCount= 1
2019-10-24T19:39:58.971Z,1571945998.971 [DUSBL_Hydroid](INFO): Powering up
2019-10-24T19:39:58.971Z,1571945998.971 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-10-24T19:40:01.138Z,1571946001.138 [CommandLine](IMPORTANT): got command configSet list
2019-10-24T19:40:01.139Z,1571946001.139 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-10-24T19:40:01.139Z,1571946001.139 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=15 count;

2019-10-24T19:40:01.140Z,1571946001.140 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=30 millisecond;

2019-10-24T19:40:01.140Z,1571946001.140 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity=3 enum;

2019-10-24T19:40:07.860Z,1571946007.860 [NAL9602](INFO): SBD MO Status=2, MOMSN=9749, MT Status=2, MTMSN=0
2019-10-24T19:40:07.861Z,1571946007.861 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-24T19:40:17.150Z,1571946017.150 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-10-24T19:40:25.232Z,1571946025.232 [NAL9602](INFO): SBD MO Status=0, MOMSN=9749, MT Status=0, MTMSN=0
2019-10-24T19:40:25.232Z,1571946025.232 [NAL9602](INFO): No messages in MT queue
2019-10-24T19:40:26.053Z,1571946026.053 [NAL9602](DEBUG): Fix Requested
2019-10-24T19:40:26.445Z,1571946026.445 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193922.00,A,3648.15918,N,12147.27897,W,0.117,0.00,241019,,,A*79
2019-10-24T19:40:26.447Z,1571946026.447 [NAL9602](INFO): GPS fix at 20191024T193922: (36.802653, -121.787983)
2019-10-24T19:40:26.519Z,1571946026.519 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T19:40:26.519Z,1571946026.519 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T19:40:32.513Z,1571946032.513 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191024T192340/Courier0010.lzma
2019-10-24T19:40:34.523Z,1571946034.523 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Courier0010.lzma.bak
2019-10-24T19:40:34.523Z,1571946034.523 [DataOverHttps](IMPORTANT): SBD MOMSN=11952073, MTMSN=20191024T193928
2019-10-24T19:40:50.782Z,1571946050.782 [CommandLine](IMPORTANT): got command failComponent
2019-10-24T19:40:50.783Z,1571946050.783 [CommandLine](IMPORTANT): Failed components:
2019-10-24T19:40:50.783Z,1571946050.783 [CommandLine](IMPORTANT): No failed Components.
2019-10-24T19:40:58.269Z,1571946058.269 [DataOverHttps](INFO): Received command:load Maintenance/DUSBL_Tracking.xml;set DUSBL.TrackingUpdatePeriod 7 second;run 
2019-10-24T19:40:58.287Z,1571946058.287 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:40:58.287Z,1571946058.287 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:40:58.342Z,1571946058.342 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-10-24T19:40:58.344Z,1571946058.344 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-10-24T19:40:58.347Z,1571946058.347 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-10-24T19:40:58.348Z,1571946058.348 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-10-24T19:40:58.379Z,1571946058.379 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-10-24T19:40:58.380Z,1571946058.380 [DUSBL:A.Pitch](DEBUG): Construct.
2019-10-24T19:40:58.384Z,1571946058.384 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-10-24T19:40:58.435Z,1571946058.435 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-10-24T19:40:58.443Z,1571946058.443 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</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>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-10-24T19:40:58.443Z,1571946058.443 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:40:59.339Z,1571946059.339 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-24T19:41:00.165Z,1571946060.165 [CommandLine](IMPORTANT): got command set DUSBL.TrackingUpdatePeriod 7.000000 second
2019-10-24T19:41:00.166Z,1571946060.166 [CommandLine](IMPORTANT): got command run 
2019-10-24T19:41:00.167Z,1571946060.167 [CommandLine](IMPORTANT): Running 
2019-10-24T19:41:00.270Z,1571946060.270 [Default] Stopped
2019-10-24T19:41:00.270Z,1571946060.270 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-24T19:41:00.271Z,1571946060.271 [Default:B.GoToSurface] Stopped
2019-10-24T19:41:00.271Z,1571946060.271 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-24T19:41:00.271Z,1571946060.271 [Default:CheckIn] Stopped
2019-10-24T19:41:00.271Z,1571946060.271 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T19:41:00.271Z,1571946060.271 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T19:41:00.271Z,1571946060.271 [MissionManager](IMPORTANT): Started mission DUSBL
2019-10-24T19:41:00.271Z,1571946060.271 [DUSBL] Running Loop=1
2019-10-24T19:41:00.271Z,1571946060.271 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:A.Pitch] Running Loop=1
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:C.] Running Loop=1
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:RequestRepeater] Running Loop=1
2019-10-24T19:41:00.272Z,1571946060.272 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-10-24T19:41:00.273Z,1571946060.273 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-10-24T19:41:00.273Z,1571946060.273 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:41:00.273Z,1571946060.273 [DUSBL:C.] Running Loop=1
2019-10-24T19:41:00.273Z,1571946060.273 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-24T19:41:00.274Z,1571946060.274 [DUSBL:A.Pitch] Running Loop=1
2019-10-24T19:41:01.773Z,1571946061.773 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:92.700287
2019-10-24T19:41:07.461Z,1571946067.461 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:41:07.822Z,1571946067.822 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:41:07.823Z,1571946067.823 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:41:07.823Z,1571946067.823 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 15
2019-10-24T19:41:07.823Z,1571946067.823 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:41:08.236Z,1571946068.236 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
O
2019-10-24T19:41:08.236Z,1571946068.236 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:41:08.236Z,1571946068.236 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:41:08.237Z,1571946068.237 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:41:08.681Z,1571946068.681 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:41:09.035Z,1571946069.035 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,DD7,000,0013D,189,80,80,0C,FF
2019-10-24T19:41:09.035Z,1571946069.035 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-24T19:41:09.462Z,1571946069.462 [Micromodem](INFO): Nmea in: $SNTTA,,,0.311775,,194108.94*4E

2019-10-24T19:41:14.738Z,1571946074.738 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:41:15.094Z,1571946075.094 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:41:15.095Z,1571946075.095 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:41:15.095Z,1571946075.095 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 15
2019-10-24T19:41:15.096Z,1571946075.096 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:41:15.499Z,1571946075.499 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
DD7,000,0013D,189,80,80,0C,FF
2019-10-24T19:41:15.499Z,1571946075.499 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:41:15.499Z,1571946075.499 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:41:15.500Z,1571946075.500 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:41:15.905Z,1571946075.905 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:41:16.307Z,1571946076.307 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,231,000,006B4,189,80,80,06,FF
2019-10-24T19:41:16.307Z,1571946076.307 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:41:16.379Z,1571946076.379 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 65.460007 m
2019-10-24T19:41:16.730Z,1571946076.730 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194116.20*56

2019-10-24T19:41:23.612Z,1571946083.612 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:41:23.994Z,1571946083.994 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:41:23.994Z,1571946083.994 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:41:23.994Z,1571946083.994 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 15
2019-10-24T19:41:23.994Z,1571946083.994 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:41:24.394Z,1571946084.394 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
231,000,006B4,189,80,80,06,FF
2019-10-24T19:41:24.395Z,1571946084.395 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:41:24.395Z,1571946084.395 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:41:24.397Z,1571946084.397 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:41:24.794Z,1571946084.794 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:41:25.198Z,1571946085.198 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,065,000,0020E,187,80,80,08,FF
2019-10-24T19:41:25.198Z,1571946085.198 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-24T19:41:25.644Z,1571946085.644 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194125.09*5D

2019-10-24T19:41:28.523Z,1571946088.523 [CommandLine](IMPORTANT): got command stop
2019-10-24T19:41:28.524Z,1571946088.524 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-10-24T19:41:28.938Z,1571946088.938 [MissionManager](INFO): MissionManager is completed.
2019-10-24T19:41:28.939Z,1571946088.939 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL] Stopped
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:A.Pitch] Stopped
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:B.SetSpeed] Stopped
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:C.] Stopped
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:RequestRepeater] Stopped
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-10-24T19:41:28.939Z,1571946088.939 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:41:29.289Z,1571946089.289 [MissionManager](IMPORTANT): Started mission Default
2019-10-24T19:41:29.289Z,1571946089.289 [Default] Running Loop=1
2019-10-24T19:41:29.289Z,1571946089.289 [Default](DEBUG): Aggregate::initialize Default
2019-10-24T19:41:29.289Z,1571946089.289 [Default:B.GoToSurface] Running Loop=1
2019-10-24T19:41:29.289Z,1571946089.289 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-24T19:41:29.290Z,1571946089.290 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-24T19:41:29.290Z,1571946089.290 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-24T19:41:29.290Z,1571946089.290 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-24T19:41:29.291Z,1571946089.291 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-24T19:41:29.291Z,1571946089.291 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-24T19:41:29.291Z,1571946089.291 [Default:A.Wait] Running Loop=1
2019-10-24T19:41:29.291Z,1571946089.291 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:41:37.898Z,1571946097.898 [CommandLine](IMPORTANT): got command maintain control VerticalControl.massPositionAction
2019-10-24T19:41:37.898Z,1571946097.898 [CommandLine](FAULT): Incomplete syntax. Try: help maintain
2019-10-24T19:41:42.036Z,1571946102.036 [CommandLine](IMPORTANT): got command maintain control VerticalControl.massPositionAction 3.000000 centimeter
2019-10-24T19:41:42.037Z,1571946102.037 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.massPositionAction" handled in the control thread.
2019-10-24T19:41:42.239Z,1571946102.239 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.massPositionAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-10-24T19:41:42.686Z,1571946102.686 [Default:A.Wait](INFO): Done Waiting.
2019-10-24T19:41:42.686Z,1571946102.686 [Default:A.Wait] Stopped
2019-10-24T19:41:42.686Z,1571946102.686 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:41:43.022Z,1571946103.022 [Default:CheckIn] Running Loop=1
2019-10-24T19:41:43.022Z,1571946103.022 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T19:41:43.022Z,1571946103.022 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T19:41:44.661Z,1571946104.661 [NAL9602](DEBUG): Fix Requested
2019-10-24T19:41:45.038Z,1571946105.038 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194040.00,A,3648.16199,N,12147.28242,W,0.058,0.00,241019,,,A*76
2019-10-24T19:41:45.040Z,1571946105.040 [NAL9602](INFO): GPS fix at 20191024T194040: (36.802700, -121.788040)
2019-10-24T19:41:45.069Z,1571946105.069 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T19:41:45.069Z,1571946105.069 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T19:41:45.341Z,1571946105.341 [DataOverHttps](INFO): Sending 754 bytes from file Logs/20191024T192340/Express0011.lzma
2019-10-24T19:41:47.346Z,1571946107.346 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Express0011.lzma.bak
2019-10-24T19:41:47.346Z,1571946107.346 [DataOverHttps](INFO): SBD MOMSN=11952089
2019-10-24T19:41:50.209Z,1571946110.209 [CommandLine](IMPORTANT): got command show variable detectionThreshold
2019-10-24T19:41:50.372Z,1571946110.372 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-10-24T19:42:02.715Z,1571946122.715 [CommandLine](IMPORTANT): got command failComponent
2019-10-24T19:42:02.715Z,1571946122.715 [CommandLine](IMPORTANT): Failed components:
2019-10-24T19:42:02.715Z,1571946122.715 [CommandLine](IMPORTANT): No failed Components.
2019-10-24T19:42:09.276Z,1571946129.276 [NAL9602](INFO): SBD MO Status=0, MOMSN=9750, MT Status=0, MTMSN=0
2019-10-24T19:42:09.276Z,1571946129.276 [NAL9602](INFO): No messages in MT queue
2019-10-24T19:42:09.518Z,1571946129.518 [CommandLine](IMPORTANT): got command get DUSBL_Hydroid.detectionThreshold
2019-10-24T19:42:09.519Z,1571946129.519 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold 15 count
2019-10-24T19:42:13.692Z,1571946133.692 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191024T192340/Courier0019.lzma
2019-10-24T19:42:15.332Z,1571946135.332 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.detectionThreshold 20.000000 count persist
2019-10-24T19:42:15.698Z,1571946135.698 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Courier0019.lzma.bak
2019-10-24T19:42:15.699Z,1571946135.699 [DataOverHttps](INFO): SBD MOMSN=11952131
2019-10-24T19:42:31.390Z,1571946151.390 [DataOverHttps](IMPORTANT): SBD MTMSN=20191024T194125
2019-10-24T19:42:40.017Z,1571946160.017 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-24T19:42:42.908Z,1571946162.908 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191024T192340/Express0014.lzma
2019-10-24T19:42:42.910Z,1571946162.910 [DataOverHttps](INFO): Received command:load Maintenance/DUSBL_Tracking.xml;set DUSBL.TrackingUpdatePeriod 7 second;run 
2019-10-24T19:42:42.936Z,1571946162.936 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:42:42.949Z,1571946162.949 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:42:43.035Z,1571946163.035 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-10-24T19:42:43.053Z,1571946163.053 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-10-24T19:42:43.055Z,1571946163.055 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-10-24T19:42:43.074Z,1571946163.074 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-10-24T19:42:43.075Z,1571946163.075 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-10-24T19:42:43.076Z,1571946163.076 [DUSBL:A.Pitch](DEBUG): Construct.
2019-10-24T19:42:43.110Z,1571946163.110 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-10-24T19:42:43.183Z,1571946163.183 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-10-24T19:42:43.187Z,1571946163.187 [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>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</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>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-10-24T19:42:43.187Z,1571946163.187 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-24T19:42:47.870Z,1571946167.870 [CommandLine](IMPORTANT): got command set DUSBL.TrackingUpdatePeriod 7.000000 second
2019-10-24T19:42:47.870Z,1571946167.870 [CommandLine](IMPORTANT): got command run 
2019-10-24T19:42:47.872Z,1571946167.872 [CommandLine](IMPORTANT): Running 
2019-10-24T19:42:48.120Z,1571946168.120 [Default] Stopped
2019-10-24T19:42:48.120Z,1571946168.120 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-24T19:42:48.120Z,1571946168.120 [Default:B.GoToSurface] Stopped
2019-10-24T19:42:48.120Z,1571946168.120 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-24T19:42:48.120Z,1571946168.120 [Default:CheckIn] Stopped
2019-10-24T19:42:48.121Z,1571946168.121 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T19:42:48.153Z,1571946168.153 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T19:42:48.153Z,1571946168.153 [MissionManager](IMPORTANT): Started mission DUSBL
2019-10-24T19:42:48.153Z,1571946168.153 [DUSBL] Running Loop=1
2019-10-24T19:42:48.153Z,1571946168.153 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:A.Pitch] Running Loop=1
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:C.] Running Loop=1
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:RequestRepeater] Running Loop=1
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-10-24T19:42:48.154Z,1571946168.154 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-10-24T19:42:48.155Z,1571946168.155 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:42:48.155Z,1571946168.155 [DUSBL:C.] Running Loop=1
2019-10-24T19:42:48.155Z,1571946168.155 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-24T19:42:48.155Z,1571946168.155 [DUSBL:A.Pitch] Running Loop=1
2019-10-24T19:42:48.886Z,1571946168.886 [DataOverHttps](INFO): Moved sent file to Logs/20191024T192340/Express0014.lzma.bak
2019-10-24T19:42:48.886Z,1571946168.886 [DataOverHttps](INFO): SBD MOMSN=11952136
2019-10-24T19:42:55.420Z,1571946175.420 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:42:55.754Z,1571946175.754 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:42:55.754Z,1571946175.754 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:42:55.754Z,1571946175.754 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:42:55.755Z,1571946175.755 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:42:56.158Z,1571946176.158 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
065,000,0020E,187,80,80,08,FF
2019-10-24T19:42:56.158Z,1571946176.158 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:42:56.158Z,1571946176.158 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:42:56.160Z,1571946176.160 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:42:56.574Z,1571946176.574 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:42:57.376Z,1571946177.376 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194256.86*5D

2019-10-24T19:42:59.798Z,1571946179.798 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
E,187,80,80,08,FF
2019-10-24T19:42:59.798Z,1571946179.798 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
E,187,80,80,08,FF
2019-10-24T19:42:59.798Z,1571946179.798 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:43:02.690Z,1571946182.690 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:43:03.035Z,1571946183.035 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:43:03.035Z,1571946183.035 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:43:03.035Z,1571946183.035 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:43:03.036Z,1571946183.036 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:43:03.434Z,1571946183.434 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
E,187,80,80,08,FF
2019-10-24T19:43:03.434Z,1571946183.434 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:43:03.434Z,1571946183.434 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:43:03.436Z,1571946183.436 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:43:03.838Z,1571946183.838 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:43:04.675Z,1571946184.675 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,04C,000,01BD5,185,80,80,0B,FF
2019-10-24T19:43:04.676Z,1571946184.676 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:43:04.678Z,1571946184.678 [Micromodem](INFO): Nmea in: $SNTTA,0.357183,,,,194304.14*45

2019-10-24T19:43:04.782Z,1571946184.782 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 390.000000 m
2019-10-24T19:43:11.948Z,1571946191.948 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:43:12.322Z,1571946192.322 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:43:12.322Z,1571946192.322 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:43:12.322Z,1571946192.322 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:43:12.323Z,1571946192.323 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:43:12.357Z,1571946192.357 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
04C,000,01BD5,185,80,80,0B,FF
2019-10-24T19:43:12.357Z,1571946192.357 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:43:12.357Z,1571946192.357 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:43:12.359Z,1571946192.359 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:43:12.724Z,1571946192.724 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:43:13.130Z,1571946193.130 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,082,000,0032A,186,80,80,14,FF
2019-10-24T19:43:13.130Z,1571946193.130 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:43:13.215Z,1571946193.215 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 11.100000 m
2019-10-24T19:43:13.554Z,1571946193.554 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194313.05*56

2019-10-24T19:43:20.437Z,1571946200.437 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:43:20.806Z,1571946200.806 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:43:20.806Z,1571946200.806 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:43:20.806Z,1571946200.806 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:43:20.807Z,1571946200.807 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:43:21.210Z,1571946201.210 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
082,000,0032A,186,80,80,14,FF
2019-10-24T19:43:21.210Z,1571946201.210 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:43:21.210Z,1571946201.210 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:43:21.212Z,1571946201.212 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:43:21.618Z,1571946201.618 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:43:22.424Z,1571946202.424 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194321.91*5A

2019-10-24T19:43:24.846Z,1571946204.846 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
A,186,80,80,14,FF
2019-10-24T19:43:24.846Z,1571946204.846 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
A,186,80,80,14,FF
2019-10-24T19:43:24.846Z,1571946204.846 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:43:27.728Z,1571946207.728 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:43:28.074Z,1571946208.074 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:43:28.074Z,1571946208.074 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:43:28.074Z,1571946208.074 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:43:28.074Z,1571946208.074 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:43:28.478Z,1571946208.478 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
A,186,80,80,14,FF
2019-10-24T19:43:28.478Z,1571946208.478 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:43:28.478Z,1571946208.478 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:43:28.480Z,1571946208.480 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:43:28.885Z,1571946208.885 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:43:29.694Z,1571946209.694 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,0E3,000,01B2B,187,80,80,0F,FF
2019-10-24T19:43:29.695Z,1571946209.695 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:43:29.697Z,1571946209.697 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194329.18*53

2019-10-24T19:43:29.835Z,1571946209.835 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 379.799988 m
2019-10-24T19:43:37.005Z,1571946217.005 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:43:37.366Z,1571946217.366 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:43:37.366Z,1571946217.366 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:43:37.366Z,1571946217.366 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:43:37.367Z,1571946217.367 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:43:37.778Z,1571946217.778 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
0E3,000,01B2B,187,80,80,0F,FF
2019-10-24T19:43:37.778Z,1571946217.778 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:43:37.778Z,1571946217.778 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:43:37.780Z,1571946217.780 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:43:38.181Z,1571946218.181 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:43:38.995Z,1571946218.995 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194338.48*56

2019-10-24T19:43:41.410Z,1571946221.410 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
B,187,80,80,0F,FF
2019-10-24T19:43:41.410Z,1571946221.410 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
B,187,80,80,0F,FF
2019-10-24T19:43:41.410Z,1571946221.410 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:43:42.680Z,1571946222.680 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-10-24T19:43:42.680Z,1571946222.680 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   +0,    +5,A
2019-10-24T19:43:44.278Z,1571946224.278 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:43:44.672Z,1571946224.672 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:43:44.672Z,1571946224.672 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:43:44.672Z,1571946224.672 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:43:44.673Z,1571946224.673 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:43:45.058Z,1571946225.058 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
B,187,80,80,0F,FF
2019-10-24T19:43:45.058Z,1571946225.058 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:43:45.058Z,1571946225.058 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:43:45.060Z,1571946225.060 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:43:45.453Z,1571946225.453 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:43:46.270Z,1571946226.270 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,FC8,000,01A9F,184,80,80,21,FF
2019-10-24T19:43:46.270Z,1571946226.270 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:43:46.273Z,1571946226.273 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194345.76*51

2019-10-24T19:43:46.344Z,1571946226.344 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 371.399994 m
2019-10-24T19:43:53.553Z,1571946233.553 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:43:53.939Z,1571946233.939 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:43:53.939Z,1571946233.939 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:43:53.939Z,1571946233.939 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:43:53.940Z,1571946233.940 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:43:54.338Z,1571946234.338 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
FC8,000,01A9F,184,80,80,21,FF
2019-10-24T19:43:54.338Z,1571946234.338 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:43:54.338Z,1571946234.338 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:43:54.340Z,1571946234.340 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:43:54.752Z,1571946234.752 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:43:55.548Z,1571946235.548 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,FB6,000,01AA0,184,80,80,22,FF
2019-10-24T19:43:55.549Z,1571946235.549 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:43:55.551Z,1571946235.551 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194355.04*55

2019-10-24T19:43:55.700Z,1571946235.700 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 371.459961 m
2019-10-24T19:44:02.892Z,1571946242.892 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:44:03.222Z,1571946243.222 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:44:03.222Z,1571946243.222 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:44:03.222Z,1571946243.222 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:44:03.223Z,1571946243.223 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:44:03.645Z,1571946243.645 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
FB6,000,01AA0,184,80,80,22,FF
2019-10-24T19:44:03.646Z,1571946243.646 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:44:03.646Z,1571946243.646 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:44:03.698Z,1571946243.698 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:44:04.033Z,1571946244.033 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:44:04.899Z,1571946244.899 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-10-24T19:44:05.243Z,1571946245.243 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194404.39*58

2019-10-24T19:44:07.262Z,1571946247.261 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
0,184,80,80,22,FF
2019-10-24T19:44:07.262Z,1571946247.262 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
0,184,80,80,22,FF
2019-10-24T19:44:07.262Z,1571946247.262 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:44:10.131Z,1571946250.131 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:44:10.494Z,1571946250.494 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:44:10.495Z,1571946250.495 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:44:10.495Z,1571946250.495 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:44:10.496Z,1571946250.496 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:44:10.907Z,1571946250.907 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
0,184,80,80,22,FF
2019-10-24T19:44:10.908Z,1571946250.908 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:44:10.908Z,1571946250.908 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:44:10.937Z,1571946250.937 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:44:11.309Z,1571946251.309 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:44:12.519Z,1571946252.519 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194411.69*59

2019-10-24T19:44:14.534Z,1571946254.534 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,N,80,80,63,E4
0,184,80,80,22,FF
2019-10-24T19:44:14.534Z,1571946254.534 [DUSBL_Hydroid](INFO): No reply:!U1,N,80,80,63,E4
0,184,80,80,22,FF
2019-10-24T19:44:14.535Z,1571946254.535 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-10-24T19:44:17.406Z,1571946257.406 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:44:17.770Z,1571946257.770 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:44:17.770Z,1571946257.770 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:44:17.770Z,1571946257.770 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:44:17.771Z,1571946257.771 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:44:18.170Z,1571946258.170 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
80,80,63,E4
0,184,80,80,22,FF
2019-10-24T19:44:18.170Z,1571946258.170 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:44:18.170Z,1571946258.170 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:44:18.172Z,1571946258.172 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:44:18.587Z,1571946258.587 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:44:19.386Z,1571946259.386 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,FE7,000,01AA0,183,80,80,21,FF
2019-10-24T19:44:19.387Z,1571946259.387 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:44:19.389Z,1571946259.389 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194418.87*50

2019-10-24T19:44:19.492Z,1571946259.492 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 371.459961 m
2019-10-24T19:44:24.685Z,1571946264.685 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-10-24T19:44:24.686Z,1571946264.686 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,    +8,   -29,
2019-10-24T19:44:26.705Z,1571946266.705 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-24T19:44:27.062Z,1571946267.062 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-10-24T19:44:27.062Z,1571946267.062 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-10-24T19:44:27.062Z,1571946267.062 [DUSBL_Hydroid](INFO): Arming DUSBL. detectThresh: 20
2019-10-24T19:44:27.063Z,1571946267.063 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-10-24T19:44:27.470Z,1571946267.470 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,P
FE7,000,01AA0,183,80,80,21,FF
2019-10-24T19:44:27.470Z,1571946267.470 [DUSBL_Hydroid](INFO): Command Ack
2019-10-24T19:44:27.470Z,1571946267.470 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-10-24T19:44:27.472Z,1571946267.472 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-24T19:44:27.881Z,1571946267.881 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-24T19:44:28.268Z,1571946268.268 [DUSBL_Hydroid](INFO): DUSBL response received:!U1,R,082,000,00329,186,80,80,12,FF
2019-10-24T19:44:28.269Z,1571946268.269 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-10-24T19:44:28.389Z,1571946268.389 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 11.039997 m
2019-10-24T19:44:28.694Z,1571946268.694 [Micromodem](INFO): Nmea in: $SNTTA,,,,,194428.17*5A

2019-10-24T19:44:29.428Z,1571946269.428 [CommandLine](IMPORTANT): got command stop
2019-10-24T19:44:29.428Z,1571946269.428 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-10-24T19:44:29.554Z,1571946269.554 [MissionManager](INFO): MissionManager is completed.
2019-10-24T19:44:29.555Z,1571946269.555 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL] Stopped
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:A.Pitch] Stopped
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:B.SetSpeed] Stopped
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:C.] Stopped
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:RequestRepeater] Stopped
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-10-24T19:44:29.555Z,1571946269.555 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:44:29.996Z,1571946269.996 [MissionManager](IMPORTANT): Started mission Default
2019-10-24T19:44:29.996Z,1571946269.996 [Default] Running Loop=1
2019-10-24T19:44:29.996Z,1571946269.996 [Default](DEBUG): Aggregate::initialize Default
2019-10-24T19:44:29.996Z,1571946269.996 [Default:B.GoToSurface] Running Loop=1
2019-10-24T19:44:29.996Z,1571946269.996 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-24T19:44:29.997Z,1571946269.997 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-24T19:44:29.997Z,1571946269.997 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-24T19:44:29.997Z,1571946269.997 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-24T19:44:29.998Z,1571946269.998 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-24T19:44:29.998Z,1571946269.998 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-24T19:44:29.999Z,1571946269.999 [Default:A.Wait] Running Loop=1
2019-10-24T19:44:29.999Z,1571946269.999 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T19:44:40.523Z,1571946280.523 [CommandLine](IMPORTANT): got command restart application
2019-10-24T19:44:41.525Z,1571946281.525 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:41.526Z,1571946281.526 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.641Z,1571946281.641 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-10-24T19:44:41.642Z,1571946281.642 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.643Z,1571946281.643 [CommandLine](INFO): Join timeout helper Thread ID is 1330
2019-10-24T19:44:41.652Z,1571946281.652 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-10-24T19:44:41.652Z,1571946281.652 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.658Z,1571946281.658 [NavChartDb](INFO): Join timeout helper Thread ID is 1331
2019-10-24T19:44:41.737Z,1571946281.737 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:41.737Z,1571946281.737 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.738Z,1571946281.738 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-10-24T19:44:41.738Z,1571946281.738 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.738Z,1571946281.738 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1332
2019-10-24T19:44:41.765Z,1571946281.765 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:41.765Z,1571946281.765 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-10-24T19:44:41.766Z,1571946281.766 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.781Z,1571946281.781 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-10-24T19:44:41.781Z,1571946281.781 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.781Z,1571946281.781 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1333
2019-10-24T19:44:41.841Z,1571946281.841 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:41.841Z,1571946281.841 [CTD_NeilBrown](INFO): Powering down
2019-10-24T19:44:41.853Z,1571946281.853 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.857Z,1571946281.857 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-10-24T19:44:41.857Z,1571946281.857 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:41.857Z,1571946281.857 [Radio_Surface](INFO): Join timeout helper Thread ID is 1334
2019-10-24T19:44:41.977Z,1571946281.977 [Radio_Surface](INFO): Powering down
2019-10-24T19:44:41.978Z,1571946281.978 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:41.978Z,1571946281.978 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:42.004Z,1571946282.004 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-10-24T19:44:42.004Z,1571946282.004 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:42.004Z,1571946282.004 [DataOverHttps](INFO): Join timeout helper Thread ID is 1335
2019-10-24T19:44:43.271Z,1571946283.271 [Default:A.Wait](INFO): Done Waiting.
2019-10-24T19:44:43.271Z,1571946283.271 [Default:A.Wait] Stopped
2019-10-24T19:44:43.271Z,1571946283.271 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T19:44:43.704Z,1571946283.704 [Default:CheckIn] Running Loop=1
2019-10-24T19:44:43.704Z,1571946283.704 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T19:44:43.704Z,1571946283.704 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T19:44:45.257Z,1571946285.257 [NAL9602](DEBUG): Fix Requested
2019-10-24T19:44:45.703Z,1571946285.703 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194341.00,A,3648.16549,N,12147.28557,W,0.058,146.33,241019,,,A*7D
2019-10-24T19:44:45.713Z,1571946285.713 [NAL9602](INFO): GPS fix at 20191024T194341: (36.802758, -121.788093)
2019-10-24T19:44:45.814Z,1571946285.814 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T19:44:45.814Z,1571946285.814 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T19:44:46.182Z,1571946286.182 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:46.194Z,1571946286.194 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:46.206Z,1571946286.206 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-10-24T19:44:46.206Z,1571946286.206 [logger ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:46.206Z,1571946286.206 [logger](INFO): Join timeout helper Thread ID is 1336
2019-10-24T19:44:46.249Z,1571946286.249 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:46.250Z,1571946286.250 [logger ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:46.266Z,1571946286.266 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-10-24T19:44:46.266Z,1571946286.266 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:46.266Z,1571946286.266 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-10-24T19:44:46.266Z,1571946286.266 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:46.267Z,1571946286.267 [controlThread](INFO): Join timeout helper Thread ID is 1337
2019-10-24T19:44:46.544Z,1571946286.544 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T19:44:46.545Z,1571946286.545 [controlThread](DEBUG): Uninitializing ControlThread
2019-10-24T19:44:46.545Z,1571946286.545 [AHRS_M2](INFO): Powering down
2019-10-24T19:44:46.618Z,1571946286.618 [DUSBL_Hydroid](INFO): Powering down
2019-10-24T19:44:46.689Z,1571946286.689 [Micromodem](INFO): Powering down
2019-10-24T19:44:46.785Z,1571946286.785 [NAL9602](INFO): Powering down
2019-10-24T19:44:46.857Z,1571946286.857 [RDI_Pathfinder](INFO): Powering down
2019-10-24T19:44:46.859Z,1571946286.859 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-10-24T19:44:46.860Z,1571946286.860 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-10-24T19:44:46.860Z,1571946286.860 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-10-24T19:44:46.861Z,1571946286.861 [MissionManager](INFO): Uninitializing Mission Default
2019-10-24T19:44:46.861Z,1571946286.861 [Default] Stopped
2019-10-24T19:44:46.862Z,1571946286.862 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-24T19:44:46.862Z,1571946286.862 [Default:B.GoToSurface] Stopped
2019-10-24T19:44:46.862Z,1571946286.862 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-24T19:44:46.862Z,1571946286.862 [Default:CheckIn] Stopped
2019-10-24T19:44:46.862Z,1571946286.862 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T19:44:46.862Z,1571946286.862 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T19:44:46.864Z,1571946286.864 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-10-24T19:44:46.864Z,1571946286.864 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-10-24T19:44:46.865Z,1571946286.865 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-10-24T19:44:46.865Z,1571946286.865 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-10-24T19:44:46.866Z,1571946286.866 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-10-24T19:44:46.866Z,1571946286.866 [BuoyancyServo](INFO): Powering down
2019-10-24T19:44:46.877Z,1571946286.877 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-10-24T19:44:46.877Z,1571946286.877 [ElevatorServo](INFO): Powering down
2019-10-24T19:44:46.878Z,1571946286.878 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-10-24T19:44:46.878Z,1571946286.878 [MassServo](INFO): Powering down
2019-10-24T19:44:46.879Z,1571946286.879 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-10-24T19:44:46.879Z,1571946286.879 [RudderServo](INFO): Powering down
2019-10-24T19:44:46.880Z,1571946286.880 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-10-24T19:44:46.880Z,1571946286.880 [ThrusterServo](INFO): Powering down
2019-10-24T19:44:46.881Z,1571946286.881 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-10-24T19:44:46.881Z,1571946286.881 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-10-24T19:44:46.882Z,1571946286.882 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-10-24T19:44:46.882Z,1571946286.882 [CBIT](DEBUG): Powering off loads.
2019-10-24T19:44:46.893Z,1571946286.893 [CBIT](DEBUG): Disabling WDT.
2019-10-24T19:44:46.905Z,1571946286.905 [CBIT](DEBUG): Opening all GF detection circuits.
2019-10-24T19:44:46.906Z,1571946286.906 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:46.971Z,1571946286.971 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:46.980Z,1571946286.980 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:47.094Z,1571946287.094 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:47.096Z,1571946287.096 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:47.193Z,1571946287.193 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-24T19:44:47.351Z,1571946287.351 [logger ThreadHandler](INFO): Thread cancelled.