2020-08-31T16:27:26.164Z,1598891246.164 [Supervisor](DEBUG): Initializing supervisor. 2020-08-31T16:27:26.167Z,1598891246.167 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2020-08-31T16:27:26.168Z,1598891246.168 [SyncHandler](INFO): Protected caller Thread ID is 4592 2020-08-31T16:27:26.168Z,1598891246.168 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2020-08-31T16:27:26.169Z,1598891246.169 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2020-08-31T16:27:26.170Z,1598891246.170 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 4593 2020-08-31T16:27:26.173Z,1598891246.173 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2020-08-31T16:27:26.187Z,1598891246.187 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2020-08-31T16:27:26.187Z,1598891246.187 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2020-08-31T16:27:26.188Z,1598891246.188 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 4594 2020-08-31T16:27:26.188Z,1598891246.188 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2020-08-31T16:27:26.189Z,1598891246.189 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2020-08-31T16:27:26.190Z,1598891246.190 [logger ThreadHandler](INFO): Protected caller Thread ID is 4595 2020-08-31T16:27:26.192Z,1598891246.192 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2020-08-31T16:27:26.192Z,1598891246.192 [Supervisor](INFO): Looking for Config files in directory: Config/ 2020-08-31T16:27:26.194Z,1598891246.194 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2020-08-31T16:27:26.345Z,1598891246.345 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2020-08-31T16:27:26.346Z,1598891246.346 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2020-08-31T16:27:26.947Z,1598891246.947 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2020-08-31T16:27:26.947Z,1598891246.947 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2020-08-31T16:27:27.139Z,1598891247.139 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2020-08-31T16:27:27.140Z,1598891247.140 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2020-08-31T16:27:27.241Z,1598891247.241 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2020-08-31T16:27:27.241Z,1598891247.241 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2020-08-31T16:27:27.344Z,1598891247.344 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2020-08-31T16:27:27.345Z,1598891247.345 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2020-08-31T16:27:27.427Z,1598891247.427 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2020-08-31T16:27:27.564Z,1598891247.564 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2020-08-31T16:27:27.565Z,1598891247.565 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2020-08-31T16:27:27.851Z,1598891247.851 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2020-08-31T16:27:27.852Z,1598891247.852 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2020-08-31T16:27:28.312Z,1598891248.312 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2020-08-31T16:27:28.313Z,1598891248.313 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2020-08-31T16:27:28.458Z,1598891248.458 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2020-08-31T16:27:28.458Z,1598891248.458 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2020-08-31T16:27:28.655Z,1598891248.655 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2020-08-31T16:27:28.656Z,1598891248.656 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2020-08-31T16:27:29.386Z,1598891249.386 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2020-08-31T16:27:29.386Z,1598891249.386 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2020-08-31T16:27:29.839Z,1598891249.839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2020-08-31T16:27:29.840Z,1598891249.840 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2020-08-31T16:27:30.045Z,1598891250.045 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2020-08-31T16:27:30.046Z,1598891250.046 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2020-08-31T16:27:30.453Z,1598891250.453 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2020-08-31T16:27:30.454Z,1598891250.454 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2020-08-31T16:27:30.788Z,1598891250.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2020-08-31T16:27:30.791Z,1598891250.791 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/ 2020-08-31T16:27:30.793Z,1598891250.793 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg 2020-08-31T16:27:30.971Z,1598891250.971 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg 2020-08-31T16:27:31.130Z,1598891251.130 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg 2020-08-31T16:27:31.239Z,1598891251.239 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg 2020-08-31T16:27:31.326Z,1598891251.326 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg 2020-08-31T16:27:31.422Z,1598891251.422 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg 2020-08-31T16:27:31.623Z,1598891251.623 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg 2020-08-31T16:27:31.853Z,1598891251.853 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2020-08-31T16:27:31.854Z,1598891251.854 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg 2020-08-31T16:27:31.950Z,1598891251.950 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg 2020-08-31T16:27:32.051Z,1598891252.051 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg 2020-08-31T16:27:32.183Z,1598891252.183 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg 2020-08-31T16:27:32.284Z,1598891252.284 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2020-08-31T16:27:32.299Z,1598891252.299 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2020-08-31T16:27:32.391Z,1598891252.391 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2020-08-31T16:27:32.392Z,1598891252.392 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2020-08-31T16:27:32.452Z,1598891252.452 [VerticalControl](DEBUG): Construct VerticalControl. 2020-08-31T16:27:32.560Z,1598891252.560 [VerticalControl] Loaded 2020-08-31T16:27:32.560Z,1598891252.560 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2020-08-31T16:27:32.561Z,1598891252.561 [HorizontalControl](DEBUG): Construct HorizontalControl. 2020-08-31T16:27:32.637Z,1598891252.637 [HorizontalControl] Loaded 2020-08-31T16:27:32.637Z,1598891252.637 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2020-08-31T16:27:32.638Z,1598891252.638 [SpeedControl](DEBUG): Construct SpeedControl. 2020-08-31T16:27:32.643Z,1598891252.643 [SpeedControl] Loaded 2020-08-31T16:27:32.644Z,1598891252.644 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2020-08-31T16:27:32.644Z,1598891252.644 [LoopControl](DEBUG): Construct LoopControl. 2020-08-31T16:27:32.645Z,1598891252.645 [LoopControl] Loaded 2020-08-31T16:27:32.645Z,1598891252.645 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2020-08-31T16:27:32.645Z,1598891252.645 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2020-08-31T16:27:32.646Z,1598891252.646 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2020-08-31T16:27:32.700Z,1598891252.700 [DepthRateCalculator] Loaded 2020-08-31T16:27:32.700Z,1598891252.700 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2020-08-31T16:27:32.705Z,1598891252.705 [PitchRateCalculator] Loaded 2020-08-31T16:27:32.705Z,1598891252.705 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2020-08-31T16:27:32.720Z,1598891252.720 [SpeedCalculator] Loaded 2020-08-31T16:27:32.720Z,1598891252.720 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2020-08-31T16:27:32.741Z,1598891252.741 [TempGradientCalculator] Loaded 2020-08-31T16:27:32.741Z,1598891252.741 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2020-08-31T16:27:32.746Z,1598891252.746 [YawRateCalculator] Loaded 2020-08-31T16:27:32.746Z,1598891252.746 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2020-08-31T16:27:32.774Z,1598891252.774 [ElevatorOffsetCalculator] Loaded 2020-08-31T16:27:32.775Z,1598891252.775 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2020-08-31T16:27:32.775Z,1598891252.775 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2020-08-31T16:27:32.776Z,1598891252.776 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2020-08-31T16:27:32.815Z,1598891252.815 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2020-08-31T16:27:32.816Z,1598891252.816 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2020-08-31T16:27:32.943Z,1598891252.943 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2020-08-31T16:27:32.943Z,1598891252.943 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2020-08-31T16:27:33.265Z,1598891253.265 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2020-08-31T16:27:33.265Z,1598891253.265 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2020-08-31T16:27:33.386Z,1598891253.386 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2020-08-31T16:27:33.387Z,1598891253.387 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2020-08-31T16:27:33.921Z,1598891253.921 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2020-08-31T16:27:33.926Z,1598891253.926 [AHRS_M2](INFO): created writer for : platform_orientation 2020-08-31T16:27:33.930Z,1598891253.930 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2020-08-31T16:27:33.935Z,1598891253.935 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2020-08-31T16:27:33.936Z,1598891253.936 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2020-08-31T16:27:33.940Z,1598891253.940 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2020-08-31T16:27:33.941Z,1598891253.941 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2020-08-31T16:27:33.946Z,1598891253.946 [AHRS_M2](INFO): created writer for : platform_roll_angle 2020-08-31T16:27:34.014Z,1598891254.014 [AHRS_M2] Loaded 2020-08-31T16:27:34.015Z,1598891254.015 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2020-08-31T16:27:34.112Z,1598891254.112 [DataOverHttps] Loaded 2020-08-31T16:27:34.112Z,1598891254.112 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2020-08-31T16:27:34.118Z,1598891254.118 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4090D4E0 2020-08-31T16:27:34.118Z,1598891254.118 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 4679 2020-08-31T16:27:34.147Z,1598891254.147 [Depth_Keller] Loaded 2020-08-31T16:27:34.148Z,1598891254.148 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2020-08-31T16:27:34.256Z,1598891254.256 [NAL9602] Loaded 2020-08-31T16:27:34.256Z,1598891254.256 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2020-08-31T16:27:34.304Z,1598891254.304 [Onboard] Loaded 2020-08-31T16:27:34.304Z,1598891254.304 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2020-08-31T16:27:34.305Z,1598891254.305 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4093D4E0 2020-08-31T16:27:34.306Z,1598891254.306 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 4680 2020-08-31T16:27:34.324Z,1598891254.324 [Radio_Surface] Loaded 2020-08-31T16:27:34.324Z,1598891254.324 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2020-08-31T16:27:34.325Z,1598891254.325 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4096D4E0 2020-08-31T16:27:34.326Z,1598891254.326 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 4681 2020-08-31T16:27:34.471Z,1598891254.471 [DAT] Loaded 2020-08-31T16:27:34.471Z,1598891254.471 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2020-08-31T16:27:36.294Z,1598891256.294 [BPC1] Loaded 2020-08-31T16:27:36.294Z,1598891256.294 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2020-08-31T16:27:36.325Z,1598891256.325 [AMEcho] Loaded 2020-08-31T16:27:36.326Z,1598891256.326 [ComponentRegistry](DEBUG): SyncComponent "AMEcho" handled in the control thread. 2020-08-31T16:27:36.326Z,1598891256.326 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2020-08-31T16:27:36.327Z,1598891256.327 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2020-08-31T16:27:36.458Z,1598891256.458 [DeadReckonUsingMultipleVelocitySources] Loaded 2020-08-31T16:27:36.458Z,1598891256.458 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2020-08-31T16:27:36.478Z,1598891256.478 [NavChart] Loaded 2020-08-31T16:27:36.478Z,1598891256.478 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2020-08-31T16:27:36.482Z,1598891256.482 [UniversalFixResidualReporter] Loaded 2020-08-31T16:27:36.482Z,1598891256.482 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2020-08-31T16:27:36.483Z,1598891256.483 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2020-08-31T16:27:36.483Z,1598891256.483 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2020-08-31T16:27:36.638Z,1598891256.638 [SBIT](DEBUG): Construct Startup Built In Test. 2020-08-31T16:27:36.649Z,1598891256.649 [SBIT] Loaded 2020-08-31T16:27:36.649Z,1598891256.649 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2020-08-31T16:27:36.650Z,1598891256.650 [IBIT](DEBUG): Construct Initiated Built In Test. 2020-08-31T16:27:36.662Z,1598891256.662 [IBIT] Loaded 2020-08-31T16:27:36.662Z,1598891256.662 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2020-08-31T16:27:36.665Z,1598891256.665 [CBIT](DEBUG): Construct Continuous Built In Test. 2020-08-31T16:27:36.800Z,1598891256.800 [CBIT] Loaded 2020-08-31T16:27:36.800Z,1598891256.800 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2020-08-31T16:27:36.801Z,1598891256.801 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2020-08-31T16:27:36.801Z,1598891256.801 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2020-08-31T16:27:36.942Z,1598891256.942 [BuoyancyServo] Loaded 2020-08-31T16:27:36.942Z,1598891256.942 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2020-08-31T16:27:36.970Z,1598891256.970 [ElevatorServo] Loaded 2020-08-31T16:27:36.970Z,1598891256.970 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2020-08-31T16:27:36.997Z,1598891256.997 [MassServo] Loaded 2020-08-31T16:27:36.997Z,1598891256.997 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2020-08-31T16:27:37.024Z,1598891257.024 [RudderServo] Loaded 2020-08-31T16:27:37.024Z,1598891257.024 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2020-08-31T16:27:37.050Z,1598891257.050 [ThrusterServo] Loaded 2020-08-31T16:27:37.050Z,1598891257.050 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2020-08-31T16:27:37.051Z,1598891257.051 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2020-08-31T16:27:37.051Z,1598891257.051 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2020-08-31T16:27:37.080Z,1598891257.080 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2020-08-31T16:27:37.080Z,1598891257.080 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2020-08-31T16:27:37.395Z,1598891257.395 [BackSeatDriver] Loaded 2020-08-31T16:27:37.395Z,1598891257.395 [ComponentRegistry](DEBUG): Component "BackSeatDriver" handled in its own thread. 2020-08-31T16:27:37.400Z,1598891257.400 [BackSeatDriver ThreadHandler](DEBUG): Created PCaller Thread at 40B034E0 2020-08-31T16:27:37.400Z,1598891257.400 [BackSeatDriver ThreadHandler](INFO): Protected caller Thread ID is 4682 2020-08-31T16:27:37.428Z,1598891257.428 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2020-08-31T16:27:37.434Z,1598891257.434 [CTD_Seabird](INFO): created writer for : sea_water_density 2020-08-31T16:27:37.434Z,1598891257.434 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2020-08-31T16:27:37.439Z,1598891257.439 [CTD_Seabird](INFO): created writer for : depth 2020-08-31T16:27:37.439Z,1598891257.439 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2020-08-31T16:27:37.445Z,1598891257.445 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2020-08-31T16:27:37.446Z,1598891257.446 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2020-08-31T16:27:37.451Z,1598891257.451 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2020-08-31T16:27:37.451Z,1598891257.451 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2020-08-31T16:27:37.456Z,1598891257.456 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2020-08-31T16:27:37.457Z,1598891257.457 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2020-08-31T16:27:37.462Z,1598891257.462 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2020-08-31T16:27:37.462Z,1598891257.462 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2020-08-31T16:27:37.467Z,1598891257.467 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2020-08-31T16:27:37.494Z,1598891257.494 [CTD_Seabird] Loaded 2020-08-31T16:27:37.495Z,1598891257.495 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2020-08-31T16:27:37.496Z,1598891257.496 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B334E0 2020-08-31T16:27:37.496Z,1598891257.496 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 4683 2020-08-31T16:27:37.517Z,1598891257.517 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470 2020-08-31T16:27:37.518Z,1598891257.518 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470 2020-08-31T16:27:37.522Z,1598891257.522 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650 2020-08-31T16:27:37.522Z,1598891257.522 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650 2020-08-31T16:27:37.526Z,1598891257.526 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl 2020-08-31T16:27:37.526Z,1598891257.526 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl 2020-08-31T16:27:37.530Z,1598891257.530 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm 2020-08-31T16:27:37.530Z,1598891257.530 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm 2020-08-31T16:27:37.534Z,1598891257.534 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm 2020-08-31T16:27:37.534Z,1598891257.534 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm 2020-08-31T16:27:37.539Z,1598891257.539 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm 2020-08-31T16:27:37.539Z,1598891257.539 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm 2020-08-31T16:27:37.543Z,1598891257.543 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm 2020-08-31T16:27:37.543Z,1598891257.543 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm 2020-08-31T16:27:37.547Z,1598891257.547 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.552Z,1598891257.552 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.552Z,1598891257.552 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.552Z,1598891257.552 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.556Z,1598891257.556 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.556Z,1598891257.556 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.560Z,1598891257.560 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.560Z,1598891257.560 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-08-31T16:27:37.565Z,1598891257.565 [WetLabsBB2FL] Loaded 2020-08-31T16:27:37.565Z,1598891257.565 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2020-08-31T16:27:37.566Z,1598891257.566 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B634E0 2020-08-31T16:27:37.566Z,1598891257.566 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 4684 2020-08-31T16:27:37.567Z,1598891257.567 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2020-08-31T16:27:37.571Z,1598891257.571 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2020-08-31T16:27:37.571Z,1598891257.571 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2020-08-31T16:27:37.578Z,1598891257.578 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2020-08-31T16:27:37.579Z,1598891257.579 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B934E0 2020-08-31T16:27:37.580Z,1598891257.580 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 4685 2020-08-31T16:27:37.584Z,1598891257.584 [Supervisor](INFO): Main Thread ID is 4591 2020-08-31T16:27:37.584Z,1598891257.584 [Supervisor](DEBUG): Running supervisor. 2020-08-31T16:27:37.585Z,1598891257.585 [CommandLine ThreadHandler](INFO): Handler Thread ID is 4686 2020-08-31T16:27:37.589Z,1598891257.589 [controlThread ThreadHandler](INFO): Handler Thread ID is 4687 2020-08-31T16:27:37.589Z,1598891257.589 [controlThread](DEBUG): Initializing ControlThread 2020-08-31T16:27:37.590Z,1598891257.590 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2020-08-31T16:27:37.592Z,1598891257.592 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2020-08-31T16:27:37.592Z,1598891257.592 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2020-08-31T16:27:37.593Z,1598891257.593 [LoopControl](DEBUG): Initialize LoopControlComponent. 2020-08-31T16:27:37.593Z,1598891257.593 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2020-08-31T16:27:37.594Z,1598891257.594 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2020-08-31T16:27:37.594Z,1598891257.594 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2020-08-31T16:27:37.594Z,1598891257.594 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2020-08-31T16:27:37.595Z,1598891257.595 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2020-08-31T16:27:37.595Z,1598891257.595 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2020-08-31T16:27:37.599Z,1598891257.599 [NavChart](DEBUG): Initialize NavChart Navigation. 2020-08-31T16:27:37.600Z,1598891257.600 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2020-08-31T16:27:37.600Z,1598891257.600 [SBIT](INFO): Initialize SBIT Component. 2020-08-31T16:27:37.600Z,1598891257.600 [SBIT](IMPORTANT): git: 2020-08-31 2020-08-31T16:27:37.601Z,1598891257.601 [SBIT](INFO): git hash: b6c0ec5a69f4280de3f7606c4f2437bb78ebd873 2020-08-31T16:27:37.601Z,1598891257.601 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2020-08-31T16:27:37.602Z,1598891257.602 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 Kernel Reported: #1 PREEMPT Thu Aug 6 12:04:53 PDT 2020 2020-08-31T16:27:37.603Z,1598891257.603 [SBIT](INFO): Beginning SBIT in 65.000000 seconds. 2020-08-31T16:27:37.604Z,1598891257.604 [IBIT](INFO): Initialize IBIT Component. 2020-08-31T16:27:37.605Z,1598891257.605 [CBIT](DEBUG): Initialize CBIT Component. 2020-08-31T16:27:37.606Z,1598891257.606 [logger ThreadHandler](INFO): Handler Thread ID is 4688 2020-08-31T16:27:37.617Z,1598891257.617 [CBIT](DEBUG): Initialized mux pins. 2020-08-31T16:27:37.617Z,1598891257.617 [CBIT](DEBUG): Initializing the watchdog timer. 2020-08-31T16:27:37.628Z,1598891257.628 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 4689 2020-08-31T16:27:37.629Z,1598891257.629 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2020-08-31T16:27:37.638Z,1598891257.638 [Onboard ThreadHandler](INFO): Handler Thread ID is 4690 2020-08-31T16:27:37.642Z,1598891257.642 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET. 2020-08-31T16:27:37.642Z,1598891257.642 [CBIT](DEBUG): Initializing heartbeat. 2020-08-31T16:27:37.668Z,1598891257.668 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 4691 2020-08-31T16:27:37.678Z,1598891257.678 [BackSeatDriver ThreadHandler](INFO): Handler Thread ID is 4692 2020-08-31T16:27:37.698Z,1598891257.698 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 4693 2020-08-31T16:27:37.698Z,1598891257.698 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2020-08-31T16:27:37.703Z,1598891257.703 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 4695 2020-08-31T16:27:37.704Z,1598891257.704 [WetLabsBB2FL](INFO): Powering down 2020-08-31T16:27:37.714Z,1598891257.714 [CBIT](DEBUG): Deactivating GF circuits. 2020-08-31T16:27:37.714Z,1598891257.714 [CBIT](DEBUG): Deactivating emergency mode. 2020-08-31T16:27:37.749Z,1598891257.749 [CBIT](DEBUG): Backplane powered. 2020-08-31T16:27:37.751Z,1598891257.751 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2020-08-31T16:27:37.827Z,1598891257.827 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 4696 2020-08-31T16:27:37.836Z,1598891257.836 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2020-08-31T16:27:37.836Z,1598891257.836 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2020-08-31T16:27:37.837Z,1598891257.837 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2020-08-31T16:27:37.837Z,1598891257.837 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2020-08-31T16:27:37.837Z,1598891257.837 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2020-08-31T16:27:37.837Z,1598891257.837 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2020-08-31T16:27:37.837Z,1598891257.837 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2020-08-31T16:27:37.837Z,1598891257.837 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2020-08-31T16:27:37.838Z,1598891257.838 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2020-08-31T16:27:37.838Z,1598891257.838 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2020-08-31T16:27:37.838Z,1598891257.838 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2020-08-31T16:27:37.838Z,1598891257.838 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2020-08-31T16:27:37.838Z,1598891257.838 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2020-08-31T16:27:37.838Z,1598891257.838 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2020-08-31T16:27:37.839Z,1598891257.839 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2020-08-31T16:27:37.839Z,1598891257.839 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2020-08-31T16:27:37.858Z,1598891257.858 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2020-08-31T16:27:37.973Z,1598891257.973 [MissionManager](DEBUG): 2020-08-31T16:27:37.974Z,1598891257.974 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2020-08-31T16:27:38.070Z,1598891258.070 [Radio_Surface](INFO): Powering up 2020-08-31T16:27:38.108Z,1598891258.108 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2020-08-31T16:27:38.117Z,1598891258.117 [Default:A.Wait](DEBUG): Construct Wait. 2020-08-31T16:27:38.119Z,1598891258.119 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2020-08-31T16:27:38.163Z,1598891258.163 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2020-08-31T16:27:38.210Z,1598891258.210 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2020-08-31T16:27:38.216Z,1598891258.216 [Default:E.Execute](DEBUG): Construct Execute. 2020-08-31T16:27:38.235Z,1598891258.235 [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-08-31T16:27:38.239Z,1598891258.239 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,NAL9602,DAT,BPC1,AMEcho,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2020-08-31T16:27:38.250Z,1598891258.250 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2020-08-31T16:27:38.390Z,1598891258.390 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar 2020-08-31T16:27:38.394Z,1598891258.394 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2020-08-31T16:27:38.436Z,1598891258.436 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2020-08-31T16:27:38.436Z,1598891258.436 [DAT](INFO): Powering up 2020-08-31T16:27:38.436Z,1598891258.436 [DAT](DEBUG): Initializing DAT. 2020-08-31T16:27:38.490Z,1598891258.490 [AMEcho](INFO): Powering up 2020-08-31T16:27:38.506Z,1598891258.506 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-08-31T16:27:38.556Z,1598891258.556 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2020-08-31T16:27:38.562Z,1598891258.562 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2020-08-31T16:27:38.563Z,1598891258.563 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-08-31T16:27:38.570Z,1598891258.570 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-08-31T16:27:38.571Z,1598891258.571 [MassServo](DEBUG): Initializing EZServoServo. 2020-08-31T16:27:38.578Z,1598891258.578 [MassServo](DEBUG): Initializing MassServo. 2020-08-31T16:27:38.579Z,1598891258.579 [RudderServo](DEBUG): Initializing EZServoServo. 2020-08-31T16:27:38.586Z,1598891258.586 [RudderServo](DEBUG): Initializing RudderServo. 2020-08-31T16:27:38.587Z,1598891258.587 [ThrusterServo](DEBUG): Initializing EZServoServo. 2020-08-31T16:27:38.594Z,1598891258.594 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2020-08-31T16:27:38.596Z,1598891258.596 [CommandLine](FAULT): Scheduling is paused 2020-08-31T16:27:38.597Z,1598891258.597 [CBIT](INFO): Critical error at 20200831T162737 2020-08-31T16:27:38.597Z,1598891258.597 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2020-08-31T16:27:38.846Z,1598891258.846 [AMEcho](INFO): Powering down 2020-08-31T16:27:38.847Z,1598891258.847 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-08-31T16:27:39.058Z,1598891259.058 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-08-31T16:27:47.065Z,1598891267.065 [BuoyancyServo](ERROR): getPosition uart error serial timeout 2020-08-31T16:27:47.066Z,1598891267.066 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout 2020-08-31T16:27:47.066Z,1598891267.066 [BuoyancyServo] Communications Fault, FailCount= 1 2020-08-31T16:27:47.066Z,1598891267.066 [BuoyancyServo](ERROR): Communications Fault 2020-08-31T16:27:47.097Z,1598891267.097 [CBIT](ERROR): Communications Fault in component: BuoyancyServo 2020-08-31T16:27:48.771Z,1598891268.771 [DAT](INFO): DAT read: 2020-08-31T16:27:48.773Z,1598891268.773 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2020-08-31T16:27:48.829Z,1598891268.829 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2020-08-31T16:27:48.830Z,1598891268.830 [BuoyancyServo](INFO): Powering down 2020-08-31T16:27:49.178Z,1598891269.178 [BuoyancyServo](FAULT): LCB fault: Current Limiter Activated. 2020-08-31T16:27:49.178Z,1598891269.178 [BuoyancyServo] Hardware Fault, FailCount= 1 2020-08-31T16:27:49.179Z,1598891269.179 [BuoyancyServo](ERROR): Hardware Fault 2020-08-31T16:27:49.605Z,1598891269.605 [CBIT](INFO): Clearing failed state for component BuoyancyServo 2020-08-31T16:27:49.605Z,1598891269.605 [BuoyancyServo] No Fault, FailCount= 1 2020-08-31T16:27:49.967Z,1598891269.967 [DAT](INFO): DAT read: MF Frequency Band 2020-08-31T16:27:49.968Z,1598891269.968 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.12.21 2020-08-31T16:27:49.969Z,1598891269.969 [DAT](INFO): DAT read: Aug 31 2020 16:27:26 2020-08-31T16:27:49.998Z,1598891269.998 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2020-08-31T16:27:50.006Z,1598891270.006 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2020-08-31T16:27:50.775Z,1598891270.775 [DAT](INFO): DAT read: Features enabled [Bearing] 2020-08-31T16:27:50.777Z,1598891270.777 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-31T16:27:50.777Z,1598891270.777 [DAT](INFO): commRate: 800 2020-08-31T16:27:50.777Z,1598891270.777 [DAT](INFO): commRate: 800 2020-08-31T16:27:51.179Z,1598891271.179 [DAT](INFO): entering command mode 2020-08-31T16:27:51.268Z,1598891271.268 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004855 2020-08-31T16:27:51.583Z,1598891271.583 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:51.987Z,1598891271.987 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:52.403Z,1598891272.403 [DAT](INFO): DAT read: 2020-08-31T16:27:52.403Z,1598891272.403 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:52.795Z,1598891272.795 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:53.199Z,1598891273.199 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:53.611Z,1598891273.611 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:54.007Z,1598891274.007 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:54.411Z,1598891274.411 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:54.815Z,1598891274.815 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:55.219Z,1598891275.219 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:55.623Z,1598891275.623 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:56.035Z,1598891276.035 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:56.431Z,1598891276.431 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:56.835Z,1598891276.835 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:57.239Z,1598891277.239 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:57.643Z,1598891277.643 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:58.047Z,1598891278.047 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:58.451Z,1598891278.451 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:58.855Z,1598891278.855 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:59.259Z,1598891279.259 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:27:59.663Z,1598891279.663 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:00.067Z,1598891280.067 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:00.471Z,1598891280.471 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:00.879Z,1598891280.879 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:01.279Z,1598891281.279 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:01.683Z,1598891281.683 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:02.087Z,1598891282.087 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:02.491Z,1598891282.491 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:02.895Z,1598891282.895 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:03.299Z,1598891283.299 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:03.703Z,1598891283.703 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:04.109Z,1598891284.109 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:04.515Z,1598891284.515 [NAL9602](INFO): Powering up NAL9602 2020-08-31T16:28:04.516Z,1598891284.516 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:04.915Z,1598891284.915 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:05.323Z,1598891285.323 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:05.723Z,1598891285.723 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:06.127Z,1598891286.127 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:06.531Z,1598891286.531 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:28:06.531Z,1598891286.531 [DAT](FAULT): failed to enter command mode 2020-08-31T16:28:06.935Z,1598891286.935 [DAT](INFO): entering command mode 2020-08-31T16:28:07.339Z,1598891287.339 [DAT](INFO): DAT read: user:1> 2020-08-31T16:28:07.340Z,1598891287.340 [DAT](INFO): DAT read: Command '+++' not found 2020-08-31T16:28:07.340Z,1598891287.340 [DAT](INFO): DAT read: Error 2020-08-31T16:28:07.341Z,1598891287.341 [DAT](INFO): setting verbose to 3 2020-08-31T16:28:07.743Z,1598891287.743 [DAT](INFO): DAT read: user:2> 2020-08-31T16:28:07.744Z,1598891287.744 [DAT](INFO): DAT read: Verbose | 3 2020-08-31T16:28:07.744Z,1598891287.744 [DAT](INFO): set verbose to 3 2020-08-31T16:28:07.745Z,1598891287.745 [DAT](INFO): setting DatVerbose to 27440 2020-08-31T16:28:08.155Z,1598891288.155 [DAT](INFO): DAT read: user:3> 2020-08-31T16:28:08.156Z,1598891288.156 [DAT](INFO): DAT read: DatVerbose | 27440 2020-08-31T16:28:08.156Z,1598891288.156 [DAT](INFO): set DatVerbose to 27440 2020-08-31T16:28:08.157Z,1598891288.157 [DAT](INFO): setting transmit power to 8 2020-08-31T16:28:08.551Z,1598891288.551 [DAT](INFO): DAT read: user:4> 2020-08-31T16:28:08.552Z,1598891288.552 [DAT](INFO): DAT read: TxPower | 8 (Max) 2020-08-31T16:28:08.552Z,1598891288.552 [DAT](INFO): set transmit power to 8 2020-08-31T16:28:08.553Z,1598891288.553 [DAT](INFO): setting local address to 9 2020-08-31T16:28:08.955Z,1598891288.955 [DAT](INFO): DAT read: user:5> 2020-08-31T16:28:08.956Z,1598891288.956 [DAT](INFO): DAT read: LocalAddr | 9 2020-08-31T16:28:08.956Z,1598891288.956 [DAT](INFO): set local address to 9 2020-08-31T16:28:15.447Z,1598891295.447 [NAL9602](INFO): NAL9602 initialized 2020-08-31T16:28:43.352Z,1598891323.352 [SBIT](IMPORTANT): Beginning Startup BIT 2020-08-31T16:28:43.356Z,1598891323.356 [CBIT](IMPORTANT): Beginning ground fault scan 2020-08-31T16:28:54.381Z,1598891334.381 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.011218 CHAN A1 (24V): -0.000923 CHAN A2 (12V): -0.007598 CHAN A3 (5V): -0.002184 CHAN B0 (3.3V): -0.000207 CHAN B1 (3.15aV): 0.000024 CHAN B2 (3.15bV): -0.000557 CHAN B3 (GND): 0.001939 OPEN: 0.005273 Full Scale Calc: 4.765 mA, -1.589 mA 2020-08-31T16:29:01.554Z,1598891341.554 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:29:14.881Z,1598891354.881 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2020-08-31T16:29:31.460Z,1598891371.460 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:29:37.062Z,1598891377.062 [SBIT](IMPORTANT): SBIT PASSED 2020-08-31T16:29:37.062Z,1598891377.062 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2020-08-31T16:29:37.063Z,1598891377.063 [SBIT](IMPORTANT): BackSeatDriver.loadAtStartup=1 bool; 2020-08-31T16:29:37.063Z,1598891377.063 [SBIT](IMPORTANT): CBIT.gf24Offset=145 microampere; 2020-08-31T16:29:37.063Z,1598891377.063 [SBIT](IMPORTANT): DAT.sbdAddress=6 enum; 2020-08-31T16:29:37.063Z,1598891377.063 [SBIT](IMPORTANT): DAT.surfaceThreshold=-1 meter; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): DAT.verbosity=3 count; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): Express none ThrusterServo.component_avgCurrent; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 1.000000 liter_per_second; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): RDI_Pathfinder.loadAtStartup=0 bool; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=344.685708 cubic_centimeter; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): VerticalControl.massDefault=11.293600 millimeter; 2020-08-31T16:29:37.064Z,1598891377.064 [SBIT](IMPORTANT): WetLabsUBAT.loadAtStartup=0 bool; 2020-08-31T16:29:37.458Z,1598891377.458 [MissionManager](IMPORTANT): Started mission Startup 2020-08-31T16:29:37.459Z,1598891377.459 [Startup] Running Loop=1 2020-08-31T16:29:37.459Z,1598891377.459 [Startup](DEBUG): Aggregate::initialize Startup 2020-08-31T16:29:37.459Z,1598891377.459 [Startup:A.GoToSurface] Running Loop=1 2020-08-31T16:29:37.459Z,1598891377.459 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-31T16:29:37.459Z,1598891377.459 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-31T16:29:37.460Z,1598891377.460 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-31T16:29:37.460Z,1598891377.460 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-31T16:29:37.461Z,1598891377.461 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-31T16:29:37.461Z,1598891377.461 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-31T16:29:37.463Z,1598891377.463 [Startup:StartupSatComms] Running Loop=1 2020-08-31T16:29:37.463Z,1598891377.463 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2020-08-31T16:29:37.463Z,1598891377.463 [Startup:StartupSatComms:A] Running Loop=1 2020-08-31T16:29:37.879Z,1598891377.879 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2020-08-31T16:29:38.253Z,1598891378.253 [AMEcho](INFO): Powering up 2020-08-31T16:29:49.568Z,1598891389.568 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:30:36.733Z,1598891436.733 [CommandLine](IMPORTANT): got command strobe off 2020-08-31T16:30:36.733Z,1598891436.733 [CommandLine](IMPORTANT): Deactivating strobe 2020-08-31T16:30:37.661Z,1598891437.661 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2020-08-31T16:30:37.661Z,1598891437.661 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-31T16:30:37.663Z,1598891437.663 [Startup:StartupSatComms:A](INFO): Timed out from 2020-08-31T16:29:37.5Z 2020-08-31T16:30:37.663Z,1598891437.663 [Startup:StartupSatComms:A] Stopped 2020-08-31T16:30:37.663Z,1598891437.663 [Startup:StartupSatComms:B] Running Loop=1 2020-08-31T16:30:37.730Z,1598891437.730 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-31T16:30:38.058Z,1598891438.058 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-08-31T16:30:38.087Z,1598891438.087 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-31T16:30:38.087Z,1598891438.087 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2020-08-31T16:30:38.570Z,1598891438.570 [DAT](INFO): #Outgoing data=1 2020-08-31T16:30:38.570Z,1598891438.570 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:30:38.955Z,1598891438.955 [DAT](INFO): setting remote address to 6 2020-08-31T16:30:39.374Z,1598891439.374 [DAT](INFO): DAT read: user:6> 2020-08-31T16:30:39.375Z,1598891439.375 [DAT](INFO): DAT read: RemoteAddr | 6 2020-08-31T16:30:39.375Z,1598891439.375 [DAT](INFO): set remote address to 6 2020-08-31T16:30:39.376Z,1598891439.376 [DAT](INFO): entering online mode 2020-08-31T16:30:39.782Z,1598891439.782 [DAT](INFO): DAT read: user:7> 2020-08-31T16:30:39.783Z,1598891439.783 [DAT](INFO): DAT read: 2020-08-31T16:30:39.784Z,1598891439.784 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-31T16:30:39.785Z,1598891439.785 [DAT](INFO): commRate: 800 2020-08-31T16:30:39.785Z,1598891439.785 [DAT](INFO): online mode acknowledged 2020-08-31T16:30:39.786Z,1598891439.786 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:30:42.558Z,1598891442.558 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20200831T162726/Courier0000.lzma 2020-08-31T16:30:43.224Z,1598891443.224 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:30:23.1559 2020-08-31T16:30:43.224Z,1598891443.224 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:30:43.559Z,1598891443.559 [DataOverHttps](INFO): Moved sent file to Logs/20200831T162726/Courier0000.lzma.bak 2020-08-31T16:30:43.559Z,1598891443.559 [DataOverHttps](INFO): SBD MOMSN=12625555 2020-08-31T16:30:45.158Z,1598891445.158 [CommandLine](IMPORTANT): got command show stack 2020-08-31T16:30:45.158Z,1598891445.158 [CommandLine](IMPORTANT): Behavior Stack: 2020-08-31T16:30:45.159Z,1598891445.159 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface 2020-08-31T16:30:45.159Z,1598891445.159 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B 2020-08-31T16:30:47.759Z,1598891447.759 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:30:59.043Z,1598891459.043 [DataOverHttps](INFO): Sending 1131 bytes from file Logs/20200831T162726/Express0001.lzma 2020-08-31T16:30:59.788Z,1598891459.788 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:30:59.789Z,1598891459.789 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:31:00.043Z,1598891460.043 [DataOverHttps](INFO): Moved sent file to Logs/20200831T162726/Express0001.lzma.bak 2020-08-31T16:31:00.043Z,1598891460.043 [DataOverHttps](INFO): SBD MOMSN=12625559 2020-08-31T16:31:00.208Z,1598891460.208 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:31:00.238Z,1598891460.238 [Startup:StartupSatComms:B] Stopped 2020-08-31T16:31:00.238Z,1598891460.238 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2020-08-31T16:31:00.238Z,1598891460.238 [Startup:StartupSatComms] Stopped 2020-08-31T16:31:00.238Z,1598891460.238 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2020-08-31T16:31:00.239Z,1598891460.239 [Startup](INFO): Completed Startup 2020-08-31T16:31:00.239Z,1598891460.239 [MissionManager](INFO): Startup is completed. 2020-08-31T16:31:00.239Z,1598891460.239 [MissionManager](INFO): Uninitializing Mission Startup 2020-08-31T16:31:00.239Z,1598891460.239 [Startup] Stopped 2020-08-31T16:31:00.240Z,1598891460.240 [Startup](DEBUG): Aggregate::uninitialize Startup 2020-08-31T16:31:00.240Z,1598891460.240 [Startup:A.GoToSurface] Stopped 2020-08-31T16:31:00.240Z,1598891460.240 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-31T16:31:00.615Z,1598891460.615 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:31:00.818Z,1598891460.818 [MissionManager](IMPORTANT): Started mission Default 2020-08-31T16:31:00.818Z,1598891460.818 [Default] Running Loop=1 2020-08-31T16:31:00.818Z,1598891460.818 [Default](DEBUG): Aggregate::initialize Default 2020-08-31T16:31:00.818Z,1598891460.818 [Default:B.GoToSurface] Running Loop=1 2020-08-31T16:31:00.819Z,1598891460.819 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-31T16:31:00.819Z,1598891460.819 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-31T16:31:00.819Z,1598891460.819 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-31T16:31:00.819Z,1598891460.819 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-31T16:31:00.820Z,1598891460.820 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-31T16:31:00.820Z,1598891460.820 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-31T16:31:00.820Z,1598891460.820 [Default:A.Wait] Running Loop=1 2020-08-31T16:31:00.820Z,1598891460.820 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-31T16:31:01.178Z,1598891461.178 [AMEcho](INFO): Powering down 2020-08-31T16:31:02.278Z,1598891462.278 [AMEcho](INFO): Powering up 2020-08-31T16:31:04.229Z,1598891464.229 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:30:44.0059 2020-08-31T16:31:04.229Z,1598891464.229 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:31:13.945Z,1598891473.945 [Default:A.Wait](INFO): Done Waiting. 2020-08-31T16:31:13.945Z,1598891473.945 [Default:A.Wait] Stopped 2020-08-31T16:31:13.945Z,1598891473.945 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-31T16:31:14.358Z,1598891474.358 [Default:CheckIn] Running Loop=1 2020-08-31T16:31:14.358Z,1598891474.358 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-31T16:31:14.359Z,1598891474.359 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-31T16:31:14.747Z,1598891474.747 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2020-08-31T16:31:20.792Z,1598891480.792 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:31:20.792Z,1598891480.792 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:31:21.210Z,1598891481.210 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:31:21.611Z,1598891481.611 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:31:25.237Z,1598891485.237 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:31:04.9561 2020-08-31T16:31:25.237Z,1598891485.237 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:31:41.800Z,1598891501.800 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:31:41.800Z,1598891501.800 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:31:42.218Z,1598891502.218 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:31:42.623Z,1598891502.623 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:31:46.250Z,1598891506.250 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:31:26.0059 2020-08-31T16:31:46.251Z,1598891506.251 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:32:01.256Z,1598891521.256 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:32:02.812Z,1598891522.812 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:32:02.812Z,1598891522.812 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:32:03.226Z,1598891523.226 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:32:36.352Z,1598891556.352 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-08-31T16:32:36.356Z,1598891556.356 [BPC1](ERROR): BPC1A failed to parse battery stick message. 2020-08-31T16:33:01.588Z,1598891581.588 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2020-08-31T16:33:01.588Z,1598891581.588 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml 2020-08-31T16:33:01.604Z,1598891581.604 [MissionManager](DEBUG): 2020-08-31T16:33:01.606Z,1598891581.606 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2020-08-31T16:33:01.832Z,1598891581.832 [Default] Stopped 2020-08-31T16:33:01.832Z,1598891581.832 [Default](DEBUG): Aggregate::uninitialize Default 2020-08-31T16:33:01.832Z,1598891581.832 [Default:B.GoToSurface] Stopped 2020-08-31T16:33:01.832Z,1598891581.832 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-31T16:33:01.832Z,1598891581.832 [Default:CheckIn] Stopped 2020-08-31T16:33:01.832Z,1598891581.832 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-31T16:33:01.832Z,1598891581.832 [Default:CheckIn:Read_GPS] Stopped 2020-08-31T16:33:01.833Z,1598891581.833 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2020-08-31T16:33:01.833Z,1598891581.833 [senddata_direct_test] Running Loop=1 2020-08-31T16:33:01.833Z,1598891581.833 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2020-08-31T16:33:01.833Z,1598891581.833 [senddata_direct_test:A] Running Loop=1 2020-08-31T16:33:01.834Z,1598891581.834 [senddata_direct_test:A] Stopped 2020-08-31T16:33:01.834Z,1598891581.834 [senddata_direct_test:B] Running Loop=1 2020-08-31T16:33:02.211Z,1598891582.211 [DAT](INFO): modem://1: set _.pressure 0.513319 atmosphere 2020-08-31T16:33:02.211Z,1598891582.211 [DAT](INFO): #Outgoing data=1 2020-08-31T16:33:02.211Z,1598891582.211 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:33:02.309Z,1598891582.309 [senddata_direct_test:B] Stopped 2020-08-31T16:33:02.310Z,1598891582.310 [senddata_direct_test:C] Running Loop=1 2020-08-31T16:33:02.606Z,1598891582.606 [DAT](INFO): entering command mode 2020-08-31T16:33:02.622Z,1598891582.622 [senddata_direct_test:C] Stopped 2020-08-31T16:33:02.622Z,1598891582.622 [senddata_direct_test](INFO): Completed senddata_direct_test 2020-08-31T16:33:02.622Z,1598891582.622 [MissionManager](INFO): senddata_direct_test is completed. 2020-08-31T16:33:02.622Z,1598891582.622 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2020-08-31T16:33:02.622Z,1598891582.622 [senddata_direct_test] Stopped 2020-08-31T16:33:02.623Z,1598891582.623 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2020-08-31T16:33:03.011Z,1598891583.011 [DAT](INFO): DAT read: 2020-08-31T16:33:03.012Z,1598891583.012 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:03.052Z,1598891583.052 [MissionManager](IMPORTANT): Started mission Default 2020-08-31T16:33:03.052Z,1598891583.052 [Default] Running Loop=1 2020-08-31T16:33:03.052Z,1598891583.052 [Default](DEBUG): Aggregate::initialize Default 2020-08-31T16:33:03.053Z,1598891583.053 [Default:B.GoToSurface] Running Loop=1 2020-08-31T16:33:03.053Z,1598891583.053 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-31T16:33:03.053Z,1598891583.053 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-31T16:33:03.054Z,1598891583.054 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-31T16:33:03.055Z,1598891583.055 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-31T16:33:03.055Z,1598891583.055 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-31T16:33:03.055Z,1598891583.055 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-31T16:33:03.056Z,1598891583.056 [Default:A.Wait] Running Loop=1 2020-08-31T16:33:03.056Z,1598891583.056 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-31T16:33:03.408Z,1598891583.408 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:03.812Z,1598891583.812 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:04.223Z,1598891584.223 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:04.620Z,1598891584.620 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:05.024Z,1598891585.024 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:05.428Z,1598891585.428 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:05.498Z,1598891585.498 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2020-08-31T16:33:05.837Z,1598891585.837 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:06.253Z,1598891586.253 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:06.654Z,1598891586.654 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:07.058Z,1598891587.058 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:07.466Z,1598891587.466 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:07.852Z,1598891587.852 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:08.256Z,1598891588.256 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:08.660Z,1598891588.660 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:09.071Z,1598891589.071 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:09.468Z,1598891589.468 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:09.872Z,1598891589.872 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:10.276Z,1598891590.276 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:10.686Z,1598891590.686 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:11.085Z,1598891591.085 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:11.502Z,1598891591.502 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:11.906Z,1598891591.906 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:12.310Z,1598891592.310 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:12.714Z,1598891592.714 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:13.107Z,1598891593.107 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:13.508Z,1598891593.508 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:13.912Z,1598891593.912 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:14.324Z,1598891594.324 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:14.720Z,1598891594.720 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:15.124Z,1598891595.124 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:15.528Z,1598891595.528 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:15.938Z,1598891595.938 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:16.336Z,1598891596.336 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:16.344Z,1598891596.344 [Default:A.Wait](INFO): Done Waiting. 2020-08-31T16:33:16.344Z,1598891596.344 [Default:A.Wait] Stopped 2020-08-31T16:33:16.344Z,1598891596.344 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-31T16:33:16.754Z,1598891596.754 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:16.780Z,1598891596.780 [Default:CheckIn] Running Loop=1 2020-08-31T16:33:16.780Z,1598891596.780 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-31T16:33:16.780Z,1598891596.780 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-31T16:33:17.158Z,1598891597.158 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:17.568Z,1598891597.568 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:17.972Z,1598891597.972 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:33:17.972Z,1598891597.972 [DAT](FAULT): failed to enter command mode 2020-08-31T16:33:17.972Z,1598891597.972 [DAT](ERROR): Failure setting remote address to 1 2020-08-31T16:33:18.359Z,1598891598.359 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-08-31T16:33:18.361Z,1598891598.361 [DAT](INFO): entering command mode 2020-08-31T16:33:18.764Z,1598891598.764 [DAT](INFO): DAT read: user:8> 2020-08-31T16:33:18.764Z,1598891598.764 [DAT](INFO): DAT read: Command '+++' not found 2020-08-31T16:33:18.765Z,1598891598.765 [DAT](INFO): DAT read: Error 2020-08-31T16:33:18.765Z,1598891598.765 [DAT](INFO): setting remote address to 1 2020-08-31T16:33:19.182Z,1598891599.182 [DAT](INFO): DAT read: user:9> 2020-08-31T16:33:19.183Z,1598891599.183 [DAT](INFO): DAT read: RemoteAddr | 1 2020-08-31T16:33:19.184Z,1598891599.184 [DAT](INFO): set remote address to 1 2020-08-31T16:33:19.184Z,1598891599.184 [DAT](INFO): entering online mode 2020-08-31T16:33:19.569Z,1598891599.569 [DAT](INFO): DAT read: user:10> 2020-08-31T16:33:19.570Z,1598891599.570 [DAT](INFO): DAT read: 2020-08-31T16:33:19.571Z,1598891599.571 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-31T16:33:19.571Z,1598891599.571 [DAT](INFO): commRate: 800 2020-08-31T16:33:19.571Z,1598891599.571 [DAT](INFO): online mode acknowledged 2020-08-31T16:33:19.572Z,1598891599.572 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:33:23.210Z,1598891603.210 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:33:02.8059 2020-08-31T16:33:23.210Z,1598891603.210 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:33:30.958Z,1598891610.958 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:33:38.581Z,1598891618.581 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2020-08-31T16:33:38.581Z,1598891618.581 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-31T16:33:38.622Z,1598891618.622 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-31T16:33:38.994Z,1598891618.994 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-31T16:33:38.994Z,1598891618.994 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2020-08-31T16:33:39.768Z,1598891619.768 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:33:39.768Z,1598891619.768 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:33:40.172Z,1598891620.172 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:33:40.578Z,1598891620.578 [DAT](INFO): modem://1: set _.temperature 23.332941 celsius 2020-08-31T16:33:40.578Z,1598891620.578 [DAT](INFO): #Outgoing data=1 2020-08-31T16:33:40.578Z,1598891620.578 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:33:40.991Z,1598891620.991 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:33:44.220Z,1598891624.220 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:33:24.2059 2020-08-31T16:33:44.220Z,1598891624.220 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:34:01.194Z,1598891641.194 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:34:01.194Z,1598891641.194 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:34:01.586Z,1598891641.586 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:34:01.992Z,1598891641.992 [DAT](INFO): modem://1: set _.humidity 28.134541 percent 2020-08-31T16:34:01.992Z,1598891641.992 [DAT](INFO): #Outgoing data=1 2020-08-31T16:34:01.992Z,1598891641.992 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:34:02.400Z,1598891642.400 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:34:05.626Z,1598891645.626 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:33:45.6059 2020-08-31T16:34:05.626Z,1598891645.626 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:34:12.961Z,1598891652.961 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:34:15.000Z,1598891656.000 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2020-08-31T16:34:16.001Z,1598891656.001 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml 2020-08-31T16:34:16.030Z,1598891656.030 [MissionManager](DEBUG): 2020-08-31T16:34:16.031Z,1598891656.031 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2020-08-31T16:34:16.154Z,1598891656.154 [Default] Stopped 2020-08-31T16:34:16.154Z,1598891656.154 [Default](DEBUG): Aggregate::uninitialize Default 2020-08-31T16:34:16.155Z,1598891656.155 [Default:B.GoToSurface] Stopped 2020-08-31T16:34:16.155Z,1598891656.155 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-31T16:34:16.155Z,1598891656.155 [Default:CheckIn] Stopped 2020-08-31T16:34:16.155Z,1598891656.155 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-31T16:34:16.155Z,1598891656.155 [Default:CheckIn:Read_GPS] Stopped 2020-08-31T16:34:16.155Z,1598891656.155 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2020-08-31T16:34:16.155Z,1598891656.155 [senddata_direct_test] Running Loop=1 2020-08-31T16:34:16.155Z,1598891656.155 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2020-08-31T16:34:16.156Z,1598891656.156 [senddata_direct_test:A] Running Loop=1 2020-08-31T16:34:16.156Z,1598891656.156 [senddata_direct_test:A] Stopped 2020-08-31T16:34:16.156Z,1598891656.156 [senddata_direct_test:B] Running Loop=1 2020-08-31T16:34:16.544Z,1598891656.544 [senddata_direct_test:B] Stopped 2020-08-31T16:34:16.544Z,1598891656.544 [senddata_direct_test:C] Running Loop=1 2020-08-31T16:34:16.961Z,1598891656.961 [senddata_direct_test:C] Stopped 2020-08-31T16:34:16.961Z,1598891656.961 [senddata_direct_test](INFO): Completed senddata_direct_test 2020-08-31T16:34:16.961Z,1598891656.961 [MissionManager](INFO): senddata_direct_test is completed. 2020-08-31T16:34:16.961Z,1598891656.961 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2020-08-31T16:34:16.961Z,1598891656.961 [senddata_direct_test] Stopped 2020-08-31T16:34:16.961Z,1598891656.961 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2020-08-31T16:34:17.354Z,1598891657.354 [MissionManager](IMPORTANT): Started mission Default 2020-08-31T16:34:17.354Z,1598891657.354 [Default] Running Loop=1 2020-08-31T16:34:17.355Z,1598891657.355 [Default](DEBUG): Aggregate::initialize Default 2020-08-31T16:34:17.355Z,1598891657.355 [Default:B.GoToSurface] Running Loop=1 2020-08-31T16:34:17.355Z,1598891657.355 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-31T16:34:17.355Z,1598891657.355 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-31T16:34:17.355Z,1598891657.355 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-31T16:34:17.356Z,1598891657.356 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-31T16:34:17.356Z,1598891657.356 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-31T16:34:17.356Z,1598891657.356 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-31T16:34:17.356Z,1598891657.356 [Default:A.Wait] Running Loop=1 2020-08-31T16:34:17.357Z,1598891657.357 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-31T16:34:22.592Z,1598891662.592 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:34:22.592Z,1598891662.592 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:34:23.020Z,1598891663.020 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:34:23.402Z,1598891663.402 [DAT](INFO): modem://1: set _.pressure 0.515145 atmosphere 2020-08-31T16:34:23.402Z,1598891663.402 [DAT](INFO): #Outgoing data=1 2020-08-31T16:34:23.402Z,1598891663.402 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:34:23.479Z,1598891663.479 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-31T16:34:23.806Z,1598891663.806 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:34:27.037Z,1598891667.037 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:34:07.0075 2020-08-31T16:34:27.037Z,1598891667.037 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:34:30.700Z,1598891670.700 [Default:A.Wait](INFO): Done Waiting. 2020-08-31T16:34:30.700Z,1598891670.700 [Default:A.Wait] Stopped 2020-08-31T16:34:30.700Z,1598891670.700 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-31T16:34:31.107Z,1598891671.107 [Default:CheckIn] Running Loop=1 2020-08-31T16:34:31.107Z,1598891671.107 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-31T16:34:31.107Z,1598891671.107 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-31T16:34:44.005Z,1598891684.005 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:34:44.005Z,1598891684.005 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:34:44.412Z,1598891684.412 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:34:44.819Z,1598891684.819 [DAT](INFO): modem://1: set _.temperature 23.332941 celsius 2020-08-31T16:34:44.819Z,1598891684.819 [DAT](INFO): #Outgoing data=1 2020-08-31T16:34:44.820Z,1598891684.820 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:34:45.220Z,1598891685.220 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:34:48.467Z,1598891688.467 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:34:28.4058 2020-08-31T16:34:48.467Z,1598891688.467 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:35:05.430Z,1598891705.430 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:35:05.430Z,1598891705.430 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:35:05.816Z,1598891705.816 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:35:06.225Z,1598891706.225 [DAT](INFO): modem://1: set _.humidity 28.158955 percent 2020-08-31T16:35:06.225Z,1598891706.225 [DAT](INFO): #Outgoing data=1 2020-08-31T16:35:06.225Z,1598891706.225 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:35:06.234Z,1598891706.234 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2020-08-31T16:35:06.237Z,1598891706.237 [BPC1](INFO): Received data from all battery sticks. 2020-08-31T16:35:06.633Z,1598891706.633 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:35:09.869Z,1598891709.869 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:34:49.8558 2020-08-31T16:35:09.869Z,1598891709.869 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:35:26.828Z,1598891726.828 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:35:26.828Z,1598891726.828 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:35:27.239Z,1598891727.239 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:36:39.577Z,1598891799.577 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2020-08-31T16:36:39.577Z,1598891799.577 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-31T16:36:39.587Z,1598891799.587 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-31T16:36:40.006Z,1598891800.006 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-31T16:36:40.006Z,1598891800.006 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2020-08-31T16:38:17.315Z,1598891897.315 [NAL9602](FAULT): GPS failed to acquire within timeout. 2020-08-31T16:38:17.315Z,1598891897.315 [NAL9602] Data Fault, FailCount= 1 2020-08-31T16:38:17.315Z,1598891897.315 [NAL9602](ERROR): Data Fault 2020-08-31T16:38:17.365Z,1598891897.365 [CBIT](ERROR): Data Fault in component: NAL9602 2020-08-31T16:38:17.719Z,1598891897.719 [NAL9602](INFO): Powering down 2020-08-31T16:38:18.550Z,1598891898.550 [CBIT](INFO): Clearing failed state for component NAL9602 2020-08-31T16:38:18.550Z,1598891898.550 [NAL9602] No Fault, FailCount= 1 2020-08-31T16:38:48.020Z,1598891928.020 [NAL9602](INFO): Powering up NAL9602 2020-08-31T16:38:58.923Z,1598891938.923 [NAL9602](INFO): NAL9602 initialized 2020-08-31T16:39:31.275Z,1598891971.275 [Default:CheckIn:Read_GPS](INFO): Timed out from 2020-08-31T16:34:31.1Z 2020-08-31T16:39:31.275Z,1598891971.275 [Default:CheckIn:Read_GPS] Stopped 2020-08-31T16:39:31.275Z,1598891971.275 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-31T16:39:31.683Z,1598891971.683 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-08-31T16:39:32.059Z,1598891972.059 [DAT](INFO): #Outgoing data=1 2020-08-31T16:39:32.059Z,1598891972.059 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-31T16:39:32.462Z,1598891972.462 [DAT](INFO): entering command mode 2020-08-31T16:39:32.864Z,1598891972.864 [DAT](INFO): DAT read: 2020-08-31T16:39:32.865Z,1598891972.865 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:33.274Z,1598891973.274 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:33.670Z,1598891973.670 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:34.090Z,1598891974.090 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:34.502Z,1598891974.502 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:34.898Z,1598891974.898 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:35.291Z,1598891975.291 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:35.711Z,1598891975.711 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:36.097Z,1598891976.097 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:36.507Z,1598891976.507 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:36.922Z,1598891976.922 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:37.322Z,1598891977.322 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:37.733Z,1598891977.733 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:38.116Z,1598891978.116 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:38.273Z,1598891978.273 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20200831T162726/Courier0004.lzma 2020-08-31T16:39:38.516Z,1598891978.516 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:38.929Z,1598891978.929 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:39.275Z,1598891979.275 [DataOverHttps](INFO): Moved sent file to Logs/20200831T162726/Courier0004.lzma.bak 2020-08-31T16:39:39.275Z,1598891979.275 [DataOverHttps](INFO): SBD MOMSN=12625590 2020-08-31T16:39:39.333Z,1598891979.333 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:39.735Z,1598891979.735 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:40.150Z,1598891980.150 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:40.558Z,1598891980.558 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:40.569Z,1598891980.569 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2020-08-31T16:39:40.569Z,1598891980.569 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-31T16:39:40.579Z,1598891980.579 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-31T16:39:40.958Z,1598891980.958 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:40.978Z,1598891980.978 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-31T16:39:40.978Z,1598891980.978 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2020-08-31T16:39:41.348Z,1598891981.348 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:41.752Z,1598891981.752 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:42.156Z,1598891982.156 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:42.571Z,1598891982.571 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:42.978Z,1598891982.978 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:43.382Z,1598891983.382 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:43.790Z,1598891983.790 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:44.187Z,1598891984.187 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:44.580Z,1598891984.580 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:44.992Z,1598891984.992 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:45.395Z,1598891985.395 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:45.806Z,1598891985.806 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:46.216Z,1598891986.216 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:46.610Z,1598891986.610 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:47.004Z,1598891987.004 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:47.413Z,1598891987.413 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:47.829Z,1598891987.829 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-31T16:39:47.829Z,1598891987.829 [DAT](FAULT): failed to enter command mode 2020-08-31T16:39:47.829Z,1598891987.829 [DAT](ERROR): Failure setting remote address to 6 2020-08-31T16:39:48.231Z,1598891988.231 [DAT](INFO): entering command mode 2020-08-31T16:39:48.634Z,1598891988.634 [DAT](INFO): DAT read: user:11> 2020-08-31T16:39:48.635Z,1598891988.635 [DAT](INFO): DAT read: Command '+++' not found 2020-08-31T16:39:48.635Z,1598891988.635 [DAT](INFO): DAT read: Error 2020-08-31T16:39:48.636Z,1598891988.636 [DAT](INFO): setting remote address to 6 2020-08-31T16:39:49.024Z,1598891989.024 [DAT](INFO): DAT read: user:12> 2020-08-31T16:39:49.034Z,1598891989.034 [DAT](INFO): DAT read: RemoteAddr | 6 2020-08-31T16:39:49.034Z,1598891989.034 [DAT](INFO): set remote address to 6 2020-08-31T16:39:49.035Z,1598891989.035 [DAT](INFO): entering online mode 2020-08-31T16:39:49.428Z,1598891989.428 [DAT](INFO): DAT read: user:13> 2020-08-31T16:39:49.428Z,1598891989.428 [DAT](INFO): DAT read: 2020-08-31T16:39:49.430Z,1598891989.430 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-31T16:39:49.430Z,1598891989.430 [DAT](INFO): commRate: 800 2020-08-31T16:39:49.430Z,1598891989.430 [DAT](INFO): online mode acknowledged 2020-08-31T16:39:49.431Z,1598891989.431 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-31T16:39:53.086Z,1598891993.086 [DAT](INFO): DAT read: Forwarding Delay UpTx time:16:39:32.8055 2020-08-31T16:39:53.086Z,1598891993.086 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-31T16:39:54.778Z,1598891994.778 [DataOverHttps](INFO): Sending 502 bytes from file Logs/20200831T162726/Express0005.lzma 2020-08-31T16:39:55.779Z,1598891995.779 [DataOverHttps](INFO): Moved sent file to Logs/20200831T162726/Express0005.lzma.bak 2020-08-31T16:39:55.779Z,1598891995.779 [DataOverHttps](INFO): SBD MOMSN=12625592 2020-08-31T16:39:57.112Z,1598891997.112 [Default:CheckIn:Read_Iridium] Stopped 2020-08-31T16:39:57.112Z,1598891997.112 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-31T16:39:57.113Z,1598891997.113 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-31T16:40:09.645Z,1598892009.645 [DAT](FAULT): Ack receipt timeout failure. 2020-08-31T16:40:09.645Z,1598892009.645 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-31T16:40:10.028Z,1598892010.028 [DAT](INFO): Sent 168 bytes from file Logs/20200831T162726/Courier0004.lzma.parts 2020-08-31T16:40:10.028Z,1598892010.028 [DAT](INFO): Packets left to send: 0 2020-08-31T16:40:10.031Z,1598892010.031 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER 2020-08-31T16:41:52.790Z,1598892112.790 [CommandLine](IMPORTANT): got command quit 2020-08-31T16:41:53.793Z,1598892113.793 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2020-08-31T16:41:53.794Z,1598892113.794 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:53.794Z,1598892113.794 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:53.913Z,1598892113.913 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2020-08-31T16:41:53.913Z,1598892113.913 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:53.914Z,1598892113.914 [CommandLine](INFO): Join timeout helper Thread ID is 4747 2020-08-31T16:41:53.915Z,1598892113.915 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2020-08-31T16:41:53.915Z,1598892113.915 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:53.915Z,1598892113.915 [NavChartDb](INFO): Join timeout helper Thread ID is 4748 2020-08-31T16:41:53.958Z,1598892113.958 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:53.958Z,1598892113.958 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:53.965Z,1598892113.965 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2020-08-31T16:41:53.965Z,1598892113.965 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:53.966Z,1598892113.966 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 4749 2020-08-31T16:41:54.342Z,1598892114.342 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:54.342Z,1598892114.342 [WetLabsBB2FL](INFO): Powering down 2020-08-31T16:41:54.343Z,1598892114.343 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:54.361Z,1598892114.361 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2020-08-31T16:41:54.361Z,1598892114.361 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:54.362Z,1598892114.362 [CTD_Seabird](INFO): Join timeout helper Thread ID is 4750 2020-08-31T16:41:55.209Z,1598892115.209 [CTD_Seabird](INFO): Powering down 2020-08-31T16:41:55.221Z,1598892115.221 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:55.221Z,1598892115.221 [CTD_Seabird](INFO): Powering down 2020-08-31T16:41:55.237Z,1598892115.237 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:55.245Z,1598892115.245 [ComponentRegistry](INFO): Shutting down BackSeatDriver ThreadHandler 2020-08-31T16:41:55.245Z,1598892115.245 [BackSeatDriver ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:55.246Z,1598892115.246 [BackSeatDriver](INFO): Join timeout helper Thread ID is 4751 2020-08-31T16:41:55.586Z,1598892115.586 [BackSeatDriver ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:55.586Z,1598892115.586 [BackSeatDriver ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:55.606Z,1598892115.606 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2020-08-31T16:41:55.606Z,1598892115.606 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:55.607Z,1598892115.607 [Radio_Surface](INFO): Join timeout helper Thread ID is 4752 2020-08-31T16:41:55.973Z,1598892115.973 [Radio_Surface](INFO): Powering down 2020-08-31T16:41:55.974Z,1598892115.974 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:55.975Z,1598892115.975 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:55.990Z,1598892115.990 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler 2020-08-31T16:41:55.990Z,1598892115.990 [Onboard ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:55.991Z,1598892115.991 [Onboard](INFO): Join timeout helper Thread ID is 4753 2020-08-31T16:41:56.762Z,1598892116.762 [DataOverHttps](INFO): Radio surface powered OFF, will not connect. 2020-08-31T16:41:58.362Z,1598892118.362 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:58.362Z,1598892118.362 [Onboard ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:58.370Z,1598892118.370 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2020-08-31T16:41:58.370Z,1598892118.370 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:58.371Z,1598892118.371 [DataOverHttps](INFO): Join timeout helper Thread ID is 4754 2020-08-31T16:41:58.781Z,1598892118.781 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:58.782Z,1598892118.782 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:58.802Z,1598892118.802 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2020-08-31T16:41:58.802Z,1598892118.802 [logger ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:58.803Z,1598892118.803 [logger](INFO): Join timeout helper Thread ID is 4755 2020-08-31T16:41:58.822Z,1598892118.822 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:58.822Z,1598892118.822 [logger ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:58.842Z,1598892118.842 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2020-08-31T16:41:58.842Z,1598892118.842 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:58.842Z,1598892118.842 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2020-08-31T16:41:58.842Z,1598892118.842 [controlThread ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:58.843Z,1598892118.843 [controlThread](INFO): Join timeout helper Thread ID is 4756 2020-08-31T16:41:59.105Z,1598892119.105 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2020-08-31T16:41:59.106Z,1598892119.106 [controlThread](DEBUG): Uninitializing ControlThread 2020-08-31T16:41:59.106Z,1598892119.106 [AHRS_M2](INFO): Powering down 2020-08-31T16:41:59.178Z,1598892119.178 [NAL9602](INFO): Powering down 2020-08-31T16:41:59.179Z,1598892119.179 [DAT](INFO): Powering down 2020-08-31T16:41:59.465Z,1598892119.465 [AMEcho](INFO): Powering down 2020-08-31T16:41:59.466Z,1598892119.466 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2020-08-31T16:41:59.467Z,1598892119.467 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2020-08-31T16:41:59.468Z,1598892119.468 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2020-08-31T16:41:59.468Z,1598892119.468 [MissionManager](INFO): Uninitializing Mission Default 2020-08-31T16:41:59.468Z,1598892119.468 [Default] Stopped 2020-08-31T16:41:59.469Z,1598892119.469 [Default](DEBUG): Aggregate::uninitialize Default 2020-08-31T16:41:59.469Z,1598892119.469 [Default:B.GoToSurface] Stopped 2020-08-31T16:41:59.469Z,1598892119.469 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-31T16:41:59.469Z,1598892119.469 [Default:CheckIn] Stopped 2020-08-31T16:41:59.469Z,1598892119.469 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-31T16:41:59.469Z,1598892119.469 [Default:CheckIn:C.Wait] Stopped 2020-08-31T16:41:59.469Z,1598892119.469 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-31T16:41:59.472Z,1598892119.472 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2020-08-31T16:41:59.472Z,1598892119.472 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2020-08-31T16:41:59.472Z,1598892119.472 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2020-08-31T16:41:59.472Z,1598892119.472 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2020-08-31T16:41:59.473Z,1598892119.473 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2020-08-31T16:41:59.473Z,1598892119.473 [BuoyancyServo](INFO): Powering down 2020-08-31T16:41:59.485Z,1598892119.485 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2020-08-31T16:41:59.486Z,1598892119.486 [ElevatorServo](INFO): Powering down 2020-08-31T16:41:59.486Z,1598892119.486 [MassServo](DEBUG): Uninitialize Mass Servo. 2020-08-31T16:41:59.486Z,1598892119.486 [MassServo](INFO): Powering down 2020-08-31T16:41:59.487Z,1598892119.487 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2020-08-31T16:41:59.487Z,1598892119.487 [RudderServo](INFO): Powering down 2020-08-31T16:41:59.488Z,1598892119.488 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2020-08-31T16:41:59.488Z,1598892119.488 [ThrusterServo](INFO): Powering down 2020-08-31T16:41:59.489Z,1598892119.489 [SBIT](DEBUG): Uninitialize SBIT Component. 2020-08-31T16:41:59.489Z,1598892119.489 [IBIT](DEBUG): Uninitialize IBIT Component. 2020-08-31T16:41:59.490Z,1598892119.490 [CBIT](DEBUG): Uninitialize CBIT Component. 2020-08-31T16:41:59.490Z,1598892119.490 [CBIT](DEBUG): Powering off loads. 2020-08-31T16:41:59.501Z,1598892119.501 [CBIT](DEBUG): Disabling WDT. 2020-08-31T16:41:59.513Z,1598892119.513 [CBIT](DEBUG): Opening all GF detection circuits. 2020-08-31T16:41:59.514Z,1598892119.514 [controlThread ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.609Z,1598892119.609 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.611Z,1598892119.611 [Onboard ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.617Z,1598892119.617 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.676Z,1598892119.676 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.679Z,1598892119.679 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.683Z,1598892119.683 [BackSeatDriver ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.692Z,1598892119.692 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-08-31T16:41:59.755Z,1598892119.755 [logger ThreadHandler](INFO): Thread cancelled.