2020-01-14T00:33:03.278Z,1578961983.278 [Supervisor](DEBUG): Initializing supervisor. 2020-01-14T00:33:03.281Z,1578961983.281 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2020-01-14T00:33:03.281Z,1578961983.281 [SyncHandler](INFO): Protected caller Thread ID is 6331 2020-01-14T00:33:03.282Z,1578961983.282 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2020-01-14T00:33:03.283Z,1578961983.283 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2020-01-14T00:33:03.284Z,1578961983.284 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 6332 2020-01-14T00:33:03.287Z,1578961983.287 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2020-01-14T00:33:03.298Z,1578961983.298 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2020-01-14T00:33:03.299Z,1578961983.299 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2020-01-14T00:33:03.300Z,1578961983.300 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 6333 2020-01-14T00:33:03.301Z,1578961983.301 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2020-01-14T00:33:03.301Z,1578961983.301 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2020-01-14T00:33:03.302Z,1578961983.302 [logger ThreadHandler](INFO): Protected caller Thread ID is 6334 2020-01-14T00:33:03.304Z,1578961983.304 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2020-01-14T00:33:03.304Z,1578961983.304 [Supervisor](INFO): Looking for Config files in directory: Config/ 2020-01-14T00:33:03.306Z,1578961983.306 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2020-01-14T00:33:03.753Z,1578961983.753 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2020-01-14T00:33:03.753Z,1578961983.753 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2020-01-14T00:33:03.849Z,1578961983.849 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2020-01-14T00:33:03.850Z,1578961983.850 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2020-01-14T00:33:04.164Z,1578961984.164 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2020-01-14T00:33:04.165Z,1578961984.165 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2020-01-14T00:33:04.302Z,1578961984.302 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2020-01-14T00:33:04.302Z,1578961984.302 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2020-01-14T00:33:04.489Z,1578961984.489 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2020-01-14T00:33:04.490Z,1578961984.490 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2020-01-14T00:33:04.944Z,1578961984.944 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2020-01-14T00:33:04.945Z,1578961984.945 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2020-01-14T00:33:05.155Z,1578961985.155 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2020-01-14T00:33:05.156Z,1578961985.156 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2020-01-14T00:33:05.299Z,1578961985.299 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2020-01-14T00:33:05.300Z,1578961985.300 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2020-01-14T00:33:05.491Z,1578961985.491 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2020-01-14T00:33:05.492Z,1578961985.492 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2020-01-14T00:33:05.587Z,1578961985.587 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2020-01-14T00:33:05.587Z,1578961985.587 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2020-01-14T00:33:05.886Z,1578961985.886 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2020-01-14T00:33:05.887Z,1578961985.887 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2020-01-14T00:33:05.967Z,1578961985.967 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2020-01-14T00:33:06.086Z,1578961986.086 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2020-01-14T00:33:06.086Z,1578961986.086 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2020-01-14T00:33:07.136Z,1578961987.136 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2020-01-14T00:33:07.136Z,1578961987.136 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2020-01-14T00:33:07.548Z,1578961987.548 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2020-01-14T00:33:07.549Z,1578961987.549 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/ 2020-01-14T00:33:07.550Z,1578961987.550 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg 2020-01-14T00:33:07.756Z,1578961987.756 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg 2020-01-14T00:33:07.859Z,1578961987.859 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg 2020-01-14T00:33:07.956Z,1578961987.956 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg 2020-01-14T00:33:08.184Z,1578961988.184 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2020-01-14T00:33:08.184Z,1578961988.184 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg 2020-01-14T00:33:08.268Z,1578961988.268 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg 2020-01-14T00:33:08.359Z,1578961988.359 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg 2020-01-14T00:33:08.462Z,1578961988.462 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg 2020-01-14T00:33:08.544Z,1578961988.544 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg 2020-01-14T00:33:08.652Z,1578961988.652 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg 2020-01-14T00:33:08.834Z,1578961988.834 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg 2020-01-14T00:33:08.963Z,1578961988.963 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/ 2020-01-14T00:33:08.963Z,1578961988.963 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2020-01-14T00:33:08.977Z,1578961988.977 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2020-01-14T00:33:09.300Z,1578961989.300 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2020-01-14T00:33:09.305Z,1578961989.305 [AHRS_M2](INFO): created writer for : platform_orientation 2020-01-14T00:33:09.307Z,1578961989.307 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2020-01-14T00:33:09.312Z,1578961989.312 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2020-01-14T00:33:09.313Z,1578961989.313 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2020-01-14T00:33:09.318Z,1578961989.318 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2020-01-14T00:33:09.319Z,1578961989.319 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2020-01-14T00:33:09.324Z,1578961989.324 [AHRS_M2](INFO): created writer for : platform_roll_angle 2020-01-14T00:33:09.395Z,1578961989.395 [AHRS_M2] Loaded 2020-01-14T00:33:09.395Z,1578961989.395 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2020-01-14T00:33:09.472Z,1578961989.472 [DataOverHttps] Loaded 2020-01-14T00:33:09.472Z,1578961989.472 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2020-01-14T00:33:09.473Z,1578961989.473 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4076F4E0 2020-01-14T00:33:09.473Z,1578961989.473 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 6413 2020-01-14T00:33:09.498Z,1578961989.498 [DDM] Loaded 2020-01-14T00:33:09.498Z,1578961989.498 [ComponentRegistry](DEBUG): SyncComponent "DDM" handled in the control thread. 2020-01-14T00:33:09.511Z,1578961989.511 [Depth_Keller] Loaded 2020-01-14T00:33:09.511Z,1578961989.511 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2020-01-14T00:33:09.516Z,1578961989.516 [DropWeight] Loaded 2020-01-14T00:33:09.516Z,1578961989.516 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2020-01-14T00:33:09.578Z,1578961989.578 [DUSBL_Hydroid] Loaded 2020-01-14T00:33:09.578Z,1578961989.578 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread. 2020-01-14T00:33:09.626Z,1578961989.626 [Micromodem] Loaded 2020-01-14T00:33:09.626Z,1578961989.626 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2020-01-14T00:33:09.725Z,1578961989.725 [NAL9602] Loaded 2020-01-14T00:33:09.725Z,1578961989.725 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2020-01-14T00:33:09.763Z,1578961989.763 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/voltage_now 2020-01-14T00:33:09.763Z,1578961989.763 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/current_now 2020-01-14T00:33:09.764Z,1578961989.764 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_now 2020-01-14T00:33:09.764Z,1578961989.764 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_full 2020-01-14T00:33:09.765Z,1578961989.765 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/voltage_now 2020-01-14T00:33:09.765Z,1578961989.765 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/current_now 2020-01-14T00:33:09.766Z,1578961989.766 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_now 2020-01-14T00:33:09.766Z,1578961989.766 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_full 2020-01-14T00:33:09.766Z,1578961989.766 [Onboard] Loaded 2020-01-14T00:33:09.767Z,1578961989.767 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2020-01-14T00:33:09.772Z,1578961989.772 [PowerOnly] Loaded 2020-01-14T00:33:09.773Z,1578961989.773 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2020-01-14T00:33:09.779Z,1578961989.779 [Radio_Surface] Loaded 2020-01-14T00:33:09.780Z,1578961989.780 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2020-01-14T00:33:09.781Z,1578961989.781 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4079F4E0 2020-01-14T00:33:09.781Z,1578961989.781 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6414 2020-01-14T00:33:09.825Z,1578961989.825 [RDI_Pathfinder] Loaded 2020-01-14T00:33:09.825Z,1578961989.825 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2020-01-14T00:33:11.329Z,1578961991.329 [BPC1] Loaded 2020-01-14T00:33:11.329Z,1578961991.329 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2020-01-14T00:33:11.329Z,1578961991.329 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2020-01-14T00:33:11.330Z,1578961991.330 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2020-01-14T00:33:11.427Z,1578961991.427 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2020-01-14T00:33:11.427Z,1578961991.427 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2020-01-14T00:33:11.715Z,1578961991.715 [DeadReckonUsingMultipleVelocitySources] Loaded 2020-01-14T00:33:11.715Z,1578961991.715 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2020-01-14T00:33:11.818Z,1578961991.818 [NavChart] Loaded 2020-01-14T00:33:11.818Z,1578961991.818 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2020-01-14T00:33:11.822Z,1578961991.822 [UniversalFixResidualReporter] Loaded 2020-01-14T00:33:11.822Z,1578961991.822 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2020-01-14T00:33:11.823Z,1578961991.823 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2020-01-14T00:33:11.823Z,1578961991.823 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2020-01-14T00:33:11.979Z,1578961991.979 [BuoyancyServo] Loaded 2020-01-14T00:33:11.979Z,1578961991.979 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2020-01-14T00:33:11.994Z,1578961991.994 [ElevatorServo] Loaded 2020-01-14T00:33:11.995Z,1578961991.995 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2020-01-14T00:33:12.014Z,1578961992.014 [MassServo] Loaded 2020-01-14T00:33:12.014Z,1578961992.014 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2020-01-14T00:33:12.029Z,1578961992.029 [RudderServo] Loaded 2020-01-14T00:33:12.029Z,1578961992.029 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2020-01-14T00:33:12.044Z,1578961992.044 [ThrusterServo] Loaded 2020-01-14T00:33:12.044Z,1578961992.044 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2020-01-14T00:33:12.045Z,1578961992.045 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2020-01-14T00:33:12.045Z,1578961992.045 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2020-01-14T00:33:12.311Z,1578961992.311 [CTD_NeilBrown] Loaded 2020-01-14T00:33:12.311Z,1578961992.311 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2020-01-14T00:33:12.312Z,1578961992.312 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408F34E0 2020-01-14T00:33:12.312Z,1578961992.312 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 6415 2020-01-14T00:33:12.327Z,1578961992.327 [PAR_Licor] Loaded 2020-01-14T00:33:12.327Z,1578961992.327 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2020-01-14T00:33:12.372Z,1578961992.372 [WetLabsSeaOWL_UV_A] Loaded 2020-01-14T00:33:12.372Z,1578961992.372 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2020-01-14T00:33:12.373Z,1578961992.373 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409234E0 2020-01-14T00:33:12.374Z,1578961992.374 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 6416 2020-01-14T00:33:12.374Z,1578961992.374 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2020-01-14T00:33:12.375Z,1578961992.375 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2020-01-14T00:33:12.700Z,1578961992.700 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2020-01-14T00:33:12.700Z,1578961992.700 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2020-01-14T00:33:12.742Z,1578961992.742 [DepthRateCalculator] Loaded 2020-01-14T00:33:12.743Z,1578961992.743 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2020-01-14T00:33:12.748Z,1578961992.748 [PitchRateCalculator] Loaded 2020-01-14T00:33:12.748Z,1578961992.748 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2020-01-14T00:33:12.761Z,1578961992.761 [SpeedCalculator] Loaded 2020-01-14T00:33:12.761Z,1578961992.761 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2020-01-14T00:33:12.782Z,1578961992.782 [TempGradientCalculator] Loaded 2020-01-14T00:33:12.782Z,1578961992.782 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2020-01-14T00:33:12.788Z,1578961992.788 [YawRateCalculator] Loaded 2020-01-14T00:33:12.788Z,1578961992.788 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2020-01-14T00:33:12.829Z,1578961992.829 [ElevatorOffsetCalculator] Loaded 2020-01-14T00:33:12.829Z,1578961992.829 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2020-01-14T00:33:12.830Z,1578961992.830 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2020-01-14T00:33:12.830Z,1578961992.830 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2020-01-14T00:33:12.973Z,1578961992.973 [SBIT](DEBUG): Construct Startup Built In Test. 2020-01-14T00:33:12.995Z,1578961992.995 [SBIT] Loaded 2020-01-14T00:33:12.995Z,1578961992.995 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2020-01-14T00:33:12.995Z,1578961992.995 [IBIT](DEBUG): Construct Initiated Built In Test. 2020-01-14T00:33:13.008Z,1578961993.008 [IBIT] Loaded 2020-01-14T00:33:13.008Z,1578961993.008 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2020-01-14T00:33:13.011Z,1578961993.011 [CBIT](DEBUG): Construct Continuous Built In Test. 2020-01-14T00:33:13.152Z,1578961993.152 [CBIT] Loaded 2020-01-14T00:33:13.152Z,1578961993.152 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2020-01-14T00:33:13.152Z,1578961993.152 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2020-01-14T00:33:13.153Z,1578961993.153 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2020-01-14T00:33:13.236Z,1578961993.236 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2020-01-14T00:33:13.236Z,1578961993.236 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2020-01-14T00:33:13.338Z,1578961993.338 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2020-01-14T00:33:13.339Z,1578961993.339 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2020-01-14T00:33:13.388Z,1578961993.388 [VerticalControl](DEBUG): Construct VerticalControl. 2020-01-14T00:33:13.473Z,1578961993.473 [VerticalControl] Loaded 2020-01-14T00:33:13.473Z,1578961993.473 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2020-01-14T00:33:13.474Z,1578961993.474 [HorizontalControl](DEBUG): Construct HorizontalControl. 2020-01-14T00:33:13.544Z,1578961993.544 [HorizontalControl] Loaded 2020-01-14T00:33:13.544Z,1578961993.544 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2020-01-14T00:33:13.545Z,1578961993.545 [SpeedControl](DEBUG): Construct SpeedControl. 2020-01-14T00:33:13.547Z,1578961993.547 [SpeedControl] Loaded 2020-01-14T00:33:13.547Z,1578961993.547 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2020-01-14T00:33:13.548Z,1578961993.548 [LoopControl](DEBUG): Construct LoopControl. 2020-01-14T00:33:13.548Z,1578961993.548 [LoopControl] Loaded 2020-01-14T00:33:13.548Z,1578961993.548 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2020-01-14T00:33:13.549Z,1578961993.549 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2020-01-14T00:33:13.549Z,1578961993.549 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2020-01-14T00:33:13.582Z,1578961993.582 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2020-01-14T00:33:13.586Z,1578961993.586 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2020-01-14T00:33:13.587Z,1578961993.587 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2020-01-14T00:33:13.594Z,1578961993.594 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2020-01-14T00:33:13.595Z,1578961993.595 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B024E0 2020-01-14T00:33:13.595Z,1578961993.595 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6417 2020-01-14T00:33:13.599Z,1578961993.599 [Supervisor](INFO): Main Thread ID is 6202 2020-01-14T00:33:13.600Z,1578961993.600 [Supervisor](DEBUG): Running supervisor. 2020-01-14T00:33:13.600Z,1578961993.600 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6418 2020-01-14T00:33:13.603Z,1578961993.603 [controlThread ThreadHandler](INFO): Handler Thread ID is 6419 2020-01-14T00:33:13.603Z,1578961993.603 [controlThread](DEBUG): Initializing ControlThread 2020-01-14T00:33:13.608Z,1578961993.608 [NavChart](DEBUG): Initialize NavChart Navigation. 2020-01-14T00:33:13.608Z,1578961993.608 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2020-01-14T00:33:13.613Z,1578961993.613 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2020-01-14T00:33:13.613Z,1578961993.613 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2020-01-14T00:33:13.614Z,1578961993.614 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2020-01-14T00:33:13.614Z,1578961993.614 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2020-01-14T00:33:13.614Z,1578961993.614 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2020-01-14T00:33:13.615Z,1578961993.615 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2020-01-14T00:33:13.615Z,1578961993.615 [SBIT](INFO): Initialize SBIT Component. 2020-01-14T00:33:13.616Z,1578961993.616 [SBIT](IMPORTANT): git: 2019-12-03-34-g1420f60 2020-01-14T00:33:13.616Z,1578961993.616 [SBIT](INFO): git hash: 1420f6075bfd9e2317cf67bc08ebc33a04e592a5 2020-01-14T00:33:13.616Z,1578961993.616 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2020-01-14T00:33:13.617Z,1578961993.617 [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 2020-01-14T00:33:13.618Z,1578961993.618 [SBIT](INFO): Beginning SBIT in 39.000000 seconds. 2020-01-14T00:33:13.619Z,1578961993.619 [IBIT](INFO): Initialize IBIT Component. 2020-01-14T00:33:13.620Z,1578961993.620 [CBIT](DEBUG): Initialize CBIT Component. 2020-01-14T00:33:13.621Z,1578961993.621 [logger ThreadHandler](INFO): Handler Thread ID is 6420 2020-01-14T00:33:13.633Z,1578961993.633 [CBIT](DEBUG): Initialized mux pins. 2020-01-14T00:33:13.633Z,1578961993.633 [CBIT](DEBUG): Initializing the watchdog timer. 2020-01-14T00:33:13.641Z,1578961993.641 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 6421 2020-01-14T00:33:13.642Z,1578961993.642 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2020-01-14T00:33:13.654Z,1578961993.654 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6422 2020-01-14T00:33:13.657Z,1578961993.657 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2020-01-14T00:33:13.657Z,1578961993.657 [CBIT](DEBUG): Initializing heartbeat. 2020-01-14T00:33:13.665Z,1578961993.665 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 6423 2020-01-14T00:33:13.666Z,1578961993.666 [CTD_NeilBrown](INFO): Powering down 2020-01-14T00:33:13.685Z,1578961993.685 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 6424 2020-01-14T00:33:13.686Z,1578961993.686 [WetLabsSeaOWL_UV_A](INFO): Powering down 2020-01-14T00:33:13.718Z,1578961993.718 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6425 2020-01-14T00:33:13.721Z,1578961993.721 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2020-01-14T00:33:13.721Z,1578961993.721 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2020-01-14T00:33:13.721Z,1578961993.721 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2020-01-14T00:33:13.721Z,1578961993.721 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2020-01-14T00:33:13.721Z,1578961993.721 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2020-01-14T00:33:13.722Z,1578961993.722 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2020-01-14T00:33:13.722Z,1578961993.722 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2020-01-14T00:33:13.722Z,1578961993.722 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2020-01-14T00:33:13.722Z,1578961993.722 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2020-01-14T00:33:13.722Z,1578961993.722 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2020-01-14T00:33:13.723Z,1578961993.723 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2020-01-14T00:33:13.723Z,1578961993.723 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2020-01-14T00:33:13.723Z,1578961993.723 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2020-01-14T00:33:13.723Z,1578961993.723 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2020-01-14T00:33:13.723Z,1578961993.723 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2020-01-14T00:33:13.723Z,1578961993.723 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2020-01-14T00:33:13.729Z,1578961993.729 [CBIT](DEBUG): Deactivating GF circuits. 2020-01-14T00:33:13.729Z,1578961993.729 [CBIT](DEBUG): Deactivating emergency mode. 2020-01-14T00:33:13.765Z,1578961993.765 [CBIT](DEBUG): Backplane powered. 2020-01-14T00:33:13.765Z,1578961993.765 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2020-01-14T00:33:13.767Z,1578961993.767 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2020-01-14T00:33:13.767Z,1578961993.767 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2020-01-14T00:33:13.768Z,1578961993.768 [LoopControl](DEBUG): Initialize LoopControlComponent. 2020-01-14T00:33:13.769Z,1578961993.769 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2020-01-14T00:33:13.778Z,1578961993.778 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2020-01-14T00:33:13.788Z,1578961993.788 [MissionManager](DEBUG): 2020-01-14T00:33:13.797Z,1578961993.797 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2020-01-14T00:33:13.868Z,1578961993.868 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2020-01-14T00:33:13.878Z,1578961993.878 [Default:A.Wait](DEBUG): Construct Wait. 2020-01-14T00:33:13.879Z,1578961993.879 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2020-01-14T00:33:13.907Z,1578961993.907 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2020-01-14T00:33:13.929Z,1578961993.929 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2020-01-14T00:33:13.935Z,1578961993.935 [Default:E.Execute](DEBUG): Construct Execute. 2020-01-14T00:33:13.978Z,1578961993.978 [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 2020-01-14T00:33:13.982Z,1578961993.982 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,DDM,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, 2020-01-14T00:33:13.988Z,1578961993.988 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2020-01-14T00:33:14.021Z,1578961994.021 [DDM](INFO): Powering up 2020-01-14T00:33:14.021Z,1578961994.021 [DDM](DEBUG): Initializing DDM. 2020-01-14T00:33:14.051Z,1578961994.051 [DUSBL_Hydroid](INFO): Powering up 2020-01-14T00:33:14.051Z,1578961994.051 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid. 2020-01-14T00:33:14.057Z,1578961994.057 [Radio_Surface](INFO): Powering up 2020-01-14T00:33:14.234Z,1578961994.234 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2020-01-14T00:33:14.241Z,1578961994.241 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2020-01-14T00:33:14.242Z,1578961994.242 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-01-14T00:33:14.249Z,1578961994.249 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-01-14T00:33:14.250Z,1578961994.250 [MassServo](DEBUG): Initializing EZServoServo. 2020-01-14T00:33:14.257Z,1578961994.257 [MassServo](DEBUG): Initializing MassServo. 2020-01-14T00:33:14.258Z,1578961994.258 [RudderServo](DEBUG): Initializing EZServoServo. 2020-01-14T00:33:14.265Z,1578961994.265 [RudderServo](DEBUG): Initializing RudderServo. 2020-01-14T00:33:14.266Z,1578961994.266 [ThrusterServo](DEBUG): Initializing EZServoServo. 2020-01-14T00:33:14.273Z,1578961994.273 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2020-01-14T00:33:14.410Z,1578961994.410 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2020-01-14T00:33:14.410Z,1578961994.410 [DropWeight] Hardware Fault, FailCount= 1 2020-01-14T00:33:14.410Z,1578961994.410 [DropWeight](ERROR): Hardware Fault 2020-01-14T00:33:14.412Z,1578961994.412 [Micromodem](INFO): Powering up 2020-01-14T00:33:14.412Z,1578961994.412 [Micromodem](DEBUG): Initializing Micromodem. 2020-01-14T00:33:14.468Z,1578961994.468 [CommandLine](FAULT): Scheduling is paused 2020-01-14T00:33:14.469Z,1578961994.469 [CBIT](INFO): Critical error at 20200114T003314 2020-01-14T00:33:14.469Z,1578961994.469 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2020-01-14T00:33:14.471Z,1578961994.471 [CBIT](ERROR): Hardware Fault in component: DropWeight 2020-01-14T00:33:14.472Z,1578961994.472 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2020-01-14T00:33:15.157Z,1578961995.157 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2020-01-14T00:33:15.157Z,1578961995.157 [RudderServo](FAULT): Rudder failed to initialize 2020-01-14T00:33:15.158Z,1578961995.158 [RudderServo] Communications Fault, FailCount= 1 2020-01-14T00:33:15.158Z,1578961995.158 [RudderServo](ERROR): Communications Fault 2020-01-14T00:33:15.266Z,1578961995.266 [CBIT](INFO): Critical error at 20200114T003314 2020-01-14T00:33:15.269Z,1578961995.269 [CBIT](ERROR): Communications Fault in component: RudderServo 2020-01-14T00:33:15.450Z,1578961995.450 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2020-01-14T00:33:15.450Z,1578961995.450 [RudderServo](INFO): Powering down 2020-01-14T00:33:16.117Z,1578961996.117 [RudderServo](DEBUG): Initializing EZServoServo. 2020-01-14T00:33:16.238Z,1578961996.238 [RudderServo](DEBUG): Initializing RudderServo. 2020-01-14T00:33:16.242Z,1578961996.242 [CBIT](INFO): Clearing failed state for component RudderServo 2020-01-14T00:33:16.242Z,1578961996.242 [RudderServo] No Fault, FailCount= 1 2020-01-14T00:33:19.356Z,1578961999.356 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33 2020-01-14T00:33:19.763Z,1578961999.763 [Micromodem](INFO): Nmea in: $CATMG,2020-01-14T00:33:19.144254Z,RTC,RTC*5E 2020-01-14T00:33:19.764Z,1578961999.764 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2020-01-14T00:33:19.144254Z,RTC,RTC*5E 2020-01-14T00:33:20.163Z,1578962000.163 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31 2020-01-14T00:33:20.163Z,1578962000.163 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31 2020-01-14T00:33:20.567Z,1578962000.567 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33 2020-01-14T00:33:20.567Z,1578962000.567 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64 2020-01-14T00:33:20.971Z,1578962000.971 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66 2020-01-14T00:33:20.971Z,1578962000.971 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F 2020-01-14T00:33:21.379Z,1578962001.379 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D 2020-01-14T00:33:21.379Z,1578962001.379 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E 2020-01-14T00:33:21.783Z,1578962001.783 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C 2020-01-14T00:33:21.783Z,1578962001.783 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46 2020-01-14T00:33:22.171Z,1578962002.171 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44 2020-01-14T00:33:22.171Z,1578962002.171 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63 2020-01-14T00:33:22.599Z,1578962002.599 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61 2020-01-14T00:33:22.599Z,1578962002.599 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A 2020-01-14T00:33:22.971Z,1578962002.971 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38 2020-01-14T00:33:22.972Z,1578962002.972 [Micromodem](INFO): Nmea out: $CCCLK,2020,01,14,00,33,23*41 2020-01-14T00:33:23.379Z,1578962003.379 [Micromodem](INFO): Nmea in: $CACLK,2020,1,14,0,33,23*43 2020-01-14T00:33:23.380Z,1578962003.380 [Micromodem](INFO): Nmea in: $CATMS,0,2020-01-14T00:33:24Z*74 2020-01-14T00:33:23.382Z,1578962003.382 [Micromodem](INFO): Nmea in: $CATMG,2020-01-14T00:33:24.028368Z,USER_CMD,RTC*14 2020-01-14T00:33:24.584Z,1578962004.584 [DDM](INFO): Dynamic Docking Module:!C REMUS Capture Rev 1.1 2020-01-14T00:33:27.440Z,1578962007.440 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2020-01-14T00:33:32.258Z,1578962012.258 [DUSBL_Hydroid](INFO): DUSBL Version:O 2020-01-14T00:33:39.924Z,1578962019.924 [NAL9602](INFO): Powering up NAL9602 2020-01-14T00:33:50.836Z,1578962030.836 [NAL9602](INFO): NAL9602 initialized 2020-01-14T00:33:53.340Z,1578962033.340 [SBIT](IMPORTANT): Beginning Startup BIT 2020-01-14T00:33:53.344Z,1578962033.344 [CBIT](IMPORTANT): Beginning ground fault scan 2020-01-14T00:34:04.393Z,1578962044.393 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.019423 CHAN A1 (24V): -0.029306 CHAN A2 (12V): -0.007524 CHAN A3 (5V): -0.002006 CHAN B0 (3.3V): 0.000122 CHAN B1 (3.15aV): -0.000357 CHAN B2 (3.15bV): -0.000020 CHAN B3 (GND): 0.002192 OPEN: 0.005374 Full Scale Calc: 4.765 mA, -1.589 mA 2020-01-14T00:34:46.983Z,1578962086.983 [SBIT](IMPORTANT): SBIT PASSED 2020-01-14T00:34:47.034Z,1578962087.034 [CommandLine](IMPORTANT): got command configSet list 2020-01-14T00:34:47.034Z,1578962087.034 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2020-01-14T00:34:47.035Z,1578962087.035 [CommandLine](IMPORTANT): DDM.loadAtStartup=1 bool; 2020-01-14T00:34:47.035Z,1578962087.035 [CommandLine](IMPORTANT): DDM.verbosity=3 count; 2020-01-14T00:34:47.035Z,1578962087.035 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=25 count; 2020-01-14T00:34:47.035Z,1578962087.035 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=40 millisecond; 2020-01-14T00:34:47.035Z,1578962087.035 [CommandLine](IMPORTANT): Express linearApproximation DDM.DDMMode 1.000000 count; 2020-01-14T00:34:47.035Z,1578962087.035 [CommandLine](IMPORTANT): Express all DDM.cablePresent; 2020-01-14T00:34:47.035Z,1578962087.035 [CommandLine](IMPORTANT): HorizontalControl.kiHeading=0.002 reciprocal_second; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): Micromodem.destinationAddress=12 enum; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): Micromodem.surfaceThreshold=0 meter; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): PowerOnly.sampleTime=90 second; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): RudderServo.deviationAngle=0.0001 degree; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=105 cubic_centimeter; 2020-01-14T00:34:47.036Z,1578962087.036 [CommandLine](IMPORTANT): VerticalControl.massDefault=-5 millimeter; 2020-01-14T00:34:47.399Z,1578962087.399 [MissionManager](IMPORTANT): Started mission Startup 2020-01-14T00:34:47.399Z,1578962087.399 [Startup] Running Loop=1 2020-01-14T00:34:47.399Z,1578962087.399 [Startup](DEBUG): Aggregate::initialize Startup 2020-01-14T00:34:47.399Z,1578962087.399 [Startup:A.GoToSurface] Running Loop=1 2020-01-14T00:34:47.399Z,1578962087.399 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:34:47.400Z,1578962087.400 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:34:47.400Z,1578962087.400 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:34:47.401Z,1578962087.401 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:34:47.401Z,1578962087.401 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:34:47.402Z,1578962087.402 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:34:47.403Z,1578962087.403 [Startup:StartupSatComms] Running Loop=1 2020-01-14T00:34:47.403Z,1578962087.403 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2020-01-14T00:34:47.403Z,1578962087.403 [Startup:StartupSatComms:A] Running Loop=1 2020-01-14T00:34:47.799Z,1578962087.799 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2020-01-14T00:35:00.561Z,1578962100.561 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 30.799999 degree 2020-01-14T00:35:00.562Z,1578962100.562 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread. 2020-01-14T00:35:00.563Z,1578962100.563 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.900002 degree 2020-01-14T00:35:00.564Z,1578962100.564 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread. 2020-01-14T00:35:00.743Z,1578962100.743 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,DDM,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2020-01-14T00:35:01.124Z,1578962101.124 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:01.124Z,1578962101.124 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2020-01-14T00:35:01.124Z,1578962101.124 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:01.126Z,1578962101.126 [Startup:StartupSatComms:A] Stopped 2020-01-14T00:35:01.126Z,1578962101.126 [Startup:StartupSatComms:B] Running Loop=1 2020-01-14T00:35:01.134Z,1578962101.134 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:01.536Z,1578962101.536 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-01-14T00:35:01.553Z,1578962101.553 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:01.553Z,1578962101.553 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2020-01-14T00:35:02.502Z,1578962102.502 [Micromodem](INFO): Outgoing frame #1, 64 bytes: F6021D5E040001005D00000400FD0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567 2020-01-14T00:35:02.502Z,1578962102.502 [Micromodem](INFO): Outgoing frame #2, 64 bytes: 266CC0E6F1A517638CB0C0B8BE372A0B00F6D61E05F93094AA77DEFC753FE61F094712E1114D8E0AD7B6106F0F7B016211E5CA62E332602D1D41ACBF7CDB6A31 2020-01-14T00:35:02.502Z,1578962102.502 [Micromodem](INFO): Outgoing frame #3, 64 bytes: 6612EED8A8416AE25E31B4E18619E5C1F90902C505781770CFDD053F3D92B2892521A612D82BE005FC891846AFDB685B90A9E84997E433AEDF6B399ED6967A92 2020-01-14T00:35:02.503Z,1578962102.503 [Micromodem](INFO): Nmea out: $CCCYC,0,1,12,1,0,3*69 2020-01-14T00:35:02.667Z,1578962102.667 [Micromodem](INFO): Nmea in: $CACYC,0,1,12,1,0,3*6B 2020-01-14T00:35:02.719Z,1578962102.719 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:02.719Z,1578962102.719 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2020-01-14T00:35:02.719Z,1578962102.719 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:02.758Z,1578962102.758 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:03.027Z,1578962103.027 [Micromodem](INFO): Nmea in: $CADRQ,003503,1,12,0,64,1*71 2020-01-14T00:35:03.027Z,1578962103.027 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,F6021D5E040001005D00000400FD0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*40 2020-01-14T00:35:03.180Z,1578962103.180 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:03.180Z,1578962103.180 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2020-01-14T00:35:03.436Z,1578962103.436 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:35:03.835Z,1578962103.835 [Micromodem](INFO): Nmea in: $CADRQ,003503,1,12,0,64,2*72 2020-01-14T00:35:03.835Z,1578962103.835 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,266CC0E6F1A517638CB0C0B8BE372A0B00F6D61E05F93094AA77DEFC753FE61F094712E1114D8E0AD7B6106F0F7B016211E5CA62E332602D1D41ACBF7CDB6A31*3C 2020-01-14T00:35:03.918Z,1578962103.918 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:03.918Z,1578962103.918 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2020-01-14T00:35:03.918Z,1578962103.918 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:03.971Z,1578962103.971 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:04.239Z,1578962104.239 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:35:04.308Z,1578962104.308 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:04.308Z,1578962104.308 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2020-01-14T00:35:04.648Z,1578962104.648 [Micromodem](INFO): Nmea in: $CADRQ,003504,1,12,0,64,3*74 2020-01-14T00:35:04.649Z,1578962104.649 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,6612EED8A8416AE25E31B4E18619E5C1F90902C505781770CFDD053F3D92B2892521A612D82BE005FC891846AFDB685B90A9E84997E433AEDF6B399ED6967A92*4C 2020-01-14T00:35:05.051Z,1578962105.051 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:35:05.112Z,1578962105.112 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:05.112Z,1578962105.112 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2020-01-14T00:35:05.112Z,1578962105.112 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:05.143Z,1578962105.143 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:05.454Z,1578962105.454 [Micromodem](INFO): Nmea in: $CATXP,192*48 2020-01-14T00:35:05.542Z,1578962105.542 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:05.542Z,1578962105.542 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2020-01-14T00:35:06.295Z,1578962106.295 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:06.295Z,1578962106.295 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2020-01-14T00:35:06.295Z,1578962106.295 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:06.305Z,1578962106.305 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:06.725Z,1578962106.725 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:06.725Z,1578962106.725 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2020-01-14T00:35:07.664Z,1578962107.664 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:07.664Z,1578962107.664 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6 2020-01-14T00:35:07.664Z,1578962107.664 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:07.674Z,1578962107.674 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:07.940Z,1578962107.940 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:07.940Z,1578962107.940 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6 2020-01-14T00:35:08.750Z,1578962108.750 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:08.750Z,1578962108.750 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7 2020-01-14T00:35:08.750Z,1578962108.750 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:08.760Z,1578962108.760 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:09.095Z,1578962109.095 [Micromodem](INFO): Nmea in: $CATXF,192*5E 2020-01-14T00:35:09.171Z,1578962109.171 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:09.171Z,1578962109.171 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7 2020-01-14T00:35:09.488Z,1578962109.488 [Micromodem](INFO): Nmea in: $CAXST,6,20200114,003505.630238,3,0,200,4000,10000,1,1,12,1,3,3,3,192*71 2020-01-14T00:35:09.922Z,1578962109.922 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:09.923Z,1578962109.923 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8 2020-01-14T00:35:09.923Z,1578962109.923 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:09.949Z,1578962109.949 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:10.356Z,1578962110.356 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:10.356Z,1578962110.356 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8 2020-01-14T00:35:11.160Z,1578962111.160 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:11.160Z,1578962111.160 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9 2020-01-14T00:35:11.160Z,1578962111.160 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:11.202Z,1578962111.202 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:11.582Z,1578962111.582 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:11.582Z,1578962111.582 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9 2020-01-14T00:35:12.407Z,1578962112.407 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:12.407Z,1578962112.407 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10 2020-01-14T00:35:12.407Z,1578962112.407 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:12.431Z,1578962112.431 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:12.783Z,1578962112.783 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:12.783Z,1578962112.783 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10 2020-01-14T00:35:13.587Z,1578962113.587 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:13.587Z,1578962113.587 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11 2020-01-14T00:35:13.587Z,1578962113.587 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:13.613Z,1578962113.613 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:13.999Z,1578962113.999 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:13.999Z,1578962113.999 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11 2020-01-14T00:35:14.783Z,1578962114.783 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:14.783Z,1578962114.783 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12 2020-01-14T00:35:14.783Z,1578962114.783 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:14.792Z,1578962114.792 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:15.194Z,1578962115.194 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:15.194Z,1578962115.194 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12 2020-01-14T00:35:15.981Z,1578962115.981 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:15.981Z,1578962115.981 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13 2020-01-14T00:35:15.981Z,1578962115.981 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:15.991Z,1578962115.991 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:16.396Z,1578962116.396 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:16.396Z,1578962116.396 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13 2020-01-14T00:35:17.224Z,1578962117.224 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:17.229Z,1578962117.229 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14 2020-01-14T00:35:17.229Z,1578962117.229 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:17.246Z,1578962117.246 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:17.642Z,1578962117.642 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:17.642Z,1578962117.642 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14 2020-01-14T00:35:18.426Z,1578962118.426 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:18.426Z,1578962118.426 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15 2020-01-14T00:35:18.426Z,1578962118.426 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:18.436Z,1578962118.436 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:18.829Z,1578962118.829 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:18.829Z,1578962118.829 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15 2020-01-14T00:35:19.631Z,1578962119.631 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:19.631Z,1578962119.631 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16 2020-01-14T00:35:19.631Z,1578962119.631 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:19.649Z,1578962119.649 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:20.054Z,1578962120.054 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:20.054Z,1578962120.054 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16 2020-01-14T00:35:20.902Z,1578962120.902 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:20.902Z,1578962120.902 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17 2020-01-14T00:35:20.902Z,1578962120.902 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:20.912Z,1578962120.912 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:21.372Z,1578962121.372 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:21.372Z,1578962121.372 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17 2020-01-14T00:35:22.161Z,1578962122.161 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2020-01-14T00:35:22.161Z,1578962122.161 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 18 2020-01-14T00:35:22.161Z,1578962122.161 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-01-14T00:35:22.264Z,1578962122.264 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:22.670Z,1578962122.670 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-01-14T00:35:22.670Z,1578962122.670 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 18 2020-01-14T00:35:22.827Z,1578962122.827 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1578962176.000000 second 2020-01-14T00:35:34.563Z,1578962134.563 [CommandLine](IMPORTANT): got command show stack 2020-01-14T00:35:34.563Z,1578962134.563 [CommandLine](IMPORTANT): Behavior Stack: 2020-01-14T00:35:34.563Z,1578962134.563 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface 2020-01-14T00:35:34.563Z,1578962134.563 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B 2020-01-14T00:35:42.739Z,1578962142.739 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004945 2020-01-14T00:35:45.275Z,1578962145.275 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2020-01-14T00:35:45.515Z,1578962145.515 [Startup:StartupSatComms:B] Stopped 2020-01-14T00:35:45.515Z,1578962145.515 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2020-01-14T00:35:45.515Z,1578962145.515 [Startup:StartupSatComms] Stopped 2020-01-14T00:35:45.515Z,1578962145.515 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2020-01-14T00:35:45.518Z,1578962145.518 [Startup](INFO): Completed Startup 2020-01-14T00:35:45.518Z,1578962145.518 [MissionManager](INFO): Startup is completed. 2020-01-14T00:35:45.518Z,1578962145.518 [MissionManager](INFO): Uninitializing Mission Startup 2020-01-14T00:35:45.519Z,1578962145.519 [Startup] Stopped 2020-01-14T00:35:45.519Z,1578962145.519 [Startup](DEBUG): Aggregate::uninitialize Startup 2020-01-14T00:35:45.519Z,1578962145.519 [Startup:A.GoToSurface] Stopped 2020-01-14T00:35:45.519Z,1578962145.519 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:35:45.939Z,1578962145.939 [MissionManager](IMPORTANT): Started mission Default 2020-01-14T00:35:45.939Z,1578962145.939 [Default] Running Loop=1 2020-01-14T00:35:45.939Z,1578962145.939 [Default](DEBUG): Aggregate::initialize Default 2020-01-14T00:35:45.939Z,1578962145.939 [Default:B.GoToSurface] Running Loop=1 2020-01-14T00:35:45.940Z,1578962145.940 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:35:45.940Z,1578962145.940 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:35:45.940Z,1578962145.940 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:35:45.940Z,1578962145.940 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:35:45.949Z,1578962145.949 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:35:45.949Z,1578962145.949 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:35:45.950Z,1578962145.950 [Default:A.Wait] Running Loop=1 2020-01-14T00:35:45.950Z,1578962145.950 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:35:49.738Z,1578962149.738 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:35:49.738Z,1578962149.738 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:35:49.797Z,1578962149.797 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min 2020-01-14T00:35:49.805Z,1578962149.805 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count 2020-01-14T00:35:49.817Z,1578962149.817 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count 2020-01-14T00:35:49.845Z,1578962149.845 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count 2020-01-14T00:35:49.857Z,1578962149.857 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup 2020-01-14T00:35:49.858Z,1578962149.858 [DUSBL:A.Pitch](DEBUG): Construct. 2020-01-14T00:35:49.900Z,1578962149.900 [DUSBL:B.SetSpeed](DEBUG): Construct. 2020-01-14T00:35:49.960Z,1578962149.960 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait. 2020-01-14T00:35:49.992Z,1578962149.992 [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 90 2020-01-14T00:35:50.014Z,1578962150.014 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:35:50.372Z,1578962150.372 [Default] Stopped 2020-01-14T00:35:50.372Z,1578962150.372 [Default](DEBUG): Aggregate::uninitialize Default 2020-01-14T00:35:50.372Z,1578962150.372 [Default:A.Wait] Stopped 2020-01-14T00:35:50.372Z,1578962150.372 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:35:50.372Z,1578962150.372 [Default:B.GoToSurface] Stopped 2020-01-14T00:35:50.373Z,1578962150.373 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:35:50.373Z,1578962150.373 [MissionManager](IMPORTANT): Started mission DUSBL 2020-01-14T00:35:50.373Z,1578962150.373 [DUSBL] Running Loop=1 2020-01-14T00:35:50.373Z,1578962150.373 [DUSBL](DEBUG): Aggregate::initialize DUSBL 2020-01-14T00:35:50.373Z,1578962150.373 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:35:50.373Z,1578962150.373 [DUSBL:A.Pitch](DEBUG): Initialize. 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:B.SetSpeed](DEBUG): Initialize. 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:C] Running Loop=1 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:RequestRepeater] Running Loop=1 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2020-01-14T00:35:50.374Z,1578962150.374 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:35:50.375Z,1578962150.375 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:35:50.375Z,1578962150.375 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:35:50.376Z,1578962150.376 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range 2020-01-14T00:35:50.376Z,1578962150.376 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame 2020-01-14T00:35:50.377Z,1578962150.377 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:35:50.377Z,1578962150.377 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:35:51.261Z,1578962151.261 [DataOverHttps](INFO): Sending 239 bytes from file Logs/20200113T235326/Courier0004.lzma 2020-01-14T00:35:52.324Z,1578962152.324 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:35:52.753Z,1578962152.753 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:35:53.269Z,1578962153.269 [DataOverHttps](INFO): Moved sent file to Logs/20200113T235326/Courier0004.lzma.bak 2020-01-14T00:35:53.270Z,1578962153.270 [DataOverHttps](INFO): SBD MOMSN=12192059 2020-01-14T00:35:53.540Z,1578962153.540 [Micromodem](INFO): Nmea in: $SNTTA,,,,,003553.26*5A 2020-01-14T00:35:55.961Z,1578962155.961 [DUSBL_Hydroid](ERROR): No response from remote modem. 2020-01-14T00:35:56.775Z,1578962156.775 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:35:57.176Z,1578962157.176 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:35:57.987Z,1578962157.987 [Micromodem](INFO): Nmea in: $SNTTA,,,,,003557.71*5C 2020-01-14T00:36:00.402Z,1578962160.402 [DUSBL_Hydroid](ERROR): No response from remote modem. 2020-01-14T00:36:01.216Z,1578962161.216 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:36:01.616Z,1578962161.616 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:36:02.427Z,1578962162.427 [Micromodem](INFO): Nmea in: $SNTTA,,,,,003602.15*5D 2020-01-14T00:36:03.154Z,1578962163.154 [CommandLine](IMPORTANT): got command stop 2020-01-14T00:36:03.155Z,1578962163.155 [CommandLine](IMPORTANT): Scheduling is paused 2020-01-14T00:36:03.155Z,1578962163.155 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop 2020-01-14T00:36:03.315Z,1578962163.315 [MissionManager](INFO): MissionManager is completed. 2020-01-14T00:36:03.316Z,1578962163.316 [MissionManager](INFO): Uninitializing Mission DUSBL 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:A.Pitch] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:B.SetSpeed] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:B.SetSpeed](DEBUG): Uninitialize. 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:C] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:RequestRepeater] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:RequestRepeater:A] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:RequestRepeater:B] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:RequestRepeater:C.Wait] Stopped 2020-01-14T00:36:03.316Z,1578962163.316 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:36:03.673Z,1578962163.673 [MissionManager](IMPORTANT): Started mission Default 2020-01-14T00:36:03.674Z,1578962163.674 [Default] Running Loop=1 2020-01-14T00:36:03.674Z,1578962163.674 [Default](DEBUG): Aggregate::initialize Default 2020-01-14T00:36:03.674Z,1578962163.674 [Default:B.GoToSurface] Running Loop=1 2020-01-14T00:36:03.674Z,1578962163.674 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:36:03.674Z,1578962163.674 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:36:03.675Z,1578962163.675 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:36:03.675Z,1578962163.675 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:36:03.675Z,1578962163.675 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:36:03.675Z,1578962163.675 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:36:03.676Z,1578962163.676 [Default:A.Wait] Running Loop=1 2020-01-14T00:36:03.676Z,1578962163.676 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:36:12.728Z,1578962172.728 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1578962176.000000 second 2020-01-14T00:36:17.008Z,1578962177.008 [Default:A.Wait](INFO): Done Waiting. 2020-01-14T00:36:17.008Z,1578962177.008 [Default:A.Wait] Stopped 2020-01-14T00:36:17.008Z,1578962177.008 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:36:17.405Z,1578962177.405 [Default:CheckIn] Running Loop=1 2020-01-14T00:36:17.406Z,1578962177.406 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-01-14T00:36:17.406Z,1578962177.406 [Default:CheckIn:Read_GPS] Running Loop=1 2020-01-14T00:36:17.809Z,1578962177.809 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2020-01-14T00:36:39.250Z,1578962199.250 [CommandLine](IMPORTANT): got command run ./Missions/Default.xml 2020-01-14T00:36:39.251Z,1578962199.251 [MissionManager](INFO): Loading Mission: ./Missions/Default.xml 2020-01-14T00:36:39.319Z,1578962199.319 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2020-01-14T00:36:39.320Z,1578962199.320 [Default:A.Wait](DEBUG): Construct Wait. 2020-01-14T00:36:39.329Z,1578962199.329 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2020-01-14T00:36:39.350Z,1578962199.350 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2020-01-14T00:36:39.352Z,1578962199.352 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2020-01-14T00:36:39.364Z,1578962199.364 [Default:E.Execute](DEBUG): Construct Execute. 2020-01-14T00:36:39.373Z,1578962199.373 [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 2020-01-14T00:36:39.378Z,1578962199.378 [CommandLine](IMPORTANT): Running ./Missions/Default.xml 2020-01-14T00:36:39.620Z,1578962199.620 [Default] Stopped 2020-01-14T00:36:39.620Z,1578962199.620 [Default](DEBUG): Aggregate::uninitialize Default 2020-01-14T00:36:39.637Z,1578962199.637 [Default:B.GoToSurface] Stopped 2020-01-14T00:36:39.637Z,1578962199.637 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:36:39.637Z,1578962199.637 [Default:CheckIn] Stopped 2020-01-14T00:36:39.637Z,1578962199.637 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-01-14T00:36:39.637Z,1578962199.637 [Default:CheckIn:Read_GPS] Stopped 2020-01-14T00:36:39.637Z,1578962199.637 [MissionManager](IMPORTANT): Started mission Default 2020-01-14T00:36:39.637Z,1578962199.637 [Default] Running Loop=1 2020-01-14T00:36:39.637Z,1578962199.637 [Default](DEBUG): Aggregate::initialize Default 2020-01-14T00:36:39.638Z,1578962199.638 [Default:B.GoToSurface] Running Loop=1 2020-01-14T00:36:39.638Z,1578962199.638 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:36:39.638Z,1578962199.638 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:36:39.638Z,1578962199.638 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:36:39.638Z,1578962199.638 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:36:39.639Z,1578962199.639 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:36:39.639Z,1578962199.639 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:36:39.639Z,1578962199.639 [Default:A.Wait] Running Loop=1 2020-01-14T00:36:39.640Z,1578962199.640 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:36:52.162Z,1578962212.162 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1578962176.000000 second 2020-01-14T00:36:52.952Z,1578962212.952 [Default:A.Wait](INFO): Done Waiting. 2020-01-14T00:36:52.952Z,1578962212.952 [Default:A.Wait] Stopped 2020-01-14T00:36:52.952Z,1578962212.952 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:36:53.373Z,1578962213.373 [Default:CheckIn] Running Loop=1 2020-01-14T00:36:53.373Z,1578962213.373 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-01-14T00:36:53.373Z,1578962213.373 [Default:CheckIn:Read_GPS] Running Loop=1 2020-01-14T00:36:53.776Z,1578962213.776 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2020-01-14T00:37:14.387Z,1578962234.387 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2020-01-14T00:37:26.115Z,1578962246.115 [CommandLine](IMPORTANT): got command failComponent 2020-01-14T00:37:26.116Z,1578962246.116 [CommandLine](IMPORTANT): Failed components: 2020-01-14T00:37:26.116Z,1578962246.116 [CommandLine](IMPORTANT): DropWeight: Hardware Fault 2020-01-14T00:37:32.435Z,1578962252.435 [CommandLine](IMPORTANT): got command failComponent none DropWeight 2020-01-14T00:37:32.435Z,1578962252.435 [DropWeight] No Fault, FailCount= 1 2020-01-14T00:37:32.435Z,1578962252.435 [CommandLine](IMPORTANT): DropWeight failureMode is No Fault 2020-01-14T00:37:36.986Z,1578962256.986 [CommandLine](IMPORTANT): got command failComponent hardware DropWeight 2020-01-14T00:37:36.987Z,1578962256.987 [DropWeight] Hardware Fault, FailCount= 2 2020-01-14T00:37:36.987Z,1578962256.987 [DropWeight](ERROR): Hardware Fault 2020-01-14T00:37:36.987Z,1578962256.987 [CommandLine](IMPORTANT): DropWeight failureMode is Hardware Fault 2020-01-14T00:37:37.105Z,1578962257.105 [CBIT](ERROR): Hardware Fault in component: DropWeight 2020-01-14T00:37:37.105Z,1578962257.105 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2020-01-14T00:37:37.466Z,1578962257.466 [CommandLine](FAULT): Scheduling is paused 2020-01-14T00:37:37.466Z,1578962257.466 [CBIT](INFO): Critical error at 20200114T003737 2020-01-14T00:37:37.466Z,1578962257.466 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2020-01-14T00:37:37.849Z,1578962257.849 [MissionManager](INFO): MissionManager is completed. 2020-01-14T00:37:37.849Z,1578962257.849 [MissionManager](INFO): Uninitializing Mission Default 2020-01-14T00:37:37.849Z,1578962257.849 [Default] Stopped 2020-01-14T00:37:37.850Z,1578962257.850 [Default](DEBUG): Aggregate::uninitialize Default 2020-01-14T00:37:37.850Z,1578962257.850 [Default:B.GoToSurface] Stopped 2020-01-14T00:37:37.850Z,1578962257.850 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:37:37.850Z,1578962257.850 [Default:CheckIn] Stopped 2020-01-14T00:37:37.850Z,1578962257.850 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-01-14T00:37:37.850Z,1578962257.850 [Default:CheckIn:Read_GPS] Stopped 2020-01-14T00:37:38.294Z,1578962258.294 [MissionManager](IMPORTANT): Started mission Default 2020-01-14T00:37:38.294Z,1578962258.294 [Default] Running Loop=1 2020-01-14T00:37:38.294Z,1578962258.294 [Default](DEBUG): Aggregate::initialize Default 2020-01-14T00:37:38.294Z,1578962258.294 [Default:B.GoToSurface] Running Loop=1 2020-01-14T00:37:38.294Z,1578962258.294 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:37:38.295Z,1578962258.295 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:37:38.295Z,1578962258.295 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:37:38.295Z,1578962258.295 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:37:38.296Z,1578962258.296 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:37:38.296Z,1578962258.296 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:37:38.296Z,1578962258.296 [Default:A.Wait] Running Loop=1 2020-01-14T00:37:38.296Z,1578962258.296 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:37:51.407Z,1578962271.407 [Default:A.Wait](INFO): Done Waiting. 2020-01-14T00:37:51.407Z,1578962271.407 [Default:A.Wait] Stopped 2020-01-14T00:37:51.407Z,1578962271.407 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:37:51.801Z,1578962271.801 [Default:CheckIn] Running Loop=1 2020-01-14T00:37:51.801Z,1578962271.801 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-01-14T00:37:51.802Z,1578962271.802 [Default:CheckIn:Read_GPS] Running Loop=1 2020-01-14T00:38:51.204Z,1578962331.204 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2020-01-14T00:38:51.204Z,1578962331.204 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-32BE,-32768,-32768,-32768,V 2020-01-14T00:38:54.783Z,1578962334.783 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-01-14T00:40:22.904Z,1578962422.904 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2020-01-14T00:40:22.907Z,1578962422.907 [BPC1](INFO): Received data from all battery sticks. 2020-01-14T00:42:07.496Z,1578962527.496 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004207.00,A,3648.16416,N,12147.28446,W,0.408,344.77,140120,,,A*74 2020-01-14T00:42:07.499Z,1578962527.499 [NAL9602](INFO): GPS fix at 20200114T004207: (36.802736, -121.788074) 2020-01-14T00:42:07.569Z,1578962527.569 [Default:CheckIn:Read_GPS] Stopped 2020-01-14T00:42:07.570Z,1578962527.570 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-01-14T00:42:07.953Z,1578962527.953 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-01-14T00:42:08.296Z,1578962528.296 [Micromodem](ERROR): Buffer fill timout failure. 2020-01-14T00:42:09.672Z,1578962529.672 [Micromodem](INFO): Outgoing frame #1, 64 bytes: F6021D5E070000005D00000400320000000000000000151D80030C5669C010E4BA2AD1C8BB449FEA8238A4A22C3134D1D9A050A3B545DFB474CBAEE3F0071F19 2020-01-14T00:42:09.672Z,1578962529.672 [Micromodem](INFO): Outgoing frame #2, 4 bytes: 49230C00 2020-01-14T00:42:09.672Z,1578962529.672 [Micromodem](INFO): Nmea out: $CCCYC,0,1,12,1,0,2*68 2020-01-14T00:42:09.837Z,1578962529.837 [Micromodem](INFO): Nmea in: $CACYC,0,1,12,1,0,2*6A 2020-01-14T00:42:10.226Z,1578962530.226 [Micromodem](INFO): Nmea in: $CADRQ,004210,1,12,0,64,1*73 2020-01-14T00:42:10.227Z,1578962530.227 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,F6021D5E070000005D00000400320000000000000000151D80030C5669C010E4BA2AD1C8BB449FEA8238A4A22C3134D1D9A050A3B545DFB474CBAEE3F0071F19*4D 2020-01-14T00:42:10.610Z,1578962530.610 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:42:11.018Z,1578962531.018 [Micromodem](INFO): Nmea in: $CADRQ,004211,1,12,0,64,2*71 2020-01-14T00:42:11.019Z,1578962531.019 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,49230C00*34 2020-01-14T00:42:11.431Z,1578962531.431 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,4*7D 2020-01-14T00:42:11.822Z,1578962531.822 [Micromodem](INFO): Nmea in: $CATXP,68*7C 2020-01-14T00:42:14.258Z,1578962534.258 [Micromodem](INFO): Nmea in: $CATXF,68*6A 2020-01-14T00:42:15.467Z,1578962535.467 [Micromodem](INFO): Nmea in: $CAXST,6,20200114,004211.921249,3,0,200,4000,10000,1,1,12,1,2,2,3,68*49 2020-01-14T00:42:15.534Z,1578962535.534 [DataOverHttps](INFO): Sending 60 bytes from file Logs/20200113T235326/Courier0007.lzma 2020-01-14T00:42:17.534Z,1578962537.534 [DataOverHttps](INFO): Moved sent file to Logs/20200113T235326/Courier0007.lzma.bak 2020-01-14T00:42:17.534Z,1578962537.534 [DataOverHttps](INFO): SBD MOMSN=12192061 2020-01-14T00:42:40.115Z,1578962560.115 [NAL9602](INFO): Not Powering down - fast GPS 2020-01-14T00:42:40.821Z,1578962560.821 [DataOverHttps](INFO): Sending 341 bytes from file Logs/20200114T003018/Courier0000.lzma 2020-01-14T00:42:42.794Z,1578962562.794 [DataOverHttps](INFO): Moved sent file to Logs/20200114T003018/Courier0000.lzma.bak 2020-01-14T00:42:42.794Z,1578962562.794 [DataOverHttps](INFO): SBD MOMSN=12192063 2020-01-14T00:42:59.204Z,1578962579.204 [DataOverHttps](INFO): Sending 321 bytes from file Logs/20200114T003303/Courier0000.lzma 2020-01-14T00:43:01.165Z,1578962581.165 [DataOverHttps](INFO): Moved sent file to Logs/20200114T003303/Courier0000.lzma.bak 2020-01-14T00:43:01.166Z,1578962581.166 [DataOverHttps](INFO): SBD MOMSN=12192069 2020-01-14T00:43:14.851Z,1578962594.851 [Micromodem](ERROR): Buffer fill timout failure. 2020-01-14T00:43:16.405Z,1578962596.405 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 3F0C1D5E040002005D00000400B30400000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567 2020-01-14T00:43:16.406Z,1578962596.406 [Micromodem](INFO): Outgoing frame #2, 64 bytes: 266CC0E6F1A517638CB0C0B8BE372A0B00F6D61E05F93094AA77DEFC753FE61F094712E1114D8E0AD7B6106F0F7B016211E5CA62E332602D1D41ACBF7CDB6A31 2020-01-14T00:43:16.406Z,1578962596.406 [Micromodem](INFO): Outgoing frame #3, 64 bytes: 6612EED8A8416AE25E31B4E18619E5C1F90902C505781770CFDD053F3D92B2892521A612D82BE005FC89184DBDB3C66EC80CC08EDF2155180632FCB869E018D3 2020-01-14T00:43:16.407Z,1578962596.407 [Micromodem](INFO): Nmea out: $CCCYC,0,1,12,1,0,3*69 2020-01-14T00:43:16.639Z,1578962596.639 [Micromodem](INFO): Nmea in: $CACYC,0,1,12,1,0,3*6B 2020-01-14T00:43:17.007Z,1578962597.007 [Micromodem](INFO): Nmea in: $CADRQ,004317,1,12,0,64,1*75 2020-01-14T00:43:17.007Z,1578962597.007 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,3F0C1D5E040002005D00000400B30400000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*41 2020-01-14T00:43:17.406Z,1578962597.406 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:43:17.810Z,1578962597.810 [Micromodem](INFO): Nmea in: $CADRQ,004317,1,12,0,64,2*76 2020-01-14T00:43:17.811Z,1578962597.811 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,266CC0E6F1A517638CB0C0B8BE372A0B00F6D61E05F93094AA77DEFC753FE61F094712E1114D8E0AD7B6106F0F7B016211E5CA62E332602D1D41ACBF7CDB6A31*3C 2020-01-14T00:43:18.218Z,1578962598.218 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:43:18.619Z,1578962598.619 [Micromodem](INFO): Nmea in: $CADRQ,004318,1,12,0,64,3*78 2020-01-14T00:43:18.619Z,1578962598.619 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,6612EED8A8416AE25E31B4E18619E5C1F90902C505781770CFDD053F3D92B2892521A612D82BE005FC89184DBDB3C66EC80CC08EDF2155180632FCB869E018D3*3F 2020-01-14T00:43:19.023Z,1578962599.023 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:43:19.431Z,1578962599.431 [Micromodem](INFO): Nmea in: $CATXP,192*48 2020-01-14T00:43:19.473Z,1578962599.473 [DataOverHttps](INFO): Sending 434 bytes from file Logs/20200114T003303/Courier0004.lzma 2020-01-14T00:43:21.478Z,1578962601.478 [DataOverHttps](INFO): Moved sent file to Logs/20200114T003303/Courier0004.lzma.bak 2020-01-14T00:43:21.479Z,1578962601.479 [DataOverHttps](INFO): SBD MOMSN=12192074 2020-01-14T00:43:23.062Z,1578962603.062 [Micromodem](INFO): Nmea in: $CATXF,192*5E 2020-01-14T00:43:23.471Z,1578962603.471 [Micromodem](INFO): Nmea in: $CAXST,6,20200114,004319.600737,3,0,200,4000,10000,1,1,12,1,3,3,3,192*74 2020-01-14T00:43:24.281Z,1578962604.281 [Micromodem](INFO): Nmea in: $CAACK,12,1,1,1*79 2020-01-14T00:43:24.680Z,1578962604.680 [Micromodem](INFO): Nmea in: $CAACK,12,1,2,1*7A 2020-01-14T00:43:25.083Z,1578962605.083 [Micromodem](INFO): Nmea in: $CAACK,12,1,3,1*7B 2020-01-14T00:43:25.084Z,1578962605.084 [Micromodem](INFO): Sent 184 bytes from file Logs/20200114T003303/Courier0004.lzma.parts 2020-01-14T00:43:25.084Z,1578962605.084 [Micromodem](INFO): Packets left to send: 2 2020-01-14T00:43:25.494Z,1578962605.494 [Micromodem](INFO): Nmea in: $CACST,6,0,20200114004324.162402,06,118,20,0091,0150,89,01,01,00,04,1,012,001,0,4,1,0,150,17.2,7.00,18,-4.00,-01,0.00,27,10000,4000*60 2020-01-14T00:43:26.451Z,1578962606.451 [Default:CheckIn:Read_Iridium] Stopped 2020-01-14T00:43:26.452Z,1578962606.452 [Default:CheckIn:C.Wait] Running Loop=1 2020-01-14T00:43:26.452Z,1578962606.452 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:43:40.586Z,1578962620.586 [DataOverHttps](INFO): Sending 98 bytes from file Logs/20200110T181144/Express0005.lzma 2020-01-14T00:43:42.590Z,1578962622.590 [DataOverHttps](INFO): Moved sent file to Logs/20200110T181144/Express0005.lzma.bak 2020-01-14T00:43:42.590Z,1578962622.590 [DataOverHttps](INFO): SBD MOMSN=12192078 2020-01-14T00:45:05.902Z,1578962705.902 [CommandLine](IMPORTANT): got command failComponent 2020-01-14T00:45:05.902Z,1578962705.902 [CommandLine](IMPORTANT): Failed components: 2020-01-14T00:45:05.902Z,1578962705.902 [CommandLine](IMPORTANT): DropWeight: Hardware Fault 2020-01-14T00:45:07.271Z,1578962707.271 [CommandLine](IMPORTANT): got command failComponent 2020-01-14T00:45:07.271Z,1578962707.271 [CommandLine](IMPORTANT): Failed components: 2020-01-14T00:45:07.271Z,1578962707.271 [CommandLine](IMPORTANT): DropWeight: Hardware Fault 2020-01-14T00:45:24.538Z,1578962724.538 [CommandLine](IMPORTANT): got command show variable address 2020-01-14T00:45:24.540Z,1578962724.540 [CommandLine](IMPORTANT): acoustic_contact_address (unknown) 2020-01-14T00:45:24.721Z,1578962724.721 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.localAddress (count) 2020-01-14T00:45:24.721Z,1578962724.721 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.sbdAddress (enum) 2020-01-14T00:45:24.722Z,1578962724.722 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.transponderAddress (enum) 2020-01-14T00:45:24.724Z,1578962724.724 [CommandLine](IMPORTANT): DAT.localAddress (count) 2020-01-14T00:45:24.724Z,1578962724.724 [CommandLine](IMPORTANT): DAT.sbdAddress (enum) 2020-01-14T00:45:24.729Z,1578962724.729 [CommandLine](IMPORTANT): DAT.transponderAddress (enum) 2020-01-14T00:45:24.732Z,1578962724.732 [CommandLine](IMPORTANT): Micromodem.localAddress (enum) 2020-01-14T00:45:24.732Z,1578962724.732 [CommandLine](IMPORTANT): Micromodem.destinationAddress (enum) 2020-01-14T00:45:24.842Z,1578962724.842 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum) 2020-01-14T00:45:24.843Z,1578962724.843 [CommandLine](IMPORTANT): Micromodem.remote_address (count) 2020-01-14T00:45:24.843Z,1578962724.843 [CommandLine](IMPORTANT): Micromodem.local_address (count) 2020-01-14T00:45:34.945Z,1578962734.945 [CommandLine](IMPORTANT): got command get Micromodem.localAddress 2020-01-14T00:45:34.946Z,1578962734.946 [CommandLine](IMPORTANT): Micromodem.localAddress 1 enum 2020-01-14T00:45:42.114Z,1578962742.114 [CommandLine](IMPORTANT): got command get Micromodem.destinationAddress 2020-01-14T00:45:42.114Z,1578962742.114 [CommandLine](IMPORTANT): Micromodem.destinationAddress 12 enum 2020-01-14T00:48:26.716Z,1578962906.716 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-01-14T00:48:26.716Z,1578962906.716 [Default:CheckIn:C.Wait] Stopped 2020-01-14T00:48:26.716Z,1578962906.716 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:48:26.716Z,1578962906.716 [Default:CheckIn:D] Running Loop=1 2020-01-14T00:48:27.114Z,1578962907.114 [Default:CheckIn:D] Stopped 2020-01-14T00:48:27.114Z,1578962907.114 [Default:CheckIn:E] Running Loop=1 2020-01-14T00:48:27.532Z,1578962907.532 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.813660 min 2020-01-14T00:48:27.533Z,1578962907.533 [Default:CheckIn:E] Stopped 2020-01-14T00:48:27.533Z,1578962907.533 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-01-14T00:48:27.533Z,1578962907.533 [Default:CheckIn] Stopped 2020-01-14T00:48:27.533Z,1578962907.533 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-01-14T00:48:27.533Z,1578962907.533 [Default:CheckIn](INFO): Running loop #2 2020-01-14T00:48:27.533Z,1578962907.533 [Default:CheckIn] Running Loop=2 2020-01-14T00:48:27.533Z,1578962907.533 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-01-14T00:48:27.534Z,1578962907.534 [Default:CheckIn:Read_GPS] Running Loop=1 2020-01-14T00:48:29.511Z,1578962909.511 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004829.00,A,3648.16492,N,12147.28393,W,0.389,344.77,140120,,,A*7F 2020-01-14T00:48:29.513Z,1578962909.513 [NAL9602](INFO): GPS fix at 20200114T004829: (36.802749, -121.788066) 2020-01-14T00:48:29.547Z,1578962909.547 [Default:CheckIn:Read_GPS] Stopped 2020-01-14T00:48:29.547Z,1578962909.547 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-01-14T00:48:31.305Z,1578962911.305 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 3F0C1D5E070000005D00000400610000000000000000151D80030C5669C08C34EE62235E74AA63AF7A11F0459B08B720A00AD45BCFF03C1A7E10D61D6C52867D 2020-01-14T00:48:31.306Z,1578962911.306 [Micromodem](INFO): Outgoing frame #2, 39 bytes: 677C678EC94EBBDA6F4005FF9FA95CDEB7274693E47A545679EA0FEA5AE47A34BD3EE4286B1000 2020-01-14T00:48:31.306Z,1578962911.306 [Micromodem](INFO): Nmea out: $CCCYC,0,1,12,1,0,2*68 2020-01-14T00:48:31.538Z,1578962911.538 [Micromodem](INFO): Nmea in: $CACYC,0,1,12,1,0,2*6A 2020-01-14T00:48:31.899Z,1578962911.899 [Micromodem](INFO): Nmea in: $CADRQ,004832,1,12,0,64,1*79 2020-01-14T00:48:31.900Z,1578962911.900 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,3F0C1D5E070000005D00000400610000000000000000151D80030C5669C08C34EE62235E74AA63AF7A11F0459B08B720A00AD45BCFF03C1A7E10D61D6C52867D*49 2020-01-14T00:48:32.298Z,1578962912.298 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:48:32.706Z,1578962912.706 [Micromodem](INFO): Nmea in: $CADRQ,004832,1,12,0,64,2*7A 2020-01-14T00:48:32.707Z,1578962912.707 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,677C678EC94EBBDA6F4005FF9FA95CDEB7274693E47A545679EA0FEA5AE47A34BD3EE4286B1000*42 2020-01-14T00:48:33.110Z,1578962913.110 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,39*43 2020-01-14T00:48:33.514Z,1578962913.514 [Micromodem](INFO): Nmea in: $CATXP,103*40 2020-01-14T00:48:35.939Z,1578962915.939 [Micromodem](INFO): Nmea in: $CATXF,103*56 2020-01-14T00:48:37.151Z,1578962917.151 [Micromodem](INFO): Nmea in: $CAXST,6,20200114,004833.650881,3,0,200,4000,10000,1,1,12,1,2,2,3,103*78 2020-01-14T00:48:38.363Z,1578962918.363 [Micromodem](INFO): Nmea in: $CAACK,12,1,1,1*79 2020-01-14T00:48:38.369Z,1578962918.369 [DataOverHttps](INFO): Sending 95 bytes from file Logs/20200114T003303/Courier0007.lzma 2020-01-14T00:48:38.767Z,1578962918.767 [Micromodem](INFO): Nmea in: $CAACK,12,1,2,1*7A 2020-01-14T00:48:38.768Z,1578962918.768 [Micromodem](INFO): Sent 95 bytes from file Logs/20200114T003303/Courier0007.lzma.parts 2020-01-14T00:48:38.768Z,1578962918.768 [Micromodem](INFO): Packets left to send: 0 2020-01-14T00:48:39.196Z,1578962919.196 [Micromodem](INFO): Nmea in: $CACST,6,0,20200114004838.195638,06,165,22,0119,0150,119,01,01,00,03,1,012,001,0,4,1,0,150,18.7,6.00,10,-3.00,-01,0.00,31,10000,4000*50 2020-01-14T00:48:40.325Z,1578962920.325 [Default:CheckIn:Read_Iridium] Stopped 2020-01-14T00:48:40.325Z,1578962920.325 [Default:CheckIn:C.Wait] Running Loop=1 2020-01-14T00:48:40.325Z,1578962920.325 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:48:41.043Z,1578962921.043 [DataOverHttps](FAULT): Server acknowledged file Logs/20200114T003303/Courier0007.lzma, notLogs/20200110T181518/Express0001.lzma 2020-01-14T00:48:41.043Z,1578962921.043 [DataOverHttps](INFO): SBD MOMSN=12192081 2020-01-14T00:48:50.646Z,1578962930.646 [CommandLine](IMPORTANT): got command show variable detectionThreshold 2020-01-14T00:48:50.710Z,1578962930.710 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count) 2020-01-14T00:48:56.170Z,1578962936.170 [CommandLine](IMPORTANT): got command get DUSBL_Hydroid.detectionThreshold 2020-01-14T00:48:56.170Z,1578962936.170 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold 25 count 2020-01-14T00:49:00.158Z,1578962940.158 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2020-01-14T00:49:00.241Z,1578962940.241 [NAL9602](FAULT): received: +CSQ:0 OK 2020-01-14T00:49:00.241Z,1578962940.241 [NAL9602] Data Fault, FailCount= 1 2020-01-14T00:49:00.241Z,1578962940.241 [NAL9602](ERROR): Data Fault 2020-01-14T00:49:00.340Z,1578962940.340 [CBIT](ERROR): Data Fault in component: NAL9602 2020-01-14T00:49:00.550Z,1578962940.550 [NAL9602](INFO): Powering down 2020-01-14T00:49:01.412Z,1578962941.412 [CBIT](INFO): Clearing failed state for component NAL9602 2020-01-14T00:49:01.412Z,1578962941.412 [NAL9602] No Fault, FailCount= 1 2020-01-14T00:49:03.554Z,1578962943.554 [CommandLine](IMPORTANT): got command show variable range 2020-01-14T00:49:03.555Z,1578962943.555 [CommandLine](IMPORTANT): acoustic_contact_range (unknown) 2020-01-14T00:49:03.639Z,1578962943.639 [CommandLine](IMPORTANT): BR_Ping1D.minRange (meter) 2020-01-14T00:49:03.640Z,1578962943.640 [CommandLine](IMPORTANT): BR_Ping1D.maxRange (meter) 2020-01-14T00:49:03.656Z,1578962943.656 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter) 2020-01-14T00:49:03.676Z,1578962943.676 [CommandLine](IMPORTANT): Micromodem.range_request (count) 2020-01-14T00:49:03.677Z,1578962943.677 [CommandLine](IMPORTANT): Micromodem.range (meter) 2020-01-14T00:49:03.680Z,1578962943.680 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter) 2020-01-14T00:49:03.680Z,1578962943.680 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter) 2020-01-14T00:49:03.680Z,1578962943.680 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter) 2020-01-14T00:49:03.681Z,1578962943.681 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter) 2020-01-14T00:49:09.301Z,1578962949.301 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.acoustic_contact_range 2020-01-14T00:49:15.927Z,1578962955.927 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2020-01-14T00:49:15.927Z,1578962955.927 [RDI_Pathfinder](ERROR): Failed to parse: :TS,20011318020960,35.0, -0.,1448.9, 0 2020-01-14T00:49:22.150Z,1578962962.150 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:49:22.150Z,1578962962.150 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:49:22.241Z,1578962962.241 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min 2020-01-14T00:49:22.243Z,1578962962.243 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count 2020-01-14T00:49:22.249Z,1578962962.249 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count 2020-01-14T00:49:22.251Z,1578962962.251 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count 2020-01-14T00:49:22.257Z,1578962962.257 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup 2020-01-14T00:49:22.258Z,1578962962.258 [DUSBL:A.Pitch](DEBUG): Construct. 2020-01-14T00:49:22.266Z,1578962962.266 [DUSBL:B.SetSpeed](DEBUG): Construct. 2020-01-14T00:49:22.301Z,1578962962.301 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait. 2020-01-14T00:49:22.309Z,1578962962.309 [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 90 2020-01-14T00:49:22.311Z,1578962962.311 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:49:22.424Z,1578962962.424 [Default] Stopped 2020-01-14T00:49:22.424Z,1578962962.424 [Default](DEBUG): Aggregate::uninitialize Default 2020-01-14T00:49:22.424Z,1578962962.424 [Default:B.GoToSurface] Stopped 2020-01-14T00:49:22.424Z,1578962962.424 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:49:22.424Z,1578962962.424 [Default:CheckIn] Stopped 2020-01-14T00:49:22.424Z,1578962962.424 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-01-14T00:49:22.424Z,1578962962.424 [Default:CheckIn:C.Wait] Stopped 2020-01-14T00:49:22.424Z,1578962962.424 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:49:22.433Z,1578962962.433 [MissionManager](IMPORTANT): Started mission DUSBL 2020-01-14T00:49:22.433Z,1578962962.433 [DUSBL] Running Loop=1 2020-01-14T00:49:22.433Z,1578962962.433 [DUSBL](DEBUG): Aggregate::initialize DUSBL 2020-01-14T00:49:22.434Z,1578962962.434 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:49:22.434Z,1578962962.434 [DUSBL:A.Pitch](DEBUG): Initialize. 2020-01-14T00:49:22.434Z,1578962962.434 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:49:22.434Z,1578962962.434 [DUSBL:B.SetSpeed](DEBUG): Initialize. 2020-01-14T00:49:22.434Z,1578962962.434 [DUSBL:C] Running Loop=1 2020-01-14T00:49:22.434Z,1578962962.434 [DUSBL:RequestRepeater] Running Loop=1 2020-01-14T00:49:22.434Z,1578962962.434 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2020-01-14T00:49:22.435Z,1578962962.435 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:49:22.435Z,1578962962.435 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:49:22.435Z,1578962962.435 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2020-01-14T00:49:22.435Z,1578962962.435 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:49:22.435Z,1578962962.435 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:49:22.435Z,1578962962.435 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:49:22.439Z,1578962962.439 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range 2020-01-14T00:49:22.439Z,1578962962.439 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame 2020-01-14T00:49:22.439Z,1578962962.439 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:49:22.441Z,1578962962.441 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:49:24.386Z,1578962964.386 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:49:24.802Z,1578962964.802 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:49:24.924Z,1578962964.924 [DataOverHttps](INFO): Sending 1574 bytes from file Logs/20200110T181518/Express0001.lzma 2020-01-14T00:49:25.607Z,1578962965.607 [Micromodem](INFO): Nmea in: $SNTTA,,,,,004925.32*55 2020-01-14T00:49:26.926Z,1578962966.926 [DataOverHttps](INFO): Moved sent file to Logs/20200110T181518/Express0001.lzma.bak 2020-01-14T00:49:26.926Z,1578962966.926 [DataOverHttps](INFO): SBD MOMSN=12192086 2020-01-14T00:49:28.026Z,1578962968.026 [DUSBL_Hydroid](ERROR): No response from remote modem. 2020-01-14T00:49:28.847Z,1578962968.847 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:49:29.257Z,1578962969.257 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:49:30.051Z,1578962970.051 [Micromodem](INFO): Nmea in: $SNTTA,,,,,004929.78*57 2020-01-14T00:49:30.851Z,1578962970.851 [NAL9602](INFO): Powering up NAL9602 2020-01-14T00:49:32.474Z,1578962972.474 [DUSBL_Hydroid](ERROR): No response from remote modem. 2020-01-14T00:49:33.279Z,1578962973.279 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:49:33.684Z,1578962973.684 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:49:34.490Z,1578962974.490 [Micromodem](INFO): Nmea in: $SNTTA,,,,,004934.22*54 2020-01-14T00:49:36.908Z,1578962976.908 [DUSBL_Hydroid](ERROR): No response from remote modem. 2020-01-14T00:49:37.717Z,1578962977.717 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:49:38.124Z,1578962978.124 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:49:38.939Z,1578962978.939 [Micromodem](INFO): Nmea in: $SNTTA,,,,,004938.66*58 2020-01-14T00:49:41.361Z,1578962981.361 [DUSBL_Hydroid](ERROR): No response from remote modem. 2020-01-14T00:49:41.776Z,1578962981.776 [NAL9602](INFO): NAL9602 initialized 2020-01-14T00:49:42.165Z,1578962982.165 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:49:42.572Z,1578962982.572 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:49:43.385Z,1578962983.385 [Micromodem](INFO): Nmea in: $SNTTA,,,,,004943.10*55 2020-01-14T00:49:45.527Z,1578962985.527 [CommandLine](IMPORTANT): got command stop 2020-01-14T00:49:45.527Z,1578962985.527 [CommandLine](IMPORTANT): Scheduling is paused 2020-01-14T00:49:45.528Z,1578962985.528 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop 2020-01-14T00:49:45.798Z,1578962985.798 [DUSBL_Hydroid](ERROR): No response from remote modem. 2020-01-14T00:49:45.867Z,1578962985.867 [MissionManager](INFO): MissionManager is completed. 2020-01-14T00:49:45.867Z,1578962985.867 [MissionManager](INFO): Uninitializing Mission DUSBL 2020-01-14T00:49:45.867Z,1578962985.867 [DUSBL] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:A.Pitch] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:B.SetSpeed] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:B.SetSpeed](DEBUG): Uninitialize. 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:C] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:RequestRepeater] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:RequestRepeater:A] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:RequestRepeater:B] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:RequestRepeater:C.Wait] Stopped 2020-01-14T00:49:45.868Z,1578962985.868 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:49:46.234Z,1578962986.234 [MissionManager](IMPORTANT): Started mission Default 2020-01-14T00:49:46.235Z,1578962986.235 [Default] Running Loop=1 2020-01-14T00:49:46.235Z,1578962986.235 [Default](DEBUG): Aggregate::initialize Default 2020-01-14T00:49:46.235Z,1578962986.235 [Default:B.GoToSurface] Running Loop=1 2020-01-14T00:49:46.235Z,1578962986.235 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:49:46.235Z,1578962986.235 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:49:46.235Z,1578962986.235 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:49:46.236Z,1578962986.236 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:49:46.236Z,1578962986.236 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:49:46.236Z,1578962986.236 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:49:46.237Z,1578962986.237 [Default:A.Wait] Running Loop=1 2020-01-14T00:49:46.237Z,1578962986.237 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:49:59.573Z,1578962999.573 [Default:A.Wait](INFO): Done Waiting. 2020-01-14T00:49:59.573Z,1578962999.573 [Default:A.Wait] Stopped 2020-01-14T00:49:59.573Z,1578962999.573 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:49:59.968Z,1578962999.968 [Default:CheckIn] Running Loop=1 2020-01-14T00:49:59.968Z,1578962999.968 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-01-14T00:49:59.969Z,1578962999.969 [Default:CheckIn:Read_GPS] Running Loop=1 2020-01-14T00:50:31.781Z,1578963031.781 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:50:31.782Z,1578963031.782 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:50:31.828Z,1578963031.828 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min 2020-01-14T00:50:31.835Z,1578963031.835 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count 2020-01-14T00:50:31.901Z,1578963031.901 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count 2020-01-14T00:50:31.906Z,1578963031.906 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count 2020-01-14T00:50:31.908Z,1578963031.908 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup 2020-01-14T00:50:31.917Z,1578963031.917 [DUSBL:A.Pitch](DEBUG): Construct. 2020-01-14T00:50:31.934Z,1578963031.934 [DUSBL:B.SetSpeed](DEBUG): Construct. 2020-01-14T00:50:31.986Z,1578963031.986 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait. 2020-01-14T00:50:32.005Z,1578963032.005 [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 90 2020-01-14T00:50:32.007Z,1578963032.007 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:50:32.317Z,1578963032.317 [Default] Stopped 2020-01-14T00:50:32.317Z,1578963032.317 [Default](DEBUG): Aggregate::uninitialize Default 2020-01-14T00:50:32.317Z,1578963032.317 [Default:B.GoToSurface] Stopped 2020-01-14T00:50:32.317Z,1578963032.317 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:50:32.317Z,1578963032.317 [Default:CheckIn] Stopped 2020-01-14T00:50:32.317Z,1578963032.317 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-01-14T00:50:32.317Z,1578963032.317 [Default:CheckIn:Read_GPS] Stopped 2020-01-14T00:50:32.318Z,1578963032.318 [MissionManager](IMPORTANT): Started mission DUSBL 2020-01-14T00:50:32.318Z,1578963032.318 [DUSBL] Running Loop=1 2020-01-14T00:50:32.318Z,1578963032.318 [DUSBL](DEBUG): Aggregate::initialize DUSBL 2020-01-14T00:50:32.318Z,1578963032.318 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:50:32.318Z,1578963032.318 [DUSBL:A.Pitch](DEBUG): Initialize. 2020-01-14T00:50:32.318Z,1578963032.318 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:50:32.318Z,1578963032.318 [DUSBL:B.SetSpeed](DEBUG): Initialize. 2020-01-14T00:50:32.318Z,1578963032.318 [DUSBL:C] Running Loop=1 2020-01-14T00:50:32.319Z,1578963032.319 [DUSBL:RequestRepeater] Running Loop=1 2020-01-14T00:50:32.319Z,1578963032.319 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2020-01-14T00:50:32.319Z,1578963032.319 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:50:32.319Z,1578963032.319 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:50:32.319Z,1578963032.319 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2020-01-14T00:50:32.319Z,1578963032.319 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:50:32.320Z,1578963032.320 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:50:32.320Z,1578963032.320 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:50:32.320Z,1578963032.320 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range 2020-01-14T00:50:32.341Z,1578963032.341 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame 2020-01-14T00:50:32.341Z,1578963032.341 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:50:32.342Z,1578963032.342 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:50:34.279Z,1578963034.279 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:50:34.688Z,1578963034.688 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:50:35.134Z,1578963035.134 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 2.940000 m 2020-01-14T00:50:35.498Z,1578963035.498 [Micromodem](INFO): Nmea in: $SNTTA,,,,0.131817,005035.21*4D 2020-01-14T00:50:38.323Z,1578963038.323 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:50:38.724Z,1578963038.724 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:50:39.221Z,1578963039.221 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 2.940000 m 2020-01-14T00:50:39.535Z,1578963039.535 [Micromodem](INFO): Nmea in: $SNTTA,,,,,005039.26*55 2020-01-14T00:50:41.195Z,1578963041.195 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2020-01-14T00:50:41.195Z,1578963041.195 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2020-01-14T00:50:42.375Z,1578963042.375 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:50:42.776Z,1578963042.776 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:50:43.225Z,1578963043.225 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 2.940000 m 2020-01-14T00:50:43.581Z,1578963043.581 [Micromodem](INFO): Nmea in: $SNTTA,,,,,005043.31*5E 2020-01-14T00:50:44.866Z,1578963044.866 [CommandLine](IMPORTANT): got command stop 2020-01-14T00:50:44.867Z,1578963044.867 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop 2020-01-14T00:50:45.230Z,1578963045.230 [MissionManager](INFO): MissionManager is completed. 2020-01-14T00:50:45.230Z,1578963045.230 [MissionManager](INFO): Uninitializing Mission DUSBL 2020-01-14T00:50:45.230Z,1578963045.230 [DUSBL] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:A.Pitch] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:B.SetSpeed] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:B.SetSpeed](DEBUG): Uninitialize. 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:C] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:RequestRepeater] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:RequestRepeater:A] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:RequestRepeater:B] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:RequestRepeater:C.Wait] Stopped 2020-01-14T00:50:45.231Z,1578963045.231 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:50:45.631Z,1578963045.631 [MissionManager](IMPORTANT): Started mission Default 2020-01-14T00:50:45.631Z,1578963045.631 [Default] Running Loop=1 2020-01-14T00:50:45.631Z,1578963045.631 [Default](DEBUG): Aggregate::initialize Default 2020-01-14T00:50:45.631Z,1578963045.631 [Default:B.GoToSurface] Running Loop=1 2020-01-14T00:50:45.631Z,1578963045.631 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:50:45.632Z,1578963045.632 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:50:45.632Z,1578963045.632 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:50:45.632Z,1578963045.632 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:50:45.633Z,1578963045.633 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:50:45.633Z,1578963045.633 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:50:45.633Z,1578963045.633 [Default:A.Wait] Running Loop=1 2020-01-14T00:50:45.633Z,1578963045.633 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:50:48.020Z,1578963048.020 [NAL9602](INFO): SBD MO Status=2, MOMSN=10160, MT Status=2, MTMSN=0 2020-01-14T00:50:48.020Z,1578963048.020 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-01-14T00:50:58.961Z,1578963058.961 [Default:A.Wait](INFO): Done Waiting. 2020-01-14T00:50:58.961Z,1578963058.961 [Default:A.Wait] Stopped 2020-01-14T00:50:58.961Z,1578963058.961 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:50:59.374Z,1578963059.374 [Default:CheckIn] Running Loop=1 2020-01-14T00:50:59.374Z,1578963059.374 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-01-14T00:50:59.374Z,1578963059.374 [Default:CheckIn:Read_GPS] Running Loop=1 2020-01-14T00:51:15.928Z,1578963075.928 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2020-01-14T00:51:15.928Z,1578963075.928 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2020-01-14T00:51:19.932Z,1578963079.932 [NAL9602](INFO): SBD MO Status=2, MOMSN=10160, MT Status=2, MTMSN=0 2020-01-14T00:51:19.932Z,1578963079.932 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-01-14T00:51:20.180Z,1578963080.180 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1578963072.000000 second 2020-01-14T00:51:20.391Z,1578963080.391 [Default:CheckIn:Read_GPS] Stopped 2020-01-14T00:51:20.391Z,1578963080.391 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-01-14T00:51:22.139Z,1578963082.139 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 3F0C1D5E0A0000005D00000400430000000000000000151D80030C5669C08C34EE57E7F1E0CA2AEC724AC1B765EE89EC3D4F7381DE442E42EDA8824F2CE180C6 2020-01-14T00:51:22.140Z,1578963082.140 [Micromodem](INFO): Outgoing frame #2, 19 bytes: 55E818C7480B883BE6198F3F8EB15DDF4B0000 2020-01-14T00:51:22.140Z,1578963082.140 [Micromodem](INFO): Nmea out: $CCCYC,0,1,12,1,0,2*68 2020-01-14T00:51:22.338Z,1578963082.338 [Micromodem](INFO): Nmea in: $CACYC,0,1,12,1,0,2*6A 2020-01-14T00:51:22.698Z,1578963082.698 [Micromodem](INFO): Nmea in: $CADRQ,005122,1,12,0,64,1*70 2020-01-14T00:51:22.699Z,1578963082.699 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,3F0C1D5E0A0000005D00000400430000000000000000151D80030C5669C08C34EE57E7F1E0CA2AEC724AC1B765EE89EC3D4F7381DE442E42EDA8824F2CE180C6*37 2020-01-14T00:51:23.114Z,1578963083.114 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,64*4B 2020-01-14T00:51:23.504Z,1578963083.504 [Micromodem](INFO): Nmea in: $CADRQ,005123,1,12,0,64,2*72 2020-01-14T00:51:23.525Z,1578963083.525 [Micromodem](INFO): Nmea out: $CCTXD,1,12,1,55E818C7480B883BE6198F3F8EB15DDF4B0000*3F 2020-01-14T00:51:23.911Z,1578963083.911 [Micromodem](INFO): Nmea in: $CATXD,1,12,1,19*41 2020-01-14T00:51:24.318Z,1578963084.318 [Micromodem](INFO): Nmea in: $CATXP,83*79 2020-01-14T00:51:26.734Z,1578963086.734 [Micromodem](INFO): Nmea in: $CATXF,83*6F 2020-01-14T00:51:27.947Z,1578963087.947 [Micromodem](INFO): Nmea in: $CAXST,6,20200114,005124.445595,3,0,200,4000,10000,1,1,12,1,2,2,3,83*41 2020-01-14T00:51:28.916Z,1578963088.916 [DataOverHttps](INFO): Sending 75 bytes from file Logs/20200114T003303/Courier0010.lzma 2020-01-14T00:51:30.922Z,1578963090.922 [DataOverHttps](INFO): Moved sent file to Logs/20200114T003303/Courier0010.lzma.bak 2020-01-14T00:51:30.922Z,1578963090.922 [DataOverHttps](INFO): SBD MOMSN=12192164 2020-01-14T00:51:35.628Z,1578963095.628 [NAL9602](INFO): SBD MO Status=2, MOMSN=10160, MT Status=2, MTMSN=0 2020-01-14T00:51:35.628Z,1578963095.628 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-01-14T00:51:51.683Z,1578963111.683 [DataOverHttps](INFO): Sending 831 bytes from file Logs/20200110T181518/Express0005.lzma 2020-01-14T00:51:52.218Z,1578963112.218 [Micromodem](INFO): Nmea in: $CACYC,1,12,1,1,0,1*68 2020-01-14T00:51:52.218Z,1578963112.218 [Micromodem](INFO): Have incoming data 2020-01-14T00:51:52.591Z,1578963112.591 [Micromodem](INFO): Nmea in: $CARXD,12,1,0,1,3D90B8D172D0E11A94BB9A0D6EC0434A2AB488F6*51 2020-01-14T00:51:52.591Z,1578963112.591 [Micromodem](ERROR): Could not determine end of data in CARXD:$CARXD,12,1,0,1,3D90B8D172D0E11A94BB9A0D6EC0434A2AB488F6*51 2020-01-14T00:51:53.002Z,1578963113.002 [Micromodem](INFO): Nmea in: $CACST,6,0,20200114005151.124941,06,499,26,0091,0150,89,02,02,00,02,1,012,001,0,3,1,0,150,21.7,6.00,00,-3.00,-01,-0.01,29,10000,4000*4F 2020-01-14T00:51:53.686Z,1578963113.686 [DataOverHttps](INFO): Moved sent file to Logs/20200110T181518/Express0005.lzma.bak 2020-01-14T00:51:53.686Z,1578963113.686 [DataOverHttps](INFO): SBD MOMSN=12192167 2020-01-14T00:52:12.479Z,1578963132.479 [DataOverHttps](INFO): Sending 837 bytes from file Logs/20200110T182046/Express0001.lzma 2020-01-14T00:52:14.482Z,1578963134.482 [DataOverHttps](INFO): Moved sent file to Logs/20200110T182046/Express0001.lzma.bak 2020-01-14T00:52:14.482Z,1578963134.482 [DataOverHttps](INFO): SBD MOMSN=12192211 2020-01-14T00:52:20.581Z,1578963140.581 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2020-01-14T00:52:20.581Z,1578963140.581 [RDI_Pathfinder] Communications Fault, FailCount= 1 2020-01-14T00:52:20.581Z,1578963140.581 [RDI_Pathfinder](ERROR): Communications Fault 2020-01-14T00:52:20.581Z,1578963140.581 [RDI_Pathfinder](ERROR): Failed to parse: 2020-01-14T00:52:20.738Z,1578963140.738 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2020-01-14T00:52:21.049Z,1578963141.049 [RDI_Pathfinder](INFO): Powering down 2020-01-14T00:52:21.818Z,1578963141.818 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2020-01-14T00:52:21.819Z,1578963141.819 [RDI_Pathfinder] No Fault, FailCount= 1 2020-01-14T00:52:27.350Z,1578963147.350 [Micromodem](ERROR): Buffer fill timout failure. 2020-01-14T00:52:29.385Z,1578963149.385 [Default:CheckIn:Read_Iridium] Stopped 2020-01-14T00:52:29.385Z,1578963149.385 [Default:CheckIn:C.Wait] Running Loop=1 2020-01-14T00:52:29.385Z,1578963149.385 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:52:30.236Z,1578963150.236 [NAL9602](INFO): SBD MO Status=2, MOMSN=10160, MT Status=2, MTMSN=0 2020-01-14T00:52:30.237Z,1578963150.237 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-01-14T00:52:35.114Z,1578963155.114 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2020-01-14T00:52:37.230Z,1578963157.230 [CBIT](INFO): Clearing failed state for component DropWeight 2020-01-14T00:52:37.231Z,1578963157.231 [DropWeight] No Fault, FailCount= 2 2020-01-14T00:52:38.306Z,1578963158.306 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2020-01-14T00:52:38.306Z,1578963158.306 [DropWeight] Hardware Fault, FailCount= 1 2020-01-14T00:52:38.306Z,1578963158.306 [DropWeight](ERROR): Hardware Fault 2020-01-14T00:52:38.450Z,1578963158.450 [CommandLine](FAULT): Scheduling is paused 2020-01-14T00:52:38.451Z,1578963158.451 [CBIT](INFO): Critical error at 20200114T005238 2020-01-14T00:52:38.465Z,1578963158.465 [CBIT](ERROR): Hardware Fault in component: DropWeight 2020-01-14T00:52:38.466Z,1578963158.466 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2020-01-14T00:52:38.798Z,1578963158.798 [CBIT](INFO): Critical error at 20200114T005238 2020-01-14T00:52:41.935Z,1578963161.935 [DataOverHttps](INFO): Sending 801 bytes from file Logs/20200110T182643/Express0001.lzma 2020-01-14T00:52:43.938Z,1578963163.938 [DataOverHttps](INFO): Moved sent file to Logs/20200110T182643/Express0001.lzma.bak 2020-01-14T00:52:43.938Z,1578963163.938 [DataOverHttps](INFO): SBD MOMSN=12192226 2020-01-14T00:53:19.735Z,1578963199.735 [CommandLine](IMPORTANT): got command failComponent hardware Micromodem 2020-01-14T00:53:19.736Z,1578963199.736 [Micromodem] Hardware Fault, FailCount= 1 2020-01-14T00:53:19.736Z,1578963199.736 [Micromodem](ERROR): Hardware Fault 2020-01-14T00:53:19.736Z,1578963199.736 [CommandLine](IMPORTANT): Micromodem failureMode is Hardware Fault 2020-01-14T00:53:19.918Z,1578963199.918 [Micromodem](INFO): Powering down 2020-01-14T00:53:20.087Z,1578963200.087 [CBIT](ERROR): Hardware Fault in component: Micromodem 2020-01-14T00:53:20.327Z,1578963200.327 [Micromodem](FAULT): LCB 2 fault: Software Overcurrent. 2020-01-14T00:53:20.769Z,1578963200.769 [CBIT](INFO): Clearing failed state for component Micromodem 2020-01-14T00:53:20.769Z,1578963200.769 [Micromodem] No Fault, FailCount= 1 2020-01-14T00:53:23.555Z,1578963203.555 [Micromodem](INFO): Powering up 2020-01-14T00:53:23.555Z,1578963203.555 [Micromodem](DEBUG): Initializing Micromodem. 2020-01-14T00:53:28.410Z,1578963208.410 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33 2020-01-14T00:53:30.432Z,1578963210.432 [Micromodem](INFO): Nmea in: $CATMG,2020-01-14T00:53:29.367612Z,RTC,RTC*5E 2020-01-14T00:53:30.432Z,1578963210.432 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2020-01-14T00:53:29.367612Z,RTC,RTC*5E 2020-01-14T00:53:31.640Z,1578963211.640 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-01-14T00:53:39.719Z,1578963219.719 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33 2020-01-14T00:53:40.130Z,1578963220.130 [Micromodem](INFO): Nmea in: $CAERR,005340,NI ,12,Unknown command*4E 2020-01-14T00:53:40.130Z,1578963220.130 [Micromodem](ERROR): Got error from modem: $CAERR,005340,NI ,12,Unknown command*4E 2020-01-14T00:53:51.044Z,1578963231.044 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33 2020-01-14T00:53:51.440Z,1578963231.440 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31 2020-01-14T00:53:51.441Z,1578963231.441 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31 2020-01-14T00:53:51.832Z,1578963231.832 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33 2020-01-14T00:53:51.832Z,1578963231.832 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64 2020-01-14T00:53:52.242Z,1578963232.242 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66 2020-01-14T00:53:52.243Z,1578963232.243 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F 2020-01-14T00:53:52.643Z,1578963232.643 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D 2020-01-14T00:53:52.643Z,1578963232.643 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E 2020-01-14T00:53:53.055Z,1578963233.055 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C 2020-01-14T00:53:53.056Z,1578963233.056 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46 2020-01-14T00:53:53.450Z,1578963233.450 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44 2020-01-14T00:53:53.451Z,1578963233.451 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63 2020-01-14T00:53:53.853Z,1578963233.853 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61 2020-01-14T00:53:53.853Z,1578963233.853 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A 2020-01-14T00:53:54.262Z,1578963234.262 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38 2020-01-14T00:53:54.263Z,1578963234.263 [Micromodem](INFO): Nmea out: $CCCLK,2020,01,14,00,53,55*46 2020-01-14T00:53:54.671Z,1578963234.671 [Micromodem](INFO): Nmea in: $CACLK,2020,1,14,0,53,55*44 2020-01-14T00:53:55.475Z,1578963235.475 [Micromodem](INFO): Nmea in: $CATMS,0,2020-01-14T00:53:56Z*77 2020-01-14T00:53:55.476Z,1578963235.476 [Micromodem](INFO): Nmea in: $CATMG,2020-01-14T00:53:56.026106Z,USER_CMD,RTC*13 2020-01-14T00:54:02.339Z,1578963242.339 [NAL9602](INFO): Not Powering down - fast GPS 2020-01-14T00:54:20.030Z,1578963260.030 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:54:20.031Z,1578963260.031 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:54:20.076Z,1578963260.076 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min 2020-01-14T00:54:20.078Z,1578963260.078 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count 2020-01-14T00:54:20.080Z,1578963260.080 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count 2020-01-14T00:54:20.082Z,1578963260.082 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count 2020-01-14T00:54:20.084Z,1578963260.084 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup 2020-01-14T00:54:20.085Z,1578963260.085 [DUSBL:A.Pitch](DEBUG): Construct. 2020-01-14T00:54:20.089Z,1578963260.089 [DUSBL:B.SetSpeed](DEBUG): Construct. 2020-01-14T00:54:20.132Z,1578963260.132 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait. 2020-01-14T00:54:20.156Z,1578963260.156 [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 90 2020-01-14T00:54:20.186Z,1578963260.186 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml 2020-01-14T00:54:20.244Z,1578963260.244 [Default] Stopped 2020-01-14T00:54:20.244Z,1578963260.244 [Default](DEBUG): Aggregate::uninitialize Default 2020-01-14T00:54:20.244Z,1578963260.244 [Default:B.GoToSurface] Stopped 2020-01-14T00:54:20.244Z,1578963260.244 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:54:20.244Z,1578963260.244 [Default:CheckIn] Stopped 2020-01-14T00:54:20.244Z,1578963260.244 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-01-14T00:54:20.244Z,1578963260.244 [Default:CheckIn:C.Wait] Stopped 2020-01-14T00:54:20.244Z,1578963260.244 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:54:20.244Z,1578963260.244 [MissionManager](IMPORTANT): Started mission DUSBL 2020-01-14T00:54:20.245Z,1578963260.245 [DUSBL] Running Loop=1 2020-01-14T00:54:20.245Z,1578963260.245 [DUSBL](DEBUG): Aggregate::initialize DUSBL 2020-01-14T00:54:20.245Z,1578963260.245 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:54:20.245Z,1578963260.245 [DUSBL:A.Pitch](DEBUG): Initialize. 2020-01-14T00:54:20.245Z,1578963260.245 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:54:20.245Z,1578963260.245 [DUSBL:B.SetSpeed](DEBUG): Initialize. 2020-01-14T00:54:20.245Z,1578963260.245 [DUSBL:C] Running Loop=1 2020-01-14T00:54:20.246Z,1578963260.246 [DUSBL:RequestRepeater] Running Loop=1 2020-01-14T00:54:20.246Z,1578963260.246 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater 2020-01-14T00:54:20.246Z,1578963260.246 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:54:20.246Z,1578963260.246 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:54:20.246Z,1578963260.246 [DUSBL:RequestRepeater:C.Wait] Running Loop=1 2020-01-14T00:54:20.246Z,1578963260.246 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:54:20.246Z,1578963260.246 [DUSBL:RequestRepeater:B] Running Loop=1 2020-01-14T00:54:20.247Z,1578963260.247 [DUSBL:RequestRepeater:A] Running Loop=1 2020-01-14T00:54:20.247Z,1578963260.247 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range 2020-01-14T00:54:20.248Z,1578963260.248 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame 2020-01-14T00:54:20.248Z,1578963260.248 [DUSBL:B.SetSpeed] Running Loop=1 2020-01-14T00:54:20.248Z,1578963260.248 [DUSBL:A.Pitch] Running Loop=1 2020-01-14T00:54:22.172Z,1578963262.172 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:54:22.552Z,1578963262.552 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:54:23.038Z,1578963263.038 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 2.880000 m 2020-01-14T00:54:23.372Z,1578963263.372 [Micromodem](INFO): Nmea in: $SNTTA,,,,,005423.11*5E 2020-01-14T00:54:26.187Z,1578963266.187 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:54:26.590Z,1578963266.590 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:54:27.047Z,1578963267.047 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 2.160000 m 2020-01-14T00:54:27.403Z,1578963267.403 [Micromodem](INFO): Nmea in: $SNTTA,,,,,005427.12*59 2020-01-14T00:54:30.224Z,1578963270.224 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77 2020-01-14T00:54:30.390Z,1578963270.390 [CommandLine](IMPORTANT): got command stop 2020-01-14T00:54:30.390Z,1578963270.390 [CommandLine](IMPORTANT): Scheduling is paused 2020-01-14T00:54:30.390Z,1578963270.390 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop 2020-01-14T00:54:30.628Z,1578963270.628 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A 2020-01-14T00:54:30.702Z,1578963270.702 [MissionManager](INFO): MissionManager is completed. 2020-01-14T00:54:30.703Z,1578963270.703 [MissionManager](INFO): Uninitializing Mission DUSBL 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:A.Pitch] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:B.SetSpeed] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:B.SetSpeed](DEBUG): Uninitialize. 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:C] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:RequestRepeater] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:RequestRepeater:A] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:RequestRepeater:B] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:RequestRepeater:C.Wait] Stopped 2020-01-14T00:54:30.703Z,1578963270.703 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:54:31.097Z,1578963271.097 [MissionManager](IMPORTANT): Started mission Default 2020-01-14T00:54:31.097Z,1578963271.097 [Default] Running Loop=1 2020-01-14T00:54:31.097Z,1578963271.097 [Default](DEBUG): Aggregate::initialize Default 2020-01-14T00:54:31.097Z,1578963271.097 [Default:B.GoToSurface] Running Loop=1 2020-01-14T00:54:31.097Z,1578963271.097 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-01-14T00:54:31.098Z,1578963271.098 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-01-14T00:54:31.098Z,1578963271.098 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-01-14T00:54:31.098Z,1578963271.098 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-01-14T00:54:31.098Z,1578963271.098 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-01-14T00:54:31.099Z,1578963271.099 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-01-14T00:54:31.099Z,1578963271.099 [Default:A.Wait] Running Loop=1 2020-01-14T00:54:31.099Z,1578963271.099 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-01-14T00:54:31.442Z,1578963271.442 [Micromodem](INFO): Nmea in: $SNTTA,,,,,005431.16*5A 2020-01-14T00:54:44.399Z,1578963284.399 [Default:A.Wait](INFO): Done Waiting. 2020-01-14T00:54:44.399Z,1578963284.399 [Default:A.Wait] Stopped 2020-01-14T00:54:44.399Z,1578963284.399 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-01-14T00:54:44.801Z,1578963284.801 [Default:CheckIn] Running Loop=1 2020-01-14T00:54:44.801Z,1578963284.801 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-01-14T00:54:44.801Z,1578963284.801 [Default:CheckIn:Read_GPS] Running Loop=1 2020-01-14T00:55:17.495Z,1578963317.495 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2020-01-14T00:55:17.569Z,1578963317.569 [NAL9602](FAULT): received: +CSQ:0 OK160, 2, 0, 0, 0 OK 2020-01-14T00:55:17.569Z,1578963317.569 [NAL9602] Data Fault, FailCount= 1 2020-01-14T00:55:17.569Z,1578963317.569 [NAL9602](ERROR): Data Fault 2020-01-14T00:55:17.637Z,1578963317.637 [CBIT](ERROR): Data Fault in component: NAL9602 2020-01-14T00:55:17.895Z,1578963317.895 [NAL9602](INFO): Powering down 2020-01-14T00:55:18.745Z,1578963318.745 [CBIT](INFO): Clearing failed state for component NAL9602 2020-01-14T00:55:18.745Z,1578963318.745 [NAL9602] No Fault, FailCount= 1 2020-01-14T00:55:48.204Z,1578963348.204 [NAL9602](INFO): Powering up NAL9602 2020-01-14T00:55:59.118Z,1578963359.118 [NAL9602](INFO): NAL9602 initialized 2020-01-14T00:56:32.398Z,1578963392.398 [CommandLine](IMPORTANT): got command quit 2020-01-14T00:56:33.405Z,1578963393.405 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:33.405Z,1578963393.405 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.441Z,1578963393.441 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2020-01-14T00:56:33.441Z,1578963393.441 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.442Z,1578963393.442 [CommandLine](INFO): Join timeout helper Thread ID is 6467 2020-01-14T00:56:33.445Z,1578963393.445 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2020-01-14T00:56:33.445Z,1578963393.445 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.446Z,1578963393.446 [NavChartDb](INFO): Join timeout helper Thread ID is 6468 2020-01-14T00:56:33.653Z,1578963393.653 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:33.653Z,1578963393.653 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.661Z,1578963393.661 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2020-01-14T00:56:33.661Z,1578963393.661 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.661Z,1578963393.661 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 6469 2020-01-14T00:56:33.737Z,1578963393.737 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:33.737Z,1578963393.737 [WetLabsSeaOWL_UV_A](INFO): Powering down 2020-01-14T00:56:33.738Z,1578963393.738 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.741Z,1578963393.741 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2020-01-14T00:56:33.741Z,1578963393.741 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.741Z,1578963393.741 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 6470 2020-01-14T00:56:33.813Z,1578963393.813 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:33.813Z,1578963393.813 [CTD_NeilBrown](INFO): Powering down 2020-01-14T00:56:33.825Z,1578963393.825 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.845Z,1578963393.845 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2020-01-14T00:56:33.845Z,1578963393.845 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:33.845Z,1578963393.845 [Radio_Surface](INFO): Join timeout helper Thread ID is 6471 2020-01-14T00:56:34.081Z,1578963394.081 [Radio_Surface](INFO): Powering down 2020-01-14T00:56:34.082Z,1578963394.082 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:34.082Z,1578963394.082 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:34.086Z,1578963394.086 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2020-01-14T00:56:34.086Z,1578963394.086 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:34.086Z,1578963394.086 [DataOverHttps](INFO): Join timeout helper Thread ID is 6472 2020-01-14T00:56:34.314Z,1578963394.314 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:34.314Z,1578963394.314 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:34.335Z,1578963394.335 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2020-01-14T00:56:34.336Z,1578963394.336 [logger ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:34.336Z,1578963394.336 [logger](INFO): Join timeout helper Thread ID is 6473 2020-01-14T00:56:34.363Z,1578963394.363 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:34.363Z,1578963394.363 [logger ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:34.366Z,1578963394.366 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2020-01-14T00:56:34.366Z,1578963394.366 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:34.366Z,1578963394.366 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2020-01-14T00:56:34.366Z,1578963394.366 [controlThread ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:34.366Z,1578963394.366 [controlThread](INFO): Join timeout helper Thread ID is 6474 2020-01-14T00:56:34.637Z,1578963394.637 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2020-01-14T00:56:34.637Z,1578963394.637 [controlThread](DEBUG): Uninitializing ControlThread 2020-01-14T00:56:34.638Z,1578963394.638 [AHRS_M2](INFO): Powering down 2020-01-14T00:56:34.709Z,1578963394.709 [DDM](INFO): Powering down 2020-01-14T00:56:34.797Z,1578963394.797 [DUSBL_Hydroid](INFO): Powering down 2020-01-14T00:56:34.869Z,1578963394.869 [Micromodem](INFO): Powering down 2020-01-14T00:56:34.965Z,1578963394.965 [NAL9602](INFO): Powering down 2020-01-14T00:56:35.037Z,1578963395.037 [RDI_Pathfinder](INFO): Powering down 2020-01-14T00:56:35.039Z,1578963395.039 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2020-01-14T00:56:35.040Z,1578963395.040 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2020-01-14T00:56:35.040Z,1578963395.040 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2020-01-14T00:56:35.040Z,1578963395.040 [MissionManager](INFO): Uninitializing Mission Default 2020-01-14T00:56:35.041Z,1578963395.041 [Default] Stopped 2020-01-14T00:56:35.041Z,1578963395.041 [Default](DEBUG): Aggregate::uninitialize Default 2020-01-14T00:56:35.041Z,1578963395.041 [Default:B.GoToSurface] Stopped 2020-01-14T00:56:35.041Z,1578963395.041 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-01-14T00:56:35.041Z,1578963395.041 [Default:CheckIn] Stopped 2020-01-14T00:56:35.041Z,1578963395.041 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-01-14T00:56:35.041Z,1578963395.041 [Default:CheckIn:Read_GPS] Stopped 2020-01-14T00:56:35.043Z,1578963395.043 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2020-01-14T00:56:35.044Z,1578963395.044 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2020-01-14T00:56:35.044Z,1578963395.044 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2020-01-14T00:56:35.044Z,1578963395.044 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2020-01-14T00:56:35.044Z,1578963395.044 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2020-01-14T00:56:35.044Z,1578963395.044 [BuoyancyServo](INFO): Powering down 2020-01-14T00:56:35.057Z,1578963395.057 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2020-01-14T00:56:35.057Z,1578963395.057 [ElevatorServo](INFO): Powering down 2020-01-14T00:56:35.058Z,1578963395.058 [MassServo](DEBUG): Uninitialize Mass Servo. 2020-01-14T00:56:35.058Z,1578963395.058 [MassServo](INFO): Powering down 2020-01-14T00:56:35.059Z,1578963395.059 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2020-01-14T00:56:35.059Z,1578963395.059 [RudderServo](INFO): Powering down 2020-01-14T00:56:35.059Z,1578963395.059 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2020-01-14T00:56:35.060Z,1578963395.060 [ThrusterServo](INFO): Powering down 2020-01-14T00:56:35.060Z,1578963395.060 [SBIT](DEBUG): Uninitialize SBIT Component. 2020-01-14T00:56:35.061Z,1578963395.061 [IBIT](DEBUG): Uninitialize IBIT Component. 2020-01-14T00:56:35.061Z,1578963395.061 [CBIT](DEBUG): Uninitialize CBIT Component. 2020-01-14T00:56:35.061Z,1578963395.061 [CBIT](DEBUG): Powering off loads. 2020-01-14T00:56:35.073Z,1578963395.073 [CBIT](DEBUG): Disabling WDT. 2020-01-14T00:56:35.085Z,1578963395.085 [CBIT](DEBUG): Opening all GF detection circuits. 2020-01-14T00:56:35.086Z,1578963395.086 [controlThread ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:35.144Z,1578963395.144 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:35.154Z,1578963395.154 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:35.196Z,1578963395.196 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:35.199Z,1578963395.199 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:35.256Z,1578963395.256 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-01-14T00:56:35.317Z,1578963395.317 [logger ThreadHandler](INFO): Thread cancelled.