2019-05-07T16:19:55.007Z,1557245995.007 [Supervisor](DEBUG): Initializing supervisor. 2019-05-07T16:19:55.010Z,1557245995.010 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-05-07T16:19:55.010Z,1557245995.010 [SyncHandler](INFO): Protected caller Thread ID is 3636 2019-05-07T16:19:55.011Z,1557245995.011 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-05-07T16:19:55.012Z,1557245995.012 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-05-07T16:19:55.012Z,1557245995.012 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3637 2019-05-07T16:19:55.015Z,1557245995.015 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-05-07T16:19:55.027Z,1557245995.027 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-05-07T16:19:55.028Z,1557245995.028 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-05-07T16:19:55.029Z,1557245995.029 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3638 2019-05-07T16:19:55.030Z,1557245995.030 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-05-07T16:19:55.031Z,1557245995.031 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-05-07T16:19:55.031Z,1557245995.031 [logger ThreadHandler](INFO): Protected caller Thread ID is 3639 2019-05-07T16:19:55.033Z,1557245995.033 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-05-07T16:19:55.033Z,1557245995.033 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-05-07T16:19:55.035Z,1557245995.035 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-05-07T16:19:55.456Z,1557245995.456 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-05-07T16:19:55.456Z,1557245995.456 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-05-07T16:19:55.555Z,1557245995.555 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-05-07T16:19:55.555Z,1557245995.555 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-05-07T16:19:55.898Z,1557245995.898 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-05-07T16:19:55.899Z,1557245995.899 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-05-07T16:19:56.042Z,1557245996.042 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-05-07T16:19:56.042Z,1557245996.042 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-05-07T16:19:56.410Z,1557245996.410 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-05-07T16:19:56.411Z,1557245996.411 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-05-07T16:19:56.865Z,1557245996.865 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-05-07T16:19:56.865Z,1557245996.865 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-05-07T16:19:57.076Z,1557245997.076 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-05-07T16:19:57.077Z,1557245997.077 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-05-07T16:19:57.224Z,1557245997.224 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-05-07T16:19:57.224Z,1557245997.224 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-05-07T16:19:57.419Z,1557245997.419 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-05-07T16:19:57.420Z,1557245997.420 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-05-07T16:19:57.516Z,1557245997.516 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-05-07T16:19:57.517Z,1557245997.517 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-05-07T16:19:57.839Z,1557245997.839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-05-07T16:19:57.840Z,1557245997.840 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-05-07T16:19:57.921Z,1557245997.921 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-05-07T16:19:58.027Z,1557245998.027 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-05-07T16:19:58.028Z,1557245998.028 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-05-07T16:19:58.605Z,1557245998.605 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-05-07T16:19:58.606Z,1557245998.606 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-05-07T16:19:58.998Z,1557245998.998 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-05-07T16:19:59.000Z,1557245999.000 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/ 2019-05-07T16:19:59.001Z,1557245999.001 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg 2019-05-07T16:19:59.210Z,1557245999.210 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg 2019-05-07T16:19:59.311Z,1557245999.311 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg 2019-05-07T16:19:59.410Z,1557245999.410 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg 2019-05-07T16:19:59.636Z,1557245999.636 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-05-07T16:19:59.637Z,1557245999.637 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg 2019-05-07T16:19:59.722Z,1557245999.722 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg 2019-05-07T16:19:59.816Z,1557245999.816 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg 2019-05-07T16:19:59.913Z,1557245999.913 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg 2019-05-07T16:19:59.997Z,1557245999.997 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg 2019-05-07T16:20:00.105Z,1557246000.105 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg 2019-05-07T16:20:00.277Z,1557246000.277 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg 2019-05-07T16:20:00.410Z,1557246000.410 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/ 2019-05-07T16:20:00.410Z,1557246000.410 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-05-07T16:20:00.423Z,1557246000.423 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-05-07T16:20:00.802Z,1557246000.802 [AHRS_M2] Loaded 2019-05-07T16:20:00.802Z,1557246000.802 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-05-07T16:20:00.875Z,1557246000.875 [DataOverHttps] Loaded 2019-05-07T16:20:00.875Z,1557246000.875 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-05-07T16:20:00.876Z,1557246000.876 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0 2019-05-07T16:20:00.877Z,1557246000.877 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3718 2019-05-07T16:20:00.890Z,1557246000.890 [Depth_Keller] Loaded 2019-05-07T16:20:00.890Z,1557246000.890 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-05-07T16:20:00.895Z,1557246000.895 [DropWeight] Loaded 2019-05-07T16:20:00.895Z,1557246000.895 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-05-07T16:20:00.952Z,1557246000.952 [DUSBL_Hydroid] Loaded 2019-05-07T16:20:00.952Z,1557246000.952 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread. 2019-05-07T16:20:00.992Z,1557246000.992 [Micromodem] Loaded 2019-05-07T16:20:00.992Z,1557246000.992 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2019-05-07T16:20:01.089Z,1557246001.089 [NAL9602] Loaded 2019-05-07T16:20:01.089Z,1557246001.089 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-05-07T16:20:01.105Z,1557246001.105 [Onboard] Loaded 2019-05-07T16:20:01.105Z,1557246001.105 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-05-07T16:20:01.111Z,1557246001.111 [PowerOnly] Loaded 2019-05-07T16:20:01.111Z,1557246001.111 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2019-05-07T16:20:01.118Z,1557246001.118 [Radio_Surface] Loaded 2019-05-07T16:20:01.118Z,1557246001.118 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-05-07T16:20:01.119Z,1557246001.119 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0 2019-05-07T16:20:01.119Z,1557246001.119 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3719 2019-05-07T16:20:01.163Z,1557246001.163 [RDI_Pathfinder] Loaded 2019-05-07T16:20:01.163Z,1557246001.163 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2019-05-07T16:20:02.934Z,1557246002.934 [BPC1] Loaded 2019-05-07T16:20:02.934Z,1557246002.934 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-05-07T16:20:02.935Z,1557246002.935 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-05-07T16:20:02.935Z,1557246002.935 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-05-07T16:20:02.948Z,1557246002.948 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-05-07T16:20:02.949Z,1557246002.949 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-05-07T16:20:03.053Z,1557246003.053 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-05-07T16:20:03.053Z,1557246003.053 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-05-07T16:20:03.073Z,1557246003.073 [NavChart] Loaded 2019-05-07T16:20:03.074Z,1557246003.074 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-05-07T16:20:03.078Z,1557246003.078 [UniversalFixResidualReporter] Loaded 2019-05-07T16:20:03.078Z,1557246003.078 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-05-07T16:20:03.078Z,1557246003.078 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-05-07T16:20:03.079Z,1557246003.079 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-05-07T16:20:03.186Z,1557246003.186 [BuoyancyServo] Loaded 2019-05-07T16:20:03.186Z,1557246003.186 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-05-07T16:20:03.202Z,1557246003.202 [ElevatorServo] Loaded 2019-05-07T16:20:03.202Z,1557246003.202 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-05-07T16:20:03.217Z,1557246003.217 [MassServo] Loaded 2019-05-07T16:20:03.217Z,1557246003.217 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-05-07T16:20:03.232Z,1557246003.232 [RudderServo] Loaded 2019-05-07T16:20:03.233Z,1557246003.233 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-05-07T16:20:03.247Z,1557246003.247 [ThrusterServo] Loaded 2019-05-07T16:20:03.247Z,1557246003.247 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-05-07T16:20:03.248Z,1557246003.248 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-05-07T16:20:03.248Z,1557246003.248 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-05-07T16:20:03.491Z,1557246003.491 [CTD_NeilBrown] Loaded 2019-05-07T16:20:03.491Z,1557246003.491 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-05-07T16:20:03.492Z,1557246003.492 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0 2019-05-07T16:20:03.493Z,1557246003.493 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3720 2019-05-07T16:20:03.537Z,1557246003.537 [WetLabsSeaOWL_UV_A] Loaded 2019-05-07T16:20:03.537Z,1557246003.537 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2019-05-07T16:20:03.538Z,1557246003.538 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0 2019-05-07T16:20:03.538Z,1557246003.538 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3721 2019-05-07T16:20:03.539Z,1557246003.539 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-05-07T16:20:03.540Z,1557246003.540 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-05-07T16:20:03.825Z,1557246003.825 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-05-07T16:20:03.826Z,1557246003.826 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-05-07T16:20:03.865Z,1557246003.865 [DepthRateCalculator] Loaded 2019-05-07T16:20:03.866Z,1557246003.866 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-05-07T16:20:03.871Z,1557246003.871 [PitchRateCalculator] Loaded 2019-05-07T16:20:03.872Z,1557246003.872 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-05-07T16:20:03.884Z,1557246003.884 [SpeedCalculator] Loaded 2019-05-07T16:20:03.884Z,1557246003.884 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-05-07T16:20:03.905Z,1557246003.905 [TempGradientCalculator] Loaded 2019-05-07T16:20:03.905Z,1557246003.905 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-05-07T16:20:03.911Z,1557246003.911 [YawRateCalculator] Loaded 2019-05-07T16:20:03.911Z,1557246003.911 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-05-07T16:20:03.951Z,1557246003.951 [ElevatorOffsetCalculator] Loaded 2019-05-07T16:20:03.951Z,1557246003.951 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-05-07T16:20:03.952Z,1557246003.952 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-05-07T16:20:03.952Z,1557246003.952 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-05-07T16:20:04.086Z,1557246004.086 [SBIT](DEBUG): Construct Startup Built In Test. 2019-05-07T16:20:04.107Z,1557246004.107 [SBIT] Loaded 2019-05-07T16:20:04.108Z,1557246004.108 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-05-07T16:20:04.109Z,1557246004.109 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-05-07T16:20:04.121Z,1557246004.121 [IBIT] Loaded 2019-05-07T16:20:04.121Z,1557246004.121 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-05-07T16:20:04.124Z,1557246004.124 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-05-07T16:20:04.261Z,1557246004.261 [CBIT] Loaded 2019-05-07T16:20:04.262Z,1557246004.262 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-05-07T16:20:04.262Z,1557246004.262 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-05-07T16:20:04.263Z,1557246004.263 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-05-07T16:20:04.332Z,1557246004.332 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-05-07T16:20:04.333Z,1557246004.333 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-05-07T16:20:04.430Z,1557246004.430 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-05-07T16:20:04.430Z,1557246004.430 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-05-07T16:20:04.496Z,1557246004.496 [VerticalControl](DEBUG): Construct VerticalControl. 2019-05-07T16:20:04.579Z,1557246004.579 [VerticalControl] Loaded 2019-05-07T16:20:04.579Z,1557246004.579 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-05-07T16:20:04.580Z,1557246004.580 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-05-07T16:20:04.638Z,1557246004.638 [HorizontalControl] Loaded 2019-05-07T16:20:04.638Z,1557246004.638 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-05-07T16:20:04.639Z,1557246004.639 [SpeedControl](DEBUG): Construct SpeedControl. 2019-05-07T16:20:04.640Z,1557246004.640 [SpeedControl] Loaded 2019-05-07T16:20:04.641Z,1557246004.641 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-05-07T16:20:04.641Z,1557246004.641 [LoopControl](DEBUG): Construct LoopControl. 2019-05-07T16:20:04.642Z,1557246004.642 [LoopControl] Loaded 2019-05-07T16:20:04.642Z,1557246004.642 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-05-07T16:20:04.643Z,1557246004.643 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-05-07T16:20:04.643Z,1557246004.643 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-05-07T16:20:04.669Z,1557246004.669 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-05-07T16:20:04.673Z,1557246004.673 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-05-07T16:20:04.674Z,1557246004.674 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-05-07T16:20:04.681Z,1557246004.681 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-05-07T16:20:04.682Z,1557246004.682 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0 2019-05-07T16:20:04.682Z,1557246004.682 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3722 2019-05-07T16:20:04.687Z,1557246004.687 [Supervisor](INFO): Main Thread ID is 802 2019-05-07T16:20:04.687Z,1557246004.687 [Supervisor](DEBUG): Running supervisor. 2019-05-07T16:20:04.687Z,1557246004.687 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3723 2019-05-07T16:20:04.690Z,1557246004.690 [controlThread ThreadHandler](INFO): Handler Thread ID is 3724 2019-05-07T16:20:04.690Z,1557246004.690 [controlThread](DEBUG): Initializing ControlThread 2019-05-07T16:20:04.698Z,1557246004.698 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-05-07T16:20:04.699Z,1557246004.699 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-05-07T16:20:04.700Z,1557246004.700 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-05-07T16:20:04.700Z,1557246004.700 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-05-07T16:20:04.700Z,1557246004.700 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-05-07T16:20:04.700Z,1557246004.700 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-05-07T16:20:04.701Z,1557246004.701 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-05-07T16:20:04.701Z,1557246004.701 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-05-07T16:20:04.702Z,1557246004.702 [SBIT](INFO): Initialize SBIT Component. 2019-05-07T16:20:04.702Z,1557246004.702 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b 2019-05-07T16:20:04.702Z,1557246004.702 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f 2019-05-07T16:20:04.703Z,1557246004.703 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-05-07T16:20:04.704Z,1557246004.704 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 2019-05-07T16:20:04.705Z,1557246004.705 [SBIT](INFO): Beginning SBIT in 44.000000 seconds. 2019-05-07T16:20:04.706Z,1557246004.706 [IBIT](INFO): Initialize IBIT Component. 2019-05-07T16:20:04.706Z,1557246004.706 [CBIT](DEBUG): Initialize CBIT Component. 2019-05-07T16:20:04.707Z,1557246004.707 [logger ThreadHandler](INFO): Handler Thread ID is 3725 2019-05-07T16:20:04.718Z,1557246004.718 [CBIT](DEBUG): Initialized mux pins. 2019-05-07T16:20:04.718Z,1557246004.718 [CBIT](DEBUG): Initializing the watchdog timer. 2019-05-07T16:20:04.727Z,1557246004.727 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3726 2019-05-07T16:20:04.728Z,1557246004.728 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-05-07T16:20:04.739Z,1557246004.739 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3727 2019-05-07T16:20:04.742Z,1557246004.742 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-05-07T16:20:04.742Z,1557246004.742 [CBIT](DEBUG): Initializing heartbeat. 2019-05-07T16:20:04.759Z,1557246004.759 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3728 2019-05-07T16:20:04.759Z,1557246004.759 [CTD_NeilBrown](INFO): Powering down 2019-05-07T16:20:04.788Z,1557246004.788 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3729 2019-05-07T16:20:04.788Z,1557246004.788 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-05-07T16:20:04.814Z,1557246004.814 [CBIT](DEBUG): Deactivating GF circuits. 2019-05-07T16:20:04.814Z,1557246004.814 [CBIT](DEBUG): Deactivating emergency mode. 2019-05-07T16:20:04.827Z,1557246004.827 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3730 2019-05-07T16:20:04.830Z,1557246004.830 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-05-07T16:20:04.830Z,1557246004.830 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-05-07T16:20:04.830Z,1557246004.830 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-05-07T16:20:04.830Z,1557246004.830 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-05-07T16:20:04.831Z,1557246004.831 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-05-07T16:20:04.831Z,1557246004.831 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-05-07T16:20:04.831Z,1557246004.831 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-05-07T16:20:04.831Z,1557246004.831 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-05-07T16:20:04.831Z,1557246004.831 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-05-07T16:20:04.832Z,1557246004.832 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-05-07T16:20:04.832Z,1557246004.832 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-05-07T16:20:04.832Z,1557246004.832 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-05-07T16:20:04.832Z,1557246004.832 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-05-07T16:20:04.832Z,1557246004.832 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-05-07T16:20:04.832Z,1557246004.832 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-05-07T16:20:04.833Z,1557246004.833 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-05-07T16:20:04.850Z,1557246004.850 [CBIT](DEBUG): Backplane powered. 2019-05-07T16:20:04.851Z,1557246004.851 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-05-07T16:20:04.852Z,1557246004.852 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-05-07T16:20:04.853Z,1557246004.853 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-05-07T16:20:04.853Z,1557246004.853 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-05-07T16:20:04.854Z,1557246004.854 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-05-07T16:20:04.864Z,1557246004.864 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-07T16:20:04.887Z,1557246004.887 [MissionManager](DEBUG): 2019-05-07T16:20:04.887Z,1557246004.887 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-05-07T16:20:04.958Z,1557246004.958 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-05-07T16:20:04.971Z,1557246004.971 [Default:A.Wait](DEBUG): Construct Wait. 2019-05-07T16:20:04.973Z,1557246004.973 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-07T16:20:04.999Z,1557246004.999 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-05-07T16:20:05.002Z,1557246005.002 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-05-07T16:20:05.023Z,1557246005.023 [Default:E.Execute](DEBUG): Construct Execute. 2019-05-07T16:20:05.055Z,1557246005.055 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2019-05-07T16:20:05.060Z,1557246005.060 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-05-07T16:20:05.073Z,1557246005.073 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-05-07T16:20:05.132Z,1557246005.132 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar 2019-05-07T16:20:05.133Z,1557246005.133 [DUSBL_Hydroid](INFO): Powering up 2019-05-07T16:20:05.133Z,1557246005.133 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid. 2019-05-07T16:20:05.142Z,1557246005.142 [Radio_Surface](INFO): Powering up 2019-05-07T16:20:05.199Z,1557246005.199 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-05-07T16:20:05.217Z,1557246005.217 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-05-07T16:20:05.223Z,1557246005.223 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-05-07T16:20:05.224Z,1557246005.224 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-05-07T16:20:05.231Z,1557246005.231 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-05-07T16:20:05.231Z,1557246005.231 [MassServo](DEBUG): Initializing EZServoServo. 2019-05-07T16:20:05.239Z,1557246005.239 [MassServo](DEBUG): Initializing MassServo. 2019-05-07T16:20:05.239Z,1557246005.239 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-07T16:20:05.255Z,1557246005.255 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-07T16:20:05.256Z,1557246005.256 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-05-07T16:20:05.271Z,1557246005.271 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-05-07T16:20:05.484Z,1557246005.484 [Micromodem](INFO): Powering up 2019-05-07T16:20:05.485Z,1557246005.485 [Micromodem](DEBUG): Initializing Micromodem. 2019-05-07T16:20:05.518Z,1557246005.518 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-05-07T16:20:06.202Z,1557246006.202 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-05-07T16:20:06.203Z,1557246006.203 [RudderServo](FAULT): Rudder failed to initialize 2019-05-07T16:20:06.203Z,1557246006.203 [RudderServo] Communications Fault, FailCount= 1 2019-05-07T16:20:06.203Z,1557246006.203 [RudderServo](ERROR): Communications Fault 2019-05-07T16:20:06.314Z,1557246006.314 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-05-07T16:20:06.471Z,1557246006.471 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-05-07T16:20:06.471Z,1557246006.471 [RudderServo](INFO): Powering down 2019-05-07T16:20:07.159Z,1557246007.159 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-07T16:20:07.279Z,1557246007.279 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-07T16:20:07.283Z,1557246007.283 [CBIT](INFO): Clearing failed state for component RudderServo 2019-05-07T16:20:07.284Z,1557246007.284 [RudderServo] No Fault, FailCount= 1 2019-05-07T16:20:18.495Z,1557246018.495 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-05-07T16:20:21.704Z,1557246021.704 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33 2019-05-07T16:20:23.333Z,1557246023.333 [DUSBL_Hydroid](INFO): DUSBL Version:O 2019-05-07T16:20:31.404Z,1557246031.404 [NAL9602](INFO): Powering up NAL9602 2019-05-07T16:20:36.693Z,1557246036.693 [RDI_Pathfinder](ERROR): only read 1 of 4 data items 2019-05-07T16:20:36.694Z,1557246036.694 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768-32768,V 2019-05-07T16:20:40.708Z,1557246040.708 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-05-07T16:20:40.708Z,1557246040.708 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19050709282491,35.0, -0.1, 0.0,1448.9A, 0.00, 0.00, 0.00, 0.00, 0.00 2019-05-07T16:20:42.339Z,1557246042.339 [NAL9602](INFO): NAL9602 initialized 2019-05-07T16:20:43.126Z,1557246043.126 [NAL9602](DEBUG): Fix Requested 2019-05-07T16:20:45.956Z,1557246045.956 [Micromodem](ERROR): Response from modem unexpected: $CADQF,191,1*59 2019-05-07T16:20:46.345Z,1557246046.345 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21 2019-05-07T16:20:46.753Z,1557246046.753 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507162043.838560,05,128,15,0090,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,191,0.00,-999,9760,4000*55 2019-05-07T16:20:49.216Z,1557246049.216 [SBIT](IMPORTANT): Beginning Startup BIT 2019-05-07T16:20:49.225Z,1557246049.225 [CBIT](IMPORTANT): Beginning ground fault scan 2019-05-07T16:20:59.967Z,1557246059.967 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.023167 CHAN A1 (24V): -0.026818 CHAN A2 (12V): -0.006546 CHAN A3 (5V): -0.002078 CHAN B0 (3.3V): 0.000102 CHAN B1 (3.15aV): 0.000005 CHAN B2 (3.15bV): 0.000187 CHAN B3 (GND): 0.001706 OPEN: 0.006297 Full Scale Calc: 4.765 mA, -1.589 mA 2019-05-07T16:21:08.060Z,1557246068.060 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-05-07T16:21:08.060Z,1557246068.060 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19050709285191,35.0, -0.1, 0.0,1448.RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-05-07T16:21:34.075Z,1557246094.075 [CommandLine](IMPORTANT): got command show stack 2019-05-07T16:21:34.075Z,1557246094.075 [CommandLine](IMPORTANT): Behavior Stack: 2019-05-07T16:21:34.075Z,1557246094.075 [MissionManager](IMPORTANT): Mission loaded, but not running. 2019-05-07T16:21:43.365Z,1557246103.365 [SBIT](IMPORTANT): SBIT PASSED 2019-05-07T16:21:43.401Z,1557246103.401 [CommandLine](IMPORTANT): got command configSet list 2019-05-07T16:21:43.401Z,1557246103.401 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-05-07T16:21:43.402Z,1557246103.402 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter; 2019-05-07T16:21:43.403Z,1557246103.403 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-05-07T16:21:43.404Z,1557246103.404 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter; 2019-05-07T16:21:43.404Z,1557246103.404 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter; 2019-05-07T16:21:43.728Z,1557246103.728 [MissionManager](IMPORTANT): Started mission Startup 2019-05-07T16:21:43.728Z,1557246103.728 [Startup] Running Loop=1 2019-05-07T16:21:43.728Z,1557246103.728 [Startup](DEBUG): Aggregate::initialize Startup 2019-05-07T16:21:43.728Z,1557246103.728 [Startup:A.GoToSurface] Running Loop=1 2019-05-07T16:21:43.728Z,1557246103.728 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-07T16:21:43.729Z,1557246103.729 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-07T16:21:43.729Z,1557246103.729 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-07T16:21:43.730Z,1557246103.730 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-07T16:21:43.731Z,1557246103.731 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-07T16:21:43.731Z,1557246103.731 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-07T16:21:43.733Z,1557246103.733 [Startup:StartupSatComms] Running Loop=1 2019-05-07T16:21:43.733Z,1557246103.733 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-05-07T16:21:43.733Z,1557246103.733 [Startup:StartupSatComms:A] Running Loop=1 2019-05-07T16:21:44.124Z,1557246104.124 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-05-07T16:22:31.076Z,1557246151.076 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004902 2019-05-07T16:22:41.288Z,1557246161.288 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2019-05-07T16:22:43.919Z,1557246163.919 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-07T16:21:43.7Z 2019-05-07T16:22:43.920Z,1557246163.920 [Startup:StartupSatComms:A] Stopped 2019-05-07T16:22:43.920Z,1557246163.920 [Startup:StartupSatComms:B] Running Loop=1 2019-05-07T16:22:44.320Z,1557246164.320 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-07T16:22:44.735Z,1557246164.735 [CommandLine](IMPORTANT): got command show variable range 2019-05-07T16:22:44.737Z,1557246164.737 [CommandLine](IMPORTANT): acoustic_contact_range (unknown) 2019-05-07T16:22:44.893Z,1557246164.893 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter) 2019-05-07T16:22:44.894Z,1557246164.894 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter) 2019-05-07T16:22:44.937Z,1557246164.937 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter) 2019-05-07T16:22:44.939Z,1557246164.939 [CommandLine](IMPORTANT): Micromodem.range_request (count) 2019-05-07T16:22:44.939Z,1557246164.939 [CommandLine](IMPORTANT): Micromodem.range (meter) 2019-05-07T16:22:44.942Z,1557246164.942 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter) 2019-05-07T16:22:44.943Z,1557246164.943 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter) 2019-05-07T16:22:44.943Z,1557246164.943 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter) 2019-05-07T16:22:44.943Z,1557246164.943 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter) 2019-05-07T16:22:49.646Z,1557246169.646 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20190507T161209/Courier0004.lzma 2019-05-07T16:22:50.452Z,1557246170.452 [DataOverHttps](INFO): Moved sent file to Logs/20190507T161209/Courier0004.lzma.bak 2019-05-07T16:22:50.452Z,1557246170.452 [DataOverHttps](INFO): SBD MOMSN=10955610 2019-05-07T16:22:50.788Z,1557246170.788 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range 2019-05-07T16:23:01.712Z,1557246181.712 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file). 2019-05-07T16:23:02.231Z,1557246182.231 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2019-05-07T16:23:02.535Z,1557246182.535 [Startup:StartupSatComms:B] Stopped 2019-05-07T16:23:02.535Z,1557246182.535 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-05-07T16:23:02.536Z,1557246182.536 [Startup:StartupSatComms] Stopped 2019-05-07T16:23:02.536Z,1557246182.536 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-05-07T16:23:02.536Z,1557246182.536 [Startup](INFO): Completed Startup 2019-05-07T16:23:02.537Z,1557246182.537 [MissionManager](INFO): Startup is completed. 2019-05-07T16:23:02.537Z,1557246182.537 [MissionManager](INFO): Uninitializing Mission Startup 2019-05-07T16:23:02.537Z,1557246182.537 [Startup] Stopped 2019-05-07T16:23:02.537Z,1557246182.537 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-05-07T16:23:02.537Z,1557246182.537 [Startup:A.GoToSurface] Stopped 2019-05-07T16:23:02.537Z,1557246182.537 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-07T16:23:02.923Z,1557246182.923 [MissionManager](IMPORTANT): Started mission Default 2019-05-07T16:23:02.924Z,1557246182.924 [Default] Running Loop=1 2019-05-07T16:23:02.924Z,1557246182.924 [Default](DEBUG): Aggregate::initialize Default 2019-05-07T16:23:02.924Z,1557246182.924 [Default:B.GoToSurface] Running Loop=1 2019-05-07T16:23:02.924Z,1557246182.924 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-07T16:23:02.924Z,1557246182.924 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-07T16:23:02.924Z,1557246182.924 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-07T16:23:02.925Z,1557246182.925 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-07T16:23:02.925Z,1557246182.925 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-07T16:23:02.925Z,1557246182.925 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-07T16:23:02.926Z,1557246182.926 [Default:A.Wait] Running Loop=1 2019-05-07T16:23:02.926Z,1557246182.926 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:23:04.919Z,1557246184.919 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-05-07T16:23:04.919Z,1557246184.919 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-07T16:23:04.933Z,1557246184.933 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-07T16:23:05.380Z,1557246185.380 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-07T16:23:05.380Z,1557246185.380 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-05-07T16:23:05.386Z,1557246185.386 [DataOverHttps](INFO): Sending 1188 bytes from file Logs/20190507T161209/Express0005.lzma 2019-05-07T16:23:06.188Z,1557246186.188 [DataOverHttps](INFO): Moved sent file to Logs/20190507T161209/Express0005.lzma.bak 2019-05-07T16:23:06.188Z,1557246186.188 [DataOverHttps](INFO): SBD MOMSN=10955612 2019-05-07T16:23:07.280Z,1557246187.280 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml 2019-05-07T16:23:07.280Z,1557246187.280 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml 2019-05-07T16:23:07.333Z,1557246187.333 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min 2019-05-07T16:23:07.349Z,1557246187.349 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count 2019-05-07T16:23:07.423Z,1557246187.423 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count 2019-05-07T16:23:07.430Z,1557246187.430 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count 2019-05-07T16:23:07.434Z,1557246187.434 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup 2019-05-07T16:23:07.447Z,1557246187.447 [DUSBL:A.Pitch](DEBUG): Construct. 2019-05-07T16:23:07.461Z,1557246187.461 [DUSBL:B.SetSpeed](DEBUG): Construct. 2019-05-07T16:23:07.515Z,1557246187.515 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait. 2019-05-07T16:23:07.531Z,1557246187.531 [MissionManager](DEBUG): This mission is requests a DUSBL arming. How long to let the mission run. 90 Number of pings to requst. 10 Transponder Address. 2 Number of pings requested each time. 1 Automatically set to true if the DUSBL is enabled. Set to false to disable reading from the DUSBL. 0 10 2019-05-07T16:23:07.533Z,1557246187.533 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml 2019-05-07T16:23:07.695Z,1557246187.695 [Default] Stopped 2019-05-07T16:23:07.695Z,1557246187.695 [Default](DEBUG): Aggregate::uninitialize Default 2019-05-07T16:23:07.695Z,1557246187.695 [Default:A.Wait] Stopped 2019-05-07T16:23:07.695Z,1557246187.695 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:23:07.695Z,1557246187.695 [Default:B.GoToSurface] Stopped 2019-05-07T16:23:07.695Z,1557246187.695 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-07T16:23:07.695Z,1557246187.695 [MissionManager](IMPORTANT): Started mission DUSBL 2019-05-07T16:23:07.696Z,1557246187.696 [DUSBL] Running Loop=1 2019-05-07T16:23:07.696Z,1557246187.696 [DUSBL](DEBUG): Aggregate::initialize DUSBL 2019-05-07T16:23:07.696Z,1557246187.696 [DUSBL:A.Pitch] Running Loop=1 2019-05-07T16:23:07.696Z,1557246187.696 [DUSBL:A.Pitch](DEBUG): Initialize. 2019-05-07T16:23:07.696Z,1557246187.696 [DUSBL:B.SetSpeed] Running Loop=1 2019-05-07T16:23:07.696Z,1557246187.696 [DUSBL:B.SetSpeed](DEBUG): Initialize. 2019-05-07T16:23:07.696Z,1557246187.696 [DUSBL:C] Running Loop=1 2019-05-07T16:23:07.697Z,1557246187.697 [DUSBL:RequestRepeater] Running Loop=1 2019-05-07T16:23:07.697Z,1557246187.697 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:23:07.697Z,1557246187.697 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:23:07.697Z,1557246187.697 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:23:07.697Z,1557246187.697 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:23:07.697Z,1557246187.697 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:23:07.697Z,1557246187.697 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:23:07.698Z,1557246187.698 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:23:07.707Z,1557246187.707 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range 2019-05-07T16:23:07.707Z,1557246187.707 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame 2019-05-07T16:23:07.707Z,1557246187.707 [DUSBL:B.SetSpeed] Running Loop=1 2019-05-07T16:23:07.708Z,1557246187.708 [DUSBL:A.Pitch] Running Loop=1 2019-05-07T16:23:08.964Z,1557246188.964 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:08.964Z,1557246188.964 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:08.964Z,1557246188.964 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:09.364Z,1557246189.364 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:09.365Z,1557246189.365 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:10.176Z,1557246190.176 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:10.176Z,1557246190.176 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:15.024Z,1557246195.024 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,1B1,000,0024E,186,80,80,03,FF 2019-05-07T16:23:15.036Z,1557246195.036 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.071482 2019-05-07T16:23:15.036Z,1557246195.036 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:15.036Z,1557246195.036 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:15.036Z,1557246195.036 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:15.424Z,1557246195.424 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:15.425Z,1557246195.425 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:16.236Z,1557246196.236 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:16.236Z,1557246196.236 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:17.875Z,1557246197.875 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:23:17.875Z,1557246197.875 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:23:17.875Z,1557246197.875 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:23:17.876Z,1557246197.876 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:23:17.876Z,1557246197.876 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:23:17.876Z,1557246197.876 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:23:17.876Z,1557246197.876 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:23:17.876Z,1557246197.876 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:23:17.876Z,1557246197.876 [DUSBL:RequestRepeater](INFO): Running loop #2 2019-05-07T16:23:17.876Z,1557246197.876 [DUSBL:RequestRepeater] Running Loop=2 2019-05-07T16:23:17.877Z,1557246197.877 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:23:17.877Z,1557246197.877 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:23:17.877Z,1557246197.877 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:23:17.877Z,1557246197.877 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:23:17.877Z,1557246197.877 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:23:21.241Z,1557246201.241 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,192,000,00000,186,80,81,08,FF 2019-05-07T16:23:21.254Z,1557246201.254 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.217867 2019-05-07T16:23:21.255Z,1557246201.255 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:21.255Z,1557246201.255 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:21.256Z,1557246201.256 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:21.596Z,1557246201.596 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:21.596Z,1557246201.596 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:22.408Z,1557246202.408 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:22.408Z,1557246202.408 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:27.256Z,1557246207.256 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,147,000,00000,186,80,81,04,FF 2019-05-07T16:23:27.266Z,1557246207.266 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.010780 2019-05-07T16:23:27.266Z,1557246207.266 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:27.267Z,1557246207.267 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:27.267Z,1557246207.267 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:27.660Z,1557246207.660 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:27.662Z,1557246207.662 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:28.065Z,1557246208.065 [Micromodem](ERROR): Response from modem unexpected: $CADQF,184,1*5D 2019-05-07T16:23:28.066Z,1557246208.066 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21 2019-05-07T16:23:28.468Z,1557246208.468 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:28.468Z,1557246208.468 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:28.475Z,1557246208.475 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507162326.785695,06,335,13,0090,0150,246,00,00,02,00,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,184,0.05,-999,9760,4000*5E 2019-05-07T16:23:28.515Z,1557246208.515 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:23:28.515Z,1557246208.515 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:23:28.515Z,1557246208.515 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:23:28.516Z,1557246208.516 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:23:28.516Z,1557246208.516 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:23:28.516Z,1557246208.516 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:23:28.516Z,1557246208.516 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:23:28.516Z,1557246208.516 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:23:28.517Z,1557246208.517 [DUSBL:RequestRepeater](INFO): Running loop #3 2019-05-07T16:23:28.517Z,1557246208.517 [DUSBL:RequestRepeater] Running Loop=3 2019-05-07T16:23:28.517Z,1557246208.517 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:23:28.517Z,1557246208.517 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:23:28.517Z,1557246208.517 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:23:28.517Z,1557246208.517 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:23:28.517Z,1557246208.517 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:23:33.323Z,1557246213.323 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,136,000,00000,186,80,81,0B,FF 2019-05-07T16:23:33.335Z,1557246213.335 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.067108 2019-05-07T16:23:33.336Z,1557246213.336 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:33.336Z,1557246213.336 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:33.337Z,1557246213.337 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:33.720Z,1557246213.720 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:33.721Z,1557246213.721 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:34.524Z,1557246214.524 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:34.524Z,1557246214.524 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:39.011Z,1557246219.011 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:23:39.011Z,1557246219.011 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:23:39.011Z,1557246219.011 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:23:39.012Z,1557246219.012 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:23:39.012Z,1557246219.012 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:23:39.012Z,1557246219.012 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:23:39.012Z,1557246219.012 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:23:39.012Z,1557246219.012 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:23:39.013Z,1557246219.013 [DUSBL:RequestRepeater](INFO): Running loop #4 2019-05-07T16:23:39.013Z,1557246219.013 [DUSBL:RequestRepeater] Running Loop=4 2019-05-07T16:23:39.013Z,1557246219.013 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:23:39.013Z,1557246219.013 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:23:39.013Z,1557246219.013 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:23:39.013Z,1557246219.013 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:23:39.013Z,1557246219.013 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:23:39.372Z,1557246219.372 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,14C,000,00000,186,80,81,0E,FF 2019-05-07T16:23:39.382Z,1557246219.382 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.045114 2019-05-07T16:23:39.383Z,1557246219.383 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:39.383Z,1557246219.383 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:39.383Z,1557246219.383 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:39.776Z,1557246219.776 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:39.777Z,1557246219.777 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:40.185Z,1557246220.185 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CDQF,198,1*50 2019-05-07T16:23:40.186Z,1557246220.186 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21 2019-05-07T16:23:40.988Z,1557246220.988 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:40.988Z,1557246220.988 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:45.444Z,1557246225.444 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,0D,FF 6,80,81,0E,FF 2019-05-07T16:23:45.458Z,1557246225.458 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.075287 2019-05-07T16:23:45.459Z,1557246225.459 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:45.459Z,1557246225.459 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:45.459Z,1557246225.459 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:45.836Z,1557246225.836 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:45.836Z,1557246225.836 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:46.648Z,1557246226.648 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:46.648Z,1557246226.648 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:49.510Z,1557246229.510 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:23:49.510Z,1557246229.510 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:23:49.510Z,1557246229.510 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:23:49.511Z,1557246229.511 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:23:49.511Z,1557246229.511 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:23:49.511Z,1557246229.511 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:23:49.511Z,1557246229.511 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:23:49.511Z,1557246229.511 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:23:49.512Z,1557246229.512 [DUSBL:RequestRepeater](INFO): Running loop #5 2019-05-07T16:23:49.512Z,1557246229.512 [DUSBL:RequestRepeater] Running Loop=5 2019-05-07T16:23:49.512Z,1557246229.512 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:23:49.512Z,1557246229.512 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:23:49.512Z,1557246229.512 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:23:49.512Z,1557246229.512 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:23:49.512Z,1557246229.512 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:23:51.492Z,1557246231.492 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,15E,000,00000,186,80,81,04,FF 2019-05-07T16:23:51.502Z,1557246231.502 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.043131 2019-05-07T16:23:51.502Z,1557246231.502 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:51.503Z,1557246231.503 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:51.503Z,1557246231.503 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:51.896Z,1557246231.896 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:51.896Z,1557246231.896 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:52.708Z,1557246232.708 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:52.708Z,1557246232.708 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:23:57.556Z,1557246237.556 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,156,000,00000,186,80,81,11,FF 2019-05-07T16:23:57.566Z,1557246237.566 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.062947 2019-05-07T16:23:57.566Z,1557246237.566 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:23:57.567Z,1557246237.567 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:23:57.567Z,1557246237.567 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:23:57.960Z,1557246237.960 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:23:57.961Z,1557246237.961 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:23:58.768Z,1557246238.768 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:23:58.768Z,1557246238.768 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:00.007Z,1557246240.007 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:24:00.007Z,1557246240.007 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:24:00.007Z,1557246240.007 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:24:00.008Z,1557246240.008 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:24:00.008Z,1557246240.008 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:24:00.008Z,1557246240.008 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:24:00.008Z,1557246240.008 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:24:00.008Z,1557246240.008 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:24:00.009Z,1557246240.009 [DUSBL:RequestRepeater](INFO): Running loop #6 2019-05-07T16:24:00.009Z,1557246240.009 [DUSBL:RequestRepeater] Running Loop=6 2019-05-07T16:24:00.009Z,1557246240.009 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:24:00.009Z,1557246240.009 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:24:00.009Z,1557246240.009 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:24:00.009Z,1557246240.009 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:24:00.009Z,1557246240.009 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:24:03.616Z,1557246243.616 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,18C,000,00000,186,80,81,0A,FF 2019-05-07T16:24:03.630Z,1557246243.630 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.063078 2019-05-07T16:24:03.631Z,1557246243.631 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:03.631Z,1557246243.631 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:03.631Z,1557246243.631 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:04.016Z,1557246244.016 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:04.017Z,1557246244.017 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:05.228Z,1557246245.228 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:05.228Z,1557246245.228 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:09.676Z,1557246249.676 [DUSBL_Hydroid](INFO): IN QUEUE:00000,186,80,81,0D,FF 6,80,81,0A,FF 2019-05-07T16:24:09.686Z,1557246249.686 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.055113 2019-05-07T16:24:09.686Z,1557246249.686 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:09.687Z,1557246249.687 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:09.687Z,1557246249.687 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:10.092Z,1557246250.092 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:10.093Z,1557246250.093 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:10.546Z,1557246250.546 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:24:10.546Z,1557246250.546 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:24:10.546Z,1557246250.546 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater](INFO): Running loop #7 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater] Running Loop=7 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:24:10.547Z,1557246250.547 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:24:10.548Z,1557246250.548 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:24:10.888Z,1557246250.888 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:10.888Z,1557246250.888 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:15.736Z,1557246255.736 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,178,000,00000,185,80,81,10,FF 2019-05-07T16:24:15.746Z,1557246255.746 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058961 2019-05-07T16:24:15.746Z,1557246255.746 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:15.747Z,1557246255.747 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:15.747Z,1557246255.747 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:16.145Z,1557246256.145 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:16.147Z,1557246256.147 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:16.545Z,1557246256.545 [Micromodem](ERROR): Response from modem unexpected: $CADQF,197,1*5F 2019-05-07T16:24:16.547Z,1557246256.547 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21 2019-05-07T16:24:16.948Z,1557246256.948 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:16.948Z,1557246256.948 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:16.954Z,1557246256.954 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190507162415.468625,06,489,14,0096,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,17,0.05,-999,9760,4000*50 2019-05-07T16:24:16.956Z,1557246256.956 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,1246,AUV,2..269*13 2019-05-07T16:24:21.007Z,1557246261.007 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:24:21.007Z,1557246261.007 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:24:21.008Z,1557246261.008 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:24:21.008Z,1557246261.008 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:24:21.008Z,1557246261.008 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater](INFO): Running loop #8 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater] Running Loop=8 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:24:21.009Z,1557246261.009 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:24:21.795Z,1557246261.795 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,19A,000,00000,187,80,81,08,FF 2019-05-07T16:24:21.806Z,1557246261.806 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.059026 2019-05-07T16:24:21.807Z,1557246261.807 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:21.807Z,1557246261.807 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:21.807Z,1557246261.807 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:22.196Z,1557246262.196 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:22.196Z,1557246262.196 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:23.008Z,1557246263.008 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:23.008Z,1557246263.008 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:27.852Z,1557246267.852 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,15C,000,00000,185,80,81,0D,FF 2019-05-07T16:24:27.862Z,1557246267.862 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.055137 2019-05-07T16:24:27.862Z,1557246267.862 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:27.863Z,1557246267.863 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:27.863Z,1557246267.863 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:28.260Z,1557246268.260 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:28.261Z,1557246268.261 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:28.661Z,1557246268.661 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21 2019-05-07T16:24:28.668Z,1557246268.668 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507162427.306174,06,319,12,0093,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,195,0.05,-999,9760,4000*51 2019-05-07T16:24:29.068Z,1557246269.068 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:29.068Z,1557246269.068 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:31.520Z,1557246271.520 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:24:31.520Z,1557246271.520 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:24:31.520Z,1557246271.520 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:24:31.521Z,1557246271.521 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:24:31.521Z,1557246271.521 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:24:31.521Z,1557246271.521 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:24:31.521Z,1557246271.521 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:24:31.521Z,1557246271.521 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:24:31.521Z,1557246271.521 [DUSBL:RequestRepeater](INFO): Running loop #9 2019-05-07T16:24:31.521Z,1557246271.521 [DUSBL:RequestRepeater] Running Loop=9 2019-05-07T16:24:31.522Z,1557246271.522 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:24:31.522Z,1557246271.522 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:24:31.522Z,1557246271.522 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:24:31.522Z,1557246271.522 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:24:31.522Z,1557246271.522 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:24:33.920Z,1557246273.920 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,142,000,00000,185,80,81,0E,FF 2019-05-07T16:24:33.931Z,1557246273.931 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.067769 2019-05-07T16:24:33.931Z,1557246273.931 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:33.931Z,1557246273.931 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:33.932Z,1557246273.932 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:34.323Z,1557246274.323 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:34.325Z,1557246274.325 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:35.128Z,1557246275.128 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:35.128Z,1557246275.128 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:39.976Z,1557246279.976 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,156,000,00000,186,80,81,0F,FF 2019-05-07T16:24:39.986Z,1557246279.986 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.054441 2019-05-07T16:24:39.986Z,1557246279.986 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:39.987Z,1557246279.987 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:39.987Z,1557246279.987 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:40.384Z,1557246280.384 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:40.385Z,1557246280.385 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:41.188Z,1557246281.188 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:41.188Z,1557246281.188 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:42.019Z,1557246282.019 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:24:42.019Z,1557246282.019 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:24:42.019Z,1557246282.019 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:24:42.020Z,1557246282.020 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:24:42.020Z,1557246282.020 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:24:42.020Z,1557246282.020 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:24:42.020Z,1557246282.020 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:24:42.020Z,1557246282.020 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:24:42.020Z,1557246282.020 [DUSBL:RequestRepeater](INFO): Running loop #10 2019-05-07T16:24:42.021Z,1557246282.021 [DUSBL:RequestRepeater] Running Loop=10 2019-05-07T16:24:42.021Z,1557246282.021 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2019-05-07T16:24:42.021Z,1557246282.021 [DUSBL:RequestRepeater:A] Running Loop=1 2019-05-07T16:24:42.021Z,1557246282.021 [DUSBL:RequestRepeater:B] Running Loop=1 2019-05-07T16:24:42.021Z,1557246282.021 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2019-05-07T16:24:42.021Z,1557246282.021 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:24:46.036Z,1557246286.036 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,15B,000,00000,185,80,81,0D,FF 2019-05-07T16:24:46.046Z,1557246286.046 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.058999 2019-05-07T16:24:46.046Z,1557246286.046 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:46.047Z,1557246286.047 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:46.047Z,1557246286.047 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:46.452Z,1557246286.452 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:46.453Z,1557246286.453 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:47.260Z,1557246287.260 [DUSBL_Hydroid](INFO): USBL response received:!U1,P 2019-05-07T16:24:47.260Z,1557246287.260 [DUSBL_Hydroid](INFO): Command Ack 2019-05-07T16:24:52.092Z,1557246292.092 [DUSBL_Hydroid](INFO): IN QUEUE:!U1,R,163,000,00000,186,80,81,0E,FF 2019-05-07T16:24:52.102Z,1557246292.102 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:6.055001 2019-05-07T16:24:52.102Z,1557246292.102 [DUSBL_Hydroid](INFO): ****** received transponder code query ****** 2019-05-07T16:24:52.103Z,1557246292.103 [DUSBL_Hydroid](INFO): ****** received ping request ****** 2019-05-07T16:24:52.103Z,1557246292.103 [DUSBL_Hydroid](INFO): ****** ping requested ****** 2019-05-07T16:24:52.496Z,1557246292.496 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2 2019-05-07T16:24:52.497Z,1557246292.497 [Micromodem](INFO): **** IS COMMANDED IN Runnable **** 2019-05-07T16:24:52.549Z,1557246292.549 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting. 2019-05-07T16:24:52.550Z,1557246292.550 [DUSBL:RequestRepeater:C.Wait] Stopped 2019-05-07T16:24:52.550Z,1557246292.550 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:24:52.551Z,1557246292.551 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater 2019-05-07T16:24:52.551Z,1557246292.551 [DUSBL:RequestRepeater] Stopped 2019-05-07T16:24:52.551Z,1557246292.551 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2019-05-07T16:24:52.551Z,1557246292.551 [DUSBL:RequestRepeater:A] Stopped 2019-05-07T16:24:52.551Z,1557246292.551 [DUSBL:RequestRepeater:B] Stopped 2019-05-07T16:24:52.552Z,1557246292.552 [DUSBL](INFO): Completed DUSBL 2019-05-07T16:24:52.553Z,1557246292.553 [MissionManager](INFO): DUSBL is completed. 2019-05-07T16:24:52.553Z,1557246292.553 [MissionManager](INFO): Uninitializing Mission DUSBL 2019-05-07T16:24:52.553Z,1557246292.553 [DUSBL] Stopped 2019-05-07T16:24:52.553Z,1557246292.553 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL 2019-05-07T16:24:52.553Z,1557246292.553 [DUSBL:A.Pitch] Stopped 2019-05-07T16:24:52.553Z,1557246292.553 [DUSBL:B.SetSpeed] Stopped 2019-05-07T16:24:52.553Z,1557246292.553 [DUSBL:B.SetSpeed](DEBUG): Uninitialize. 2019-05-07T16:24:52.553Z,1557246292.553 [DUSBL:C] Stopped 2019-05-07T16:24:52.951Z,1557246292.951 [MissionManager](IMPORTANT): Started mission Default 2019-05-07T16:24:52.951Z,1557246292.951 [Default] Running Loop=1 2019-05-07T16:24:52.951Z,1557246292.951 [Default](DEBUG): Aggregate::initialize Default 2019-05-07T16:24:52.952Z,1557246292.952 [Default:B.GoToSurface] Running Loop=1 2019-05-07T16:24:52.952Z,1557246292.952 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-07T16:24:52.952Z,1557246292.952 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-07T16:24:52.952Z,1557246292.952 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-07T16:24:52.952Z,1557246292.952 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-07T16:24:52.953Z,1557246292.953 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-07T16:24:52.953Z,1557246292.953 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-07T16:24:52.953Z,1557246292.953 [Default:A.Wait] Running Loop=1 2019-05-07T16:24:52.953Z,1557246292.953 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-05-07T16:25:06.260Z,1557246306.260 [Default:A.Wait](INFO): Done Waiting. 2019-05-07T16:25:06.260Z,1557246306.260 [Default:A.Wait] Stopped 2019-05-07T16:25:06.260Z,1557246306.260 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-05-07T16:25:06.684Z,1557246306.684 [Default:CheckIn] Running Loop=1 2019-05-07T16:25:06.684Z,1557246306.684 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-07T16:25:06.684Z,1557246306.684 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-07T16:25:07.068Z,1557246307.068 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-05-07T16:25:45.825Z,1557246345.825 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-07T16:25:46.654Z,1557246346.654 [NAL9602](DEBUG): Fix Requested 2019-05-07T16:25:47.039Z,1557246347.039 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162419.00,A,3648.16360,N,12147.29203,W,0.914,0.00,070519,,,A*73 2019-05-07T16:25:47.042Z,1557246347.042 [NAL9602](INFO): GPS fix at 20190507T162419: (36.802727, -121.788201) 2019-05-07T16:25:47.073Z,1557246347.073 [Default:CheckIn:Read_GPS] Stopped 2019-05-07T16:25:47.074Z,1557246347.074 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-07T16:25:47.491Z,1557246347.491 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-07T16:25:55.270Z,1557246355.270 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190507T161954/Courier0004.lzma 2019-05-07T16:25:56.076Z,1557246356.076 [DataOverHttps](INFO): Moved sent file to Logs/20190507T161954/Courier0004.lzma.bak 2019-05-07T16:25:56.076Z,1557246356.076 [DataOverHttps](INFO): SBD MOMSN=10955671 2019-05-07T16:26:14.576Z,1557246374.576 [DataOverHttps](INFO): Sending 1364 bytes from file Logs/20190507T161954/Express0001.lzma 2019-05-07T16:26:15.380Z,1557246375.380 [DataOverHttps](INFO): Moved sent file to Logs/20190507T161954/Express0001.lzma.bak 2019-05-07T16:26:15.380Z,1557246375.380 [DataOverHttps](INFO): SBD MOMSN=10955675 2019-05-07T16:26:16.897Z,1557246376.897 [CommandLine](IMPORTANT): got command restart application 2019-05-07T16:26:17.926Z,1557246377.926 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2019-05-07T16:26:17.927Z,1557246377.927 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:17.927Z,1557246377.927 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.022Z,1557246378.022 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-05-07T16:26:18.022Z,1557246378.022 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.023Z,1557246378.023 [CommandLine](INFO): Join timeout helper Thread ID is 3755 2019-05-07T16:26:18.024Z,1557246378.024 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-05-07T16:26:18.024Z,1557246378.024 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.025Z,1557246378.025 [NavChartDb](INFO): Join timeout helper Thread ID is 3756 2019-05-07T16:26:18.267Z,1557246378.267 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:18.267Z,1557246378.267 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.286Z,1557246378.286 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2019-05-07T16:26:18.286Z,1557246378.286 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.287Z,1557246378.287 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 3757 2019-05-07T16:26:18.514Z,1557246378.514 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:18.515Z,1557246378.515 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-05-07T16:26:18.515Z,1557246378.515 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.518Z,1557246378.518 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-05-07T16:26:18.518Z,1557246378.518 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.519Z,1557246378.519 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3758 2019-05-07T16:26:18.622Z,1557246378.622 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:18.623Z,1557246378.623 [CTD_NeilBrown](INFO): Powering down 2019-05-07T16:26:18.634Z,1557246378.634 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.654Z,1557246378.654 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-05-07T16:26:18.654Z,1557246378.654 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.655Z,1557246378.655 [Radio_Surface](INFO): Join timeout helper Thread ID is 3759 2019-05-07T16:26:18.844Z,1557246378.844 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-07T16:26:18.926Z,1557246378.926 [Radio_Surface](INFO): Powering down 2019-05-07T16:26:18.927Z,1557246378.927 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:18.928Z,1557246378.928 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.935Z,1557246378.935 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-05-07T16:26:18.935Z,1557246378.935 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:18.936Z,1557246378.936 [DataOverHttps](INFO): Join timeout helper Thread ID is 3760 2019-05-07T16:26:20.932Z,1557246380.932 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:20.936Z,1557246380.936 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:20.944Z,1557246380.944 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-05-07T16:26:20.944Z,1557246380.944 [logger ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:20.944Z,1557246380.944 [logger](INFO): Join timeout helper Thread ID is 3761 2019-05-07T16:26:20.979Z,1557246380.979 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:20.979Z,1557246380.979 [logger ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:20.984Z,1557246380.984 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-05-07T16:26:20.984Z,1557246380.984 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:20.984Z,1557246380.984 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-05-07T16:26:20.984Z,1557246380.984 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:20.985Z,1557246380.985 [controlThread](INFO): Join timeout helper Thread ID is 3762 2019-05-07T16:26:21.250Z,1557246381.250 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-07T16:26:21.251Z,1557246381.251 [controlThread](DEBUG): Uninitializing ControlThread 2019-05-07T16:26:21.251Z,1557246381.251 [AHRS_M2](INFO): Powering down 2019-05-07T16:26:21.325Z,1557246381.325 [DUSBL_Hydroid](INFO): Powering down 2019-05-07T16:26:21.399Z,1557246381.399 [Micromodem](INFO): Powering down 2019-05-07T16:26:21.495Z,1557246381.495 [NAL9602](INFO): Powering down 2019-05-07T16:26:21.566Z,1557246381.566 [RDI_Pathfinder](INFO): Powering down 2019-05-07T16:26:21.568Z,1557246381.568 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-05-07T16:26:21.569Z,1557246381.569 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-05-07T16:26:21.569Z,1557246381.569 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-05-07T16:26:21.570Z,1557246381.570 [MissionManager](INFO): Uninitializing Mission Default 2019-05-07T16:26:21.570Z,1557246381.570 [Default] Stopped 2019-05-07T16:26:21.570Z,1557246381.570 [Default](DEBUG): Aggregate::uninitialize Default 2019-05-07T16:26:21.570Z,1557246381.570 [Default:B.GoToSurface] Stopped 2019-05-07T16:26:21.570Z,1557246381.570 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-07T16:26:21.570Z,1557246381.570 [Default:CheckIn] Stopped 2019-05-07T16:26:21.570Z,1557246381.570 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-07T16:26:21.571Z,1557246381.571 [Default:CheckIn:Read_Iridium] Stopped 2019-05-07T16:26:21.573Z,1557246381.573 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-05-07T16:26:21.573Z,1557246381.573 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-05-07T16:26:21.573Z,1557246381.573 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-05-07T16:26:21.574Z,1557246381.574 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-05-07T16:26:21.574Z,1557246381.574 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-05-07T16:26:21.574Z,1557246381.574 [BuoyancyServo](INFO): Powering down 2019-05-07T16:26:21.586Z,1557246381.586 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-05-07T16:26:21.586Z,1557246381.586 [ElevatorServo](INFO): Powering down 2019-05-07T16:26:21.587Z,1557246381.587 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-05-07T16:26:21.587Z,1557246381.587 [MassServo](INFO): Powering down 2019-05-07T16:26:21.588Z,1557246381.588 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-05-07T16:26:21.588Z,1557246381.588 [RudderServo](INFO): Powering down 2019-05-07T16:26:21.589Z,1557246381.589 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-05-07T16:26:21.589Z,1557246381.589 [ThrusterServo](INFO): Powering down 2019-05-07T16:26:21.590Z,1557246381.590 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-05-07T16:26:21.590Z,1557246381.590 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-05-07T16:26:21.591Z,1557246381.591 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-05-07T16:26:21.591Z,1557246381.591 [CBIT](DEBUG): Powering off loads. 2019-05-07T16:26:21.602Z,1557246381.602 [CBIT](DEBUG): Disabling WDT. 2019-05-07T16:26:21.614Z,1557246381.614 [CBIT](DEBUG): Opening all GF detection circuits. 2019-05-07T16:26:21.615Z,1557246381.615 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:21.659Z,1557246381.659 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:21.668Z,1557246381.668 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:21.712Z,1557246381.712 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:21.714Z,1557246381.714 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:21.769Z,1557246381.769 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-07T16:26:21.834Z,1557246381.834 [logger ThreadHandler](INFO): Thread cancelled.