2020-12-11T23:55:25.135Z,1607730925.135 [Supervisor](DEBUG): Initializing supervisor. 2020-12-11T23:55:25.138Z,1607730925.138 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2020-12-11T23:55:25.138Z,1607730925.138 [SyncHandler](INFO): Protected caller Thread ID is 5942 2020-12-11T23:55:25.139Z,1607730925.139 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2020-12-11T23:55:25.140Z,1607730925.140 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2020-12-11T23:55:25.140Z,1607730925.140 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5943 2020-12-11T23:55:25.143Z,1607730925.143 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2020-12-11T23:55:25.161Z,1607730925.161 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2020-12-11T23:55:25.162Z,1607730925.162 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2020-12-11T23:55:25.162Z,1607730925.162 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5944 2020-12-11T23:55:25.163Z,1607730925.163 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2020-12-11T23:55:25.164Z,1607730925.164 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2020-12-11T23:55:25.164Z,1607730925.164 [logger ThreadHandler](INFO): Protected caller Thread ID is 5945 2020-12-11T23:55:25.166Z,1607730925.166 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2020-12-11T23:55:25.167Z,1607730925.167 [Supervisor](INFO): Looking for Config files in directory: Config/ 2020-12-11T23:55:25.168Z,1607730925.168 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2020-12-11T23:55:25.772Z,1607730925.772 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2020-12-11T23:55:25.773Z,1607730925.773 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2020-12-11T23:55:25.921Z,1607730925.921 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2020-12-11T23:55:25.921Z,1607730925.921 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2020-12-11T23:55:26.004Z,1607730926.004 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2020-12-11T23:55:26.223Z,1607730926.223 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2020-12-11T23:55:26.223Z,1607730926.223 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2020-12-11T23:55:26.324Z,1607730926.324 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2020-12-11T23:55:26.325Z,1607730926.325 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2020-12-11T23:55:26.423Z,1607730926.423 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2020-12-11T23:55:26.423Z,1607730926.423 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2020-12-11T23:55:26.832Z,1607730926.832 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2020-12-11T23:55:26.833Z,1607730926.833 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2020-12-11T23:55:26.942Z,1607730926.942 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2020-12-11T23:55:26.943Z,1607730926.943 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2020-12-11T23:55:27.471Z,1607730927.471 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2020-12-11T23:55:27.471Z,1607730927.471 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2020-12-11T23:55:27.676Z,1607730927.676 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2020-12-11T23:55:27.677Z,1607730927.677 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2020-12-11T23:55:27.996Z,1607730927.996 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2020-12-11T23:55:27.996Z,1607730927.996 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2020-12-11T23:55:28.223Z,1607730928.223 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2020-12-11T23:55:28.224Z,1607730928.224 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2020-12-11T23:55:28.371Z,1607730928.371 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2020-12-11T23:55:28.372Z,1607730928.372 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2020-12-11T23:55:29.074Z,1607730929.074 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2020-12-11T23:55:29.075Z,1607730929.075 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2020-12-11T23:55:29.568Z,1607730929.568 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2020-12-11T23:55:29.568Z,1607730929.568 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2020-12-11T23:55:30.252Z,1607730930.252 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2020-12-11T23:55:30.255Z,1607730930.255 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-triton/ 2020-12-11T23:55:30.256Z,1607730930.256 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/vehicle.cfg 2020-12-11T23:55:30.616Z,1607730930.616 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/secure.cfg 2020-12-11T23:55:30.821Z,1607730930.821 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Science.cfg 2020-12-11T23:55:31.293Z,1607730931.293 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Simulator.cfg 2020-12-11T23:55:31.398Z,1607730931.398 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Battery.cfg 2020-12-11T23:55:32.085Z,1607730932.085 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2020-12-11T23:55:32.086Z,1607730932.086 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/logger.cfg 2020-12-11T23:55:32.300Z,1607730932.300 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Servo.cfg 2020-12-11T23:55:32.766Z,1607730932.766 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Navigation.cfg 2020-12-11T23:55:32.862Z,1607730932.862 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Sensor.cfg 2020-12-11T23:55:33.016Z,1607730933.016 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Control.cfg 2020-12-11T23:55:33.118Z,1607730933.118 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/BIT.cfg 2020-12-11T23:55:33.221Z,1607730933.221 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2020-12-11T23:55:33.234Z,1607730933.234 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2020-12-11T23:55:33.254Z,1607730933.254 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2020-12-11T23:55:33.254Z,1607730933.254 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2020-12-11T23:55:33.330Z,1607730933.330 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2020-12-11T23:55:33.330Z,1607730933.330 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2020-12-11T23:55:33.378Z,1607730933.378 [VerticalControl](DEBUG): Construct VerticalControl. 2020-12-11T23:55:33.436Z,1607730933.436 [VerticalControl] Loaded 2020-12-11T23:55:33.436Z,1607730933.436 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2020-12-11T23:55:33.437Z,1607730933.437 [HorizontalControl](DEBUG): Construct HorizontalControl. 2020-12-11T23:55:33.474Z,1607730933.474 [HorizontalControl] Loaded 2020-12-11T23:55:33.475Z,1607730933.475 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2020-12-11T23:55:33.475Z,1607730933.475 [SpeedControl](DEBUG): Construct SpeedControl. 2020-12-11T23:55:33.478Z,1607730933.478 [SpeedControl] Loaded 2020-12-11T23:55:33.479Z,1607730933.479 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2020-12-11T23:55:33.479Z,1607730933.479 [LoopControl](DEBUG): Construct LoopControl. 2020-12-11T23:55:33.480Z,1607730933.480 [LoopControl] Loaded 2020-12-11T23:55:33.480Z,1607730933.480 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2020-12-11T23:55:33.481Z,1607730933.481 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2020-12-11T23:55:33.481Z,1607730933.481 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2020-12-11T23:55:33.612Z,1607730933.612 [BuoyancyServo] Loaded 2020-12-11T23:55:33.612Z,1607730933.612 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2020-12-11T23:55:33.629Z,1607730933.629 [ElevatorServo] Loaded 2020-12-11T23:55:33.629Z,1607730933.629 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2020-12-11T23:55:33.644Z,1607730933.644 [MassServo] Loaded 2020-12-11T23:55:33.645Z,1607730933.645 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2020-12-11T23:55:33.660Z,1607730933.660 [RudderServo] Loaded 2020-12-11T23:55:33.660Z,1607730933.660 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2020-12-11T23:55:33.675Z,1607730933.675 [ThrusterServo] Loaded 2020-12-11T23:55:33.675Z,1607730933.675 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2020-12-11T23:55:33.676Z,1607730933.676 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2020-12-11T23:55:33.676Z,1607730933.676 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2020-12-11T23:55:33.713Z,1607730933.713 [DepthRateCalculator] Loaded 2020-12-11T23:55:33.713Z,1607730933.713 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2020-12-11T23:55:33.716Z,1607730933.716 [PitchRateCalculator] Loaded 2020-12-11T23:55:33.716Z,1607730933.716 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2020-12-11T23:55:33.724Z,1607730933.724 [SpeedCalculator] Loaded 2020-12-11T23:55:33.724Z,1607730933.724 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2020-12-11T23:55:33.735Z,1607730933.735 [TempGradientCalculator] Loaded 2020-12-11T23:55:33.736Z,1607730933.736 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2020-12-11T23:55:33.738Z,1607730933.738 [YawRateCalculator] Loaded 2020-12-11T23:55:33.739Z,1607730933.739 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2020-12-11T23:55:33.754Z,1607730933.754 [ElevatorOffsetCalculator] Loaded 2020-12-11T23:55:33.754Z,1607730933.754 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2020-12-11T23:55:33.754Z,1607730933.754 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2020-12-11T23:55:33.755Z,1607730933.755 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2020-12-11T23:55:33.832Z,1607730933.832 [DeadReckonUsingMultipleVelocitySources] Loaded 2020-12-11T23:55:33.832Z,1607730933.832 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2020-12-11T23:55:33.843Z,1607730933.843 [NavChart] Loaded 2020-12-11T23:55:33.844Z,1607730933.844 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2020-12-11T23:55:33.847Z,1607730933.847 [UniversalFixResidualReporter] Loaded 2020-12-11T23:55:33.848Z,1607730933.848 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2020-12-11T23:55:33.848Z,1607730933.848 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2020-12-11T23:55:33.849Z,1607730933.849 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2020-12-11T23:55:34.139Z,1607730934.139 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2020-12-11T23:55:34.142Z,1607730934.142 [AHRS_M2](INFO): created writer for : platform_orientation 2020-12-11T23:55:34.143Z,1607730934.143 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2020-12-11T23:55:34.146Z,1607730934.146 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2020-12-11T23:55:34.147Z,1607730934.147 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2020-12-11T23:55:34.150Z,1607730934.150 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2020-12-11T23:55:34.150Z,1607730934.150 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2020-12-11T23:55:34.153Z,1607730934.153 [AHRS_M2](INFO): created writer for : platform_roll_angle 2020-12-11T23:55:34.191Z,1607730934.191 [AHRS_M2] Loaded 2020-12-11T23:55:34.191Z,1607730934.191 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2020-12-11T23:55:34.262Z,1607730934.262 [DataOverHttps] Loaded 2020-12-11T23:55:34.262Z,1607730934.262 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2020-12-11T23:55:34.264Z,1607730934.264 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408514E0 2020-12-11T23:55:34.264Z,1607730934.264 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 6027 2020-12-11T23:55:34.281Z,1607730934.281 [Depth_Keller] Loaded 2020-12-11T23:55:34.281Z,1607730934.281 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2020-12-11T23:55:34.336Z,1607730934.336 [NAL9602] Loaded 2020-12-11T23:55:34.336Z,1607730934.336 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2020-12-11T23:55:34.362Z,1607730934.362 [Onboard] Loaded 2020-12-11T23:55:34.363Z,1607730934.363 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2020-12-11T23:55:34.364Z,1607730934.364 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408814E0 2020-12-11T23:55:34.364Z,1607730934.364 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 6028 2020-12-11T23:55:34.375Z,1607730934.375 [Radio_Surface] Loaded 2020-12-11T23:55:34.375Z,1607730934.375 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2020-12-11T23:55:34.376Z,1607730934.376 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408B14E0 2020-12-11T23:55:34.376Z,1607730934.376 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6029 2020-12-11T23:55:34.453Z,1607730934.453 [DAT] Loaded 2020-12-11T23:55:34.453Z,1607730934.453 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2020-12-11T23:55:35.239Z,1607730935.239 [BPC1] Loaded 2020-12-11T23:55:35.239Z,1607730935.239 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2020-12-11T23:55:35.239Z,1607730935.239 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2020-12-11T23:55:35.240Z,1607730935.240 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2020-12-11T23:55:35.320Z,1607730935.320 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2020-12-11T23:55:35.321Z,1607730935.321 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2020-12-11T23:55:35.775Z,1607730935.775 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2020-12-11T23:55:35.776Z,1607730935.776 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2020-12-11T23:55:35.801Z,1607730935.801 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2020-12-11T23:55:35.802Z,1607730935.802 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2020-12-11T23:55:36.137Z,1607730936.137 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2020-12-11T23:55:36.140Z,1607730936.140 [CTD_Seabird](INFO): created writer for : sea_water_density 2020-12-11T23:55:36.141Z,1607730936.141 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2020-12-11T23:55:36.143Z,1607730936.143 [CTD_Seabird](INFO): created writer for : depth 2020-12-11T23:55:36.144Z,1607730936.144 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2020-12-11T23:55:36.146Z,1607730936.146 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2020-12-11T23:55:36.147Z,1607730936.147 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2020-12-11T23:55:36.150Z,1607730936.150 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2020-12-11T23:55:36.150Z,1607730936.150 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2020-12-11T23:55:36.153Z,1607730936.153 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2020-12-11T23:55:36.154Z,1607730936.154 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2020-12-11T23:55:36.157Z,1607730936.157 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2020-12-11T23:55:36.157Z,1607730936.157 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2020-12-11T23:55:36.160Z,1607730936.160 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2020-12-11T23:55:36.174Z,1607730936.174 [CTD_Seabird] Loaded 2020-12-11T23:55:36.174Z,1607730936.174 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2020-12-11T23:55:36.175Z,1607730936.175 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A594E0 2020-12-11T23:55:36.176Z,1607730936.176 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 6030 2020-12-11T23:55:36.205Z,1607730936.205 [ESPComponent] Loaded 2020-12-11T23:55:36.205Z,1607730936.205 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2020-12-11T23:55:36.222Z,1607730936.222 [PAR_Licor] Loaded 2020-12-11T23:55:36.222Z,1607730936.222 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2020-12-11T23:55:36.235Z,1607730936.235 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470 2020-12-11T23:55:36.235Z,1607730936.235 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470 2020-12-11T23:55:36.237Z,1607730936.237 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650 2020-12-11T23:55:36.237Z,1607730936.237 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650 2020-12-11T23:55:36.239Z,1607730936.239 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl 2020-12-11T23:55:36.239Z,1607730936.239 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl 2020-12-11T23:55:36.241Z,1607730936.241 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm 2020-12-11T23:55:36.241Z,1607730936.241 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm 2020-12-11T23:55:36.243Z,1607730936.243 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm 2020-12-11T23:55:36.243Z,1607730936.243 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm 2020-12-11T23:55:36.246Z,1607730936.246 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm 2020-12-11T23:55:36.246Z,1607730936.246 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm 2020-12-11T23:55:36.248Z,1607730936.248 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm 2020-12-11T23:55:36.248Z,1607730936.248 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm 2020-12-11T23:55:36.250Z,1607730936.250 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.252Z,1607730936.252 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.253Z,1607730936.253 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.253Z,1607730936.253 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.255Z,1607730936.255 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.255Z,1607730936.255 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.257Z,1607730936.257 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.257Z,1607730936.257 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-12-11T23:55:36.259Z,1607730936.259 [WetLabsBB2FL] Loaded 2020-12-11T23:55:36.259Z,1607730936.259 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2020-12-11T23:55:36.261Z,1607730936.261 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A894E0 2020-12-11T23:55:36.261Z,1607730936.261 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 6031 2020-12-11T23:55:36.262Z,1607730936.262 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2020-12-11T23:55:36.262Z,1607730936.262 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2020-12-11T23:55:36.543Z,1607730936.543 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2020-12-11T23:55:36.543Z,1607730936.543 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2020-12-11T23:55:36.673Z,1607730936.673 [SBIT](DEBUG): Construct Startup Built In Test. 2020-12-11T23:55:36.681Z,1607730936.681 [SBIT] Loaded 2020-12-11T23:55:36.682Z,1607730936.682 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2020-12-11T23:55:36.682Z,1607730936.682 [IBIT](DEBUG): Construct Initiated Built In Test. 2020-12-11T23:55:36.695Z,1607730936.695 [IBIT] Loaded 2020-12-11T23:55:36.695Z,1607730936.695 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2020-12-11T23:55:36.698Z,1607730936.698 [CBIT](DEBUG): Construct Continuous Built In Test. 2020-12-11T23:55:36.797Z,1607730936.797 [CBIT] Loaded 2020-12-11T23:55:36.797Z,1607730936.797 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2020-12-11T23:55:36.797Z,1607730936.797 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2020-12-11T23:55:36.801Z,1607730936.801 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2020-12-11T23:55:36.802Z,1607730936.802 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2020-12-11T23:55:36.811Z,1607730936.811 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2020-12-11T23:55:36.812Z,1607730936.812 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B674E0 2020-12-11T23:55:36.812Z,1607730936.812 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6032 2020-12-11T23:55:36.817Z,1607730936.817 [Supervisor](INFO): Main Thread ID is 5773 2020-12-11T23:55:36.817Z,1607730936.817 [Supervisor](DEBUG): Running supervisor. 2020-12-11T23:55:36.818Z,1607730936.818 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6033 2020-12-11T23:55:36.820Z,1607730936.820 [controlThread ThreadHandler](INFO): Handler Thread ID is 6034 2020-12-11T23:55:36.820Z,1607730936.820 [controlThread](DEBUG): Initializing ControlThread 2020-12-11T23:55:36.821Z,1607730936.821 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2020-12-11T23:55:36.823Z,1607730936.823 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2020-12-11T23:55:36.823Z,1607730936.823 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2020-12-11T23:55:36.824Z,1607730936.824 [LoopControl](DEBUG): Initialize LoopControlComponent. 2020-12-11T23:55:36.825Z,1607730936.825 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2020-12-11T23:55:36.826Z,1607730936.826 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2020-12-11T23:55:36.826Z,1607730936.826 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2020-12-11T23:55:36.826Z,1607730936.826 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2020-12-11T23:55:36.827Z,1607730936.827 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2020-12-11T23:55:36.827Z,1607730936.827 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2020-12-11T23:55:36.828Z,1607730936.828 [NavChart](DEBUG): Initialize NavChart Navigation. 2020-12-11T23:55:36.829Z,1607730936.829 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2020-12-11T23:55:36.837Z,1607730936.837 [SBIT](INFO): Initialize SBIT Component. 2020-12-11T23:55:36.837Z,1607730936.837 [SBIT](IMPORTANT): git: 2020-11-24-6-gcb638d650 2020-12-11T23:55:36.838Z,1607730936.838 [SBIT](INFO): git hash: cb638d650ac65501896d406bf5988c2fe747cbc6 2020-12-11T23:55:36.838Z,1607730936.838 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2020-12-11T23:55:36.839Z,1607730936.839 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018 Kernel Reported: #1 PREEMPT Tue May 26 08:17:09 PDT 2020 2020-12-11T23:55:36.840Z,1607730936.840 [SBIT](INFO): Beginning SBIT in 34.000000 seconds. 2020-12-11T23:55:36.841Z,1607730936.841 [IBIT](INFO): Initialize IBIT Component. 2020-12-11T23:55:36.842Z,1607730936.842 [CBIT](DEBUG): Initialize CBIT Component. 2020-12-11T23:55:36.842Z,1607730936.842 [logger ThreadHandler](INFO): Handler Thread ID is 6035 2020-12-11T23:55:36.853Z,1607730936.853 [CBIT](DEBUG): Initialized mux pins. 2020-12-11T23:55:36.853Z,1607730936.853 [CBIT](DEBUG): Initializing the watchdog timer. 2020-12-11T23:55:36.861Z,1607730936.861 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 6036 2020-12-11T23:55:36.862Z,1607730936.862 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2020-12-11T23:55:36.873Z,1607730936.873 [Onboard ThreadHandler](INFO): Handler Thread ID is 6037 2020-12-11T23:55:36.877Z,1607730936.877 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2020-12-11T23:55:36.877Z,1607730936.877 [CBIT](DEBUG): Initializing heartbeat. 2020-12-11T23:55:36.891Z,1607730936.891 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6038 2020-12-11T23:55:36.909Z,1607730936.909 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 6039 2020-12-11T23:55:36.910Z,1607730936.910 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2020-12-11T23:55:36.914Z,1607730936.914 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 6041 2020-12-11T23:55:36.915Z,1607730936.915 [WetLabsBB2FL](INFO): Powering down 2020-12-11T23:55:36.937Z,1607730936.937 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6042 2020-12-11T23:55:36.940Z,1607730936.940 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2020-12-11T23:55:36.940Z,1607730936.940 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2020-12-11T23:55:36.941Z,1607730936.941 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2020-12-11T23:55:36.941Z,1607730936.941 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2020-12-11T23:55:36.941Z,1607730936.941 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2020-12-11T23:55:36.941Z,1607730936.941 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2020-12-11T23:55:36.941Z,1607730936.941 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2020-12-11T23:55:36.941Z,1607730936.941 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2020-12-11T23:55:36.941Z,1607730936.941 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2020-12-11T23:55:36.942Z,1607730936.942 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2020-12-11T23:55:36.942Z,1607730936.942 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2020-12-11T23:55:36.942Z,1607730936.942 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2020-12-11T23:55:36.942Z,1607730936.942 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2020-12-11T23:55:36.942Z,1607730936.942 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2020-12-11T23:55:36.942Z,1607730936.942 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2020-12-11T23:55:36.943Z,1607730936.943 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2020-12-11T23:55:36.949Z,1607730936.949 [CBIT](DEBUG): Deactivating GF circuits. 2020-12-11T23:55:36.949Z,1607730936.949 [CBIT](DEBUG): Deactivating emergency mode. 2020-12-11T23:55:36.985Z,1607730936.985 [CBIT](DEBUG): Backplane powered. 2020-12-11T23:55:36.986Z,1607730936.986 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2020-12-11T23:55:36.996Z,1607730936.996 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2020-12-11T23:55:37.006Z,1607730937.006 [MissionManager](DEBUG): 2020-12-11T23:55:37.007Z,1607730937.007 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2020-12-11T23:55:37.074Z,1607730937.074 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2020-12-11T23:55:37.076Z,1607730937.076 [Default:A.Wait](DEBUG): Construct Wait. 2020-12-11T23:55:37.093Z,1607730937.093 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2020-12-11T23:55:37.120Z,1607730937.120 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2020-12-11T23:55:37.122Z,1607730937.122 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2020-12-11T23:55:37.138Z,1607730937.138 [Default:E.Execute](DEBUG): Construct Execute. 2020-12-11T23:55:37.169Z,1607730937.169 [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-12-11T23:55:37.173Z,1607730937.173 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,NAL9602,DAT,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2020-12-11T23:55:37.181Z,1607730937.181 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2020-12-11T23:55:37.218Z,1607730937.218 [Depth_Keller](ERROR): Pressure reading out of range: 1925.893799 decibar 2020-12-11T23:55:37.221Z,1607730937.221 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2020-12-11T23:55:37.221Z,1607730937.221 [DAT](INFO): Powering up 2020-12-11T23:55:37.221Z,1607730937.221 [DAT](DEBUG): Initializing DAT. 2020-12-11T23:55:37.297Z,1607730937.297 [Radio_Surface](INFO): Powering up 2020-12-11T23:55:37.317Z,1607730937.317 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2020-12-11T23:55:37.367Z,1607730937.367 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-12-11T23:55:37.407Z,1607730937.407 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:55:37.413Z,1607730937.413 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2020-12-11T23:55:37.414Z,1607730937.414 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:55:37.425Z,1607730937.425 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-12-11T23:55:37.426Z,1607730937.426 [MassServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:55:37.433Z,1607730937.433 [MassServo](DEBUG): Initializing MassServo. 2020-12-11T23:55:37.434Z,1607730937.434 [RudderServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:55:37.441Z,1607730937.441 [RudderServo](DEBUG): Initializing RudderServo. 2020-12-11T23:55:37.442Z,1607730937.442 [ThrusterServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:55:37.449Z,1607730937.449 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2020-12-11T23:55:38.321Z,1607730938.321 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2020-12-11T23:55:38.337Z,1607730938.337 [RudderServo](FAULT): Rudder failed to initialize 2020-12-11T23:55:38.337Z,1607730938.337 [RudderServo] Communications Fault, FailCount= 1 2020-12-11T23:55:38.337Z,1607730938.337 [RudderServo](ERROR): Communications Fault 2020-12-11T23:55:38.437Z,1607730938.437 [CBIT](ERROR): Communications Fault in component: RudderServo 2020-12-11T23:55:38.638Z,1607730938.638 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2020-12-11T23:55:38.638Z,1607730938.638 [RudderServo](INFO): Powering down 2020-12-11T23:55:39.305Z,1607730939.305 [RudderServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:55:39.426Z,1607730939.426 [RudderServo](DEBUG): Initializing RudderServo. 2020-12-11T23:55:39.430Z,1607730939.430 [CBIT](INFO): Clearing failed state for component RudderServo 2020-12-11T23:55:39.430Z,1607730939.430 [RudderServo] No Fault, FailCount= 1 2020-12-11T23:55:47.750Z,1607730947.750 [DAT](INFO): DAT read: 2020-12-11T23:55:47.752Z,1607730947.752 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2020-12-11T23:55:48.962Z,1607730948.962 [DAT](INFO): DAT read: MF Frequency Band 2020-12-11T23:55:48.963Z,1607730948.963 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.12.21 2020-12-11T23:55:48.964Z,1607730948.964 [DAT](INFO): DAT read: Dec 11 2020 23:54:09 2020-12-11T23:55:49.770Z,1607730949.770 [DAT](INFO): DAT read: Features enabled [Bearing] 2020-12-11T23:55:49.772Z,1607730949.772 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-12-11T23:55:49.772Z,1607730949.772 [DAT](INFO): commRate: 800 2020-12-11T23:55:51.790Z,1607730951.790 [DAT](INFO): entering command mode 2020-12-11T23:55:52.190Z,1607730952.190 [DAT](INFO): DAT read: 2020-12-11T23:55:52.190Z,1607730952.190 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:52.598Z,1607730952.598 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:53.002Z,1607730953.002 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:53.402Z,1607730953.402 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:53.806Z,1607730953.806 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:54.210Z,1607730954.210 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:54.614Z,1607730954.614 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:55.022Z,1607730955.022 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:55.427Z,1607730955.427 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:55.826Z,1607730955.826 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:56.230Z,1607730956.230 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:56.634Z,1607730956.634 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:57.042Z,1607730957.042 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:57.446Z,1607730957.446 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:57.850Z,1607730957.850 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:58.250Z,1607730958.250 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:58.658Z,1607730958.658 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:59.058Z,1607730959.058 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:59.462Z,1607730959.462 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:55:59.866Z,1607730959.866 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:00.270Z,1607730960.270 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:00.679Z,1607730960.679 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:01.078Z,1607730961.078 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:01.482Z,1607730961.482 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:01.886Z,1607730961.886 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:02.294Z,1607730962.294 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:02.694Z,1607730962.694 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:03.098Z,1607730963.098 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:03.502Z,1607730963.502 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:03.910Z,1607730963.910 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:04.310Z,1607730964.310 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:04.714Z,1607730964.714 [NAL9602](INFO): Powering up NAL9602 2020-12-11T23:56:04.715Z,1607730964.715 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:05.118Z,1607730965.118 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:05.522Z,1607730965.522 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:05.932Z,1607730965.932 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:06.330Z,1607730966.330 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:06.734Z,1607730966.734 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:07.142Z,1607730967.142 [DAT](DEBUG): checking for command mode acknowledgment 2020-12-11T23:56:07.142Z,1607730967.142 [DAT](FAULT): failed to enter command mode 2020-12-11T23:56:07.550Z,1607730967.550 [DAT](INFO): entering command mode 2020-12-11T23:56:07.946Z,1607730967.946 [DAT](INFO): DAT read: user:1> 2020-12-11T23:56:07.947Z,1607730967.947 [DAT](INFO): DAT read: Command '+++' not found 2020-12-11T23:56:07.947Z,1607730967.947 [DAT](INFO): DAT read: Error 2020-12-11T23:56:07.948Z,1607730967.948 [DAT](INFO): setting verbose to 3 2020-12-11T23:56:08.350Z,1607730968.350 [DAT](INFO): DAT read: user:2> 2020-12-11T23:56:08.351Z,1607730968.351 [DAT](INFO): DAT read: Verbose | 3 2020-12-11T23:56:08.352Z,1607730968.352 [DAT](INFO): set verbose to 3 2020-12-11T23:56:08.352Z,1607730968.352 [DAT](INFO): setting DatVerbose to 27440 2020-12-11T23:56:08.754Z,1607730968.754 [DAT](INFO): DAT read: user:3> 2020-12-11T23:56:08.755Z,1607730968.755 [DAT](INFO): DAT read: DatVerbose | 27440 2020-12-11T23:56:08.756Z,1607730968.756 [DAT](INFO): set DatVerbose to 27440 2020-12-11T23:56:08.756Z,1607730968.756 [DAT](INFO): setting transmit power to 8 2020-12-11T23:56:09.163Z,1607730969.163 [DAT](INFO): DAT read: user:4> 2020-12-11T23:56:09.163Z,1607730969.163 [DAT](INFO): DAT read: TxPower | 8 (Max) 2020-12-11T23:56:09.164Z,1607730969.164 [DAT](INFO): set transmit power to 8 2020-12-11T23:56:09.164Z,1607730969.164 [DAT](INFO): setting local address to 5 2020-12-11T23:56:09.566Z,1607730969.566 [DAT](INFO): DAT read: user:5> 2020-12-11T23:56:09.567Z,1607730969.567 [DAT](INFO): DAT read: LocalAddr | 5 2020-12-11T23:56:09.567Z,1607730969.567 [DAT](INFO): set local address to 5 2020-12-11T23:56:11.631Z,1607730971.631 [SBIT](IMPORTANT): Beginning Startup BIT 2020-12-11T23:56:11.635Z,1607730971.635 [CBIT](IMPORTANT): Beginning ground fault scan 2020-12-11T23:56:15.628Z,1607730975.628 [NAL9602](INFO): NAL9602 initialized 2020-12-11T23:56:16.099Z,1607730976.099 [ElevatorServo](FAULT): Overload Error 2020-12-11T23:56:16.099Z,1607730976.099 [ElevatorServo] Hardware Fault, FailCount= 1 2020-12-11T23:56:16.099Z,1607730976.099 [ElevatorServo](ERROR): Hardware Fault 2020-12-11T23:56:16.229Z,1607730976.229 [CBIT](ERROR): Hardware Fault in component: ElevatorServo 2020-12-11T23:56:16.474Z,1607730976.474 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2020-12-11T23:56:16.474Z,1607730976.474 [ElevatorServo](INFO): Powering down 2020-12-11T23:56:17.282Z,1607730977.282 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:56:17.398Z,1607730977.398 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-12-11T23:56:17.429Z,1607730977.429 [CBIT](INFO): Clearing failed state for component ElevatorServo 2020-12-11T23:56:17.429Z,1607730977.429 [ElevatorServo] No Fault, FailCount= 1 2020-12-11T23:56:22.537Z,1607730982.537 [ElevatorServo](FAULT): Overload Error 2020-12-11T23:56:22.537Z,1607730982.537 [ElevatorServo] Hardware Fault, FailCount= 2 2020-12-11T23:56:22.537Z,1607730982.537 [ElevatorServo](ERROR): Hardware Fault 2020-12-11T23:56:22.578Z,1607730982.578 [CBIT](ERROR): Hardware Fault in component: ElevatorServo 2020-12-11T23:56:22.581Z,1607730982.581 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.007104 CHAN A1 (24V): -0.007393 CHAN A2 (12V): -0.005007 CHAN A3 (5V): -0.003193 CHAN B0 (3.3V): -0.001296 CHAN B1 (3.15aV): -0.001817 CHAN B2 (3.15bV): -0.000690 CHAN B3 (GND): 0.000082 OPEN: 0.004712 Full Scale Calc: 4.765 mA, -1.589 mA 2020-12-11T23:56:22.921Z,1607730982.921 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2020-12-11T23:56:22.922Z,1607730982.922 [ElevatorServo](INFO): Powering down 2020-12-11T23:56:23.718Z,1607730983.718 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:56:23.833Z,1607730983.833 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-12-11T23:56:23.838Z,1607730983.838 [CBIT](INFO): Clearing failed state for component ElevatorServo 2020-12-11T23:56:23.839Z,1607730983.839 [ElevatorServo] No Fault, FailCount= 2 2020-12-11T23:56:24.978Z,1607730984.978 [SBIT](ERROR): Could not read elevatorAngleReader_. 2020-12-11T23:56:28.555Z,1607730988.555 [NAL9602](INFO): SBD MO Status=0, MOMSN=4060, MT Status=0, MTMSN=0 2020-12-11T23:56:28.555Z,1607730988.555 [NAL9602](INFO): No messages in MT queue 2020-12-11T23:56:33.849Z,1607730993.849 [ElevatorServo](FAULT): Overload Error 2020-12-11T23:56:33.849Z,1607730993.849 [ElevatorServo] Hardware Fault, FailCount= 3 2020-12-11T23:56:33.849Z,1607730993.849 [ElevatorServo](ERROR): Hardware Fault 2020-12-11T23:56:33.930Z,1607730993.930 [CBIT](ERROR): Hardware Fault in component: ElevatorServo 2020-12-11T23:56:33.930Z,1607730993.930 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo 2020-12-11T23:56:34.235Z,1607730994.235 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2020-12-11T23:56:34.235Z,1607730994.235 [ElevatorServo](INFO): Powering down 2020-12-11T23:56:34.263Z,1607730994.263 [CommandLine](FAULT): Scheduling is paused 2020-12-11T23:56:34.264Z,1607730994.264 [CBIT](INFO): Critical error at 20201211T235633 2020-12-11T23:56:34.264Z,1607730994.264 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2020-12-11T23:56:35.035Z,1607730995.035 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-12-11T23:56:35.150Z,1607730995.150 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-12-11T23:56:42.294Z,1607731002.294 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235548.00,A,3648.17556,N,12147.28512,W,0.039,0.00,111220,,,A*7E 2020-12-11T23:56:42.305Z,1607731002.305 [NAL9602](INFO): GPS fix at 20201211T235548: (36.802926, -121.788085) 2020-12-11T23:56:51.621Z,1607731011.621 [SBIT](ERROR): Could not read elevatorAngleReader_. 2020-12-11T23:56:51.621Z,1607731011.621 [SBIT](FAULT): Control surface position failure. 2020-12-11T23:57:05.353Z,1607731025.353 [SBIT](ERROR): Could not read elevatorAngleReader_. 2020-12-11T23:57:05.353Z,1607731025.353 [SBIT](FAULT): Control surface position failure. 2020-12-11T23:57:05.744Z,1607731025.744 [SBIT](CRITICAL): SBIT FAILED 2020-12-11T23:57:05.745Z,1607731025.745 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2020-12-11T23:57:05.745Z,1607731025.745 [SBIT](IMPORTANT): AHRS_M2.loadAtStartup=1 bool; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): DAT.verbosity=3 count; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): DVL_micro.loadAtStartup=0 bool; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): Express none CTD_Seabird.bin_median_sea_water_salinity; 2020-12-11T23:57:05.746Z,1607731025.746 [SBIT](IMPORTANT): Express linearApproximation WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water 0.100000 microgram_per_liter; 2020-12-11T23:57:05.747Z,1607731025.747 [SBIT](IMPORTANT): Express linearApproximation depth 5.000000 meter; 2020-12-11T23:57:05.747Z,1607731025.747 [SBIT](IMPORTANT): Express linearApproximation latitude 0.005000 degree; 2020-12-11T23:57:05.747Z,1607731025.747 [SBIT](IMPORTANT): Express linearApproximation longitude 0.005000 degree; 2020-12-11T23:57:05.747Z,1607731025.747 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=168 cubic_centimeter; 2020-12-11T23:57:05.747Z,1607731025.747 [SBIT](IMPORTANT): VerticalControl.elevLimit=35 degree; 2020-12-11T23:57:05.747Z,1607731025.747 [SBIT](IMPORTANT): VerticalControl.massDefault=3.7 millimeter; 2020-12-11T23:57:05.765Z,1607731025.765 [CBIT](INFO): Critical error at 20201211T235705 2020-12-11T23:57:06.152Z,1607731026.152 [MissionManager](IMPORTANT): Started mission Startup 2020-12-11T23:57:06.153Z,1607731026.153 [Startup] Running Loop=1 2020-12-11T23:57:06.153Z,1607731026.153 [Startup](DEBUG): Aggregate::initialize Startup 2020-12-11T23:57:06.153Z,1607731026.153 [Startup:A.GoToSurface] Running Loop=1 2020-12-11T23:57:06.153Z,1607731026.153 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-12-11T23:57:06.153Z,1607731026.153 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-12-11T23:57:06.154Z,1607731026.154 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-12-11T23:57:06.154Z,1607731026.154 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-12-11T23:57:06.155Z,1607731026.155 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-12-11T23:57:06.155Z,1607731026.155 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-12-11T23:57:06.156Z,1607731026.156 [Startup:StartupSatComms] Running Loop=1 2020-12-11T23:57:06.156Z,1607731026.156 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2020-12-11T23:57:06.157Z,1607731026.157 [Startup:StartupSatComms:A] Running Loop=1 2020-12-11T23:57:06.552Z,1607731026.552 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2020-12-11T23:57:08.151Z,1607731028.151 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235614.00,A,3648.17566,N,12147.28575,W,0.058,0.00,111220,,,A*71 2020-12-11T23:57:08.153Z,1607731028.153 [NAL9602](INFO): GPS fix at 20201211T235614: (36.802928, -121.788096) 2020-12-11T23:57:08.165Z,1607731028.165 [Startup:StartupSatComms:A] Stopped 2020-12-11T23:57:08.165Z,1607731028.165 [Startup:StartupSatComms:B] Running Loop=1 2020-12-11T23:57:08.605Z,1607731028.605 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-12-11T23:57:21.951Z,1607731041.951 [NAL9602](INFO): SBD MO Status=1, MOMSN=4061, MT Status=0, MTMSN=0 2020-12-11T23:57:22.017Z,1607731042.017 [NAL9602](INFO): Sent 39 bytes from file Logs/20201211T223617/Courier0043.lzma 2020-12-11T23:57:22.017Z,1607731042.017 [NAL9602](INFO): Packets left to send: 0 2020-12-11T23:57:34.351Z,1607731054.351 [NAL9602](INFO): SBD MO Status=1, MOMSN=4062, MT Status=0, MTMSN=0 2020-12-11T23:57:34.413Z,1607731054.413 [NAL9602](INFO): Sent 332 bytes from file Logs/20201211T235525/Courier0000.lzma 2020-12-11T23:57:34.413Z,1607731054.413 [NAL9602](INFO): Packets left to send: 1 2020-12-11T23:57:48.468Z,1607731068.468 [NAL9602](INFO): SBD MO Status=1, MOMSN=4063, MT Status=0, MTMSN=0 2020-12-11T23:57:48.517Z,1607731068.517 [NAL9602](INFO): Sent 17 bytes from file Logs/20201211T235525/Courier0000.lzma 2020-12-11T23:57:48.517Z,1607731068.517 [NAL9602](INFO): Packets left to send: 0 2020-12-11T23:58:01.285Z,1607731081.285 [NAL9602](INFO): SBD MO Status=1, MOMSN=4064, MT Status=0, MTMSN=0 2020-12-11T23:58:01.341Z,1607731081.341 [NAL9602](INFO): Sent 128 bytes from file Logs/20201211T223617/Express0041.lzma 2020-12-11T23:58:01.341Z,1607731081.341 [NAL9602](INFO): Packets left to send: 0 2020-12-11T23:58:08.481Z,1607731088.481 [Startup:StartupSatComms:B](INFO): Timed out from 2020-12-11T23:57:08.2Z 2020-12-11T23:58:08.482Z,1607731088.482 [Startup:StartupSatComms:B] Stopped 2020-12-11T23:58:08.482Z,1607731088.482 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2020-12-11T23:58:08.482Z,1607731088.482 [Startup:StartupSatComms] Stopped 2020-12-11T23:58:08.482Z,1607731088.482 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2020-12-11T23:58:08.483Z,1607731088.483 [Startup](INFO): Completed Startup 2020-12-11T23:58:08.483Z,1607731088.483 [MissionManager](INFO): Startup is completed. 2020-12-11T23:58:08.483Z,1607731088.483 [MissionManager](INFO): Uninitializing Mission Startup 2020-12-11T23:58:08.483Z,1607731088.483 [Startup] Stopped 2020-12-11T23:58:08.483Z,1607731088.483 [Startup](DEBUG): Aggregate::uninitialize Startup 2020-12-11T23:58:08.483Z,1607731088.483 [Startup:A.GoToSurface] Stopped 2020-12-11T23:58:08.483Z,1607731088.483 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-12-11T23:58:08.815Z,1607731088.815 [MissionManager](IMPORTANT): Started mission Default 2020-12-11T23:58:08.815Z,1607731088.815 [Default] Running Loop=1 2020-12-11T23:58:08.815Z,1607731088.815 [Default](DEBUG): Aggregate::initialize Default 2020-12-11T23:58:08.816Z,1607731088.816 [Default:B.GoToSurface] Running Loop=1 2020-12-11T23:58:08.816Z,1607731088.816 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-12-11T23:58:08.816Z,1607731088.816 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-12-11T23:58:08.816Z,1607731088.816 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-12-11T23:58:08.817Z,1607731088.817 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-12-11T23:58:08.817Z,1607731088.817 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-12-11T23:58:08.817Z,1607731088.817 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-12-11T23:58:08.818Z,1607731088.818 [Default:A.Wait] Running Loop=1 2020-12-11T23:58:08.818Z,1607731088.818 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-12-11T23:58:22.168Z,1607731102.168 [Default:A.Wait](INFO): Done Waiting. 2020-12-11T23:58:22.168Z,1607731102.168 [Default:A.Wait] Stopped 2020-12-11T23:58:22.168Z,1607731102.168 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-12-11T23:58:22.580Z,1607731102.580 [Default:CheckIn] Running Loop=1 2020-12-11T23:58:22.581Z,1607731102.581 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-11T23:58:22.581Z,1607731102.581 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-11T23:58:22.972Z,1607731102.972 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2020-12-11T23:58:23.343Z,1607731103.343 [NAL9602](INFO): SBD MO Status=2, MOMSN=4065, MT Status=2, MTMSN=0 2020-12-11T23:58:23.343Z,1607731103.343 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-12-11T23:58:24.555Z,1607731104.555 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235730.00,A,3648.17617,N,12147.28540,W,0.000,0.00,111220,,,D*7D 2020-12-11T23:58:24.557Z,1607731104.557 [NAL9602](INFO): GPS fix at 20201211T235730: (36.802936, -121.788090) 2020-12-11T23:58:24.569Z,1607731104.569 [Default:CheckIn:Read_GPS] Stopped 2020-12-11T23:58:24.569Z,1607731104.569 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-11T23:58:24.985Z,1607731104.985 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-12-11T23:58:43.555Z,1607731123.555 [NAL9602](INFO): SBD MO Status=1, MOMSN=4065, MT Status=0, MTMSN=0 2020-12-11T23:58:43.613Z,1607731123.613 [NAL9602](INFO): Sent 72 bytes from file Logs/20201211T235525/Courier0004.lzma 2020-12-11T23:58:43.613Z,1607731123.613 [NAL9602](INFO): Packets left to send: 0 2020-12-11T23:58:53.000Z,1607731134.000 [NAL9602](INFO): SBD MO Status=1, MOMSN=4066, MT Status=0, MTMSN=0 2020-12-11T23:58:54.057Z,1607731134.057 [NAL9602](INFO): Sent 171 bytes from file Logs/20201211T223617/Express0044.lzma 2020-12-11T23:58:54.057Z,1607731134.057 [NAL9602](INFO): Packets left to send: 0 2020-12-11T23:59:02.403Z,1607731142.403 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004657 2020-12-11T23:59:14.323Z,1607731154.323 [DataOverHttps](INFO): Sending 1163 bytes from file Logs/20201211T235525/Express0001.lzma 2020-12-11T23:59:15.322Z,1607731155.322 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0001.lzma.bak 2020-12-11T23:59:15.323Z,1607731155.323 [DataOverHttps](INFO): SBD MOMSN=13491668 2020-12-11T23:59:20.871Z,1607731160.871 [NAL9602](INFO): SBD MO Status=2, MOMSN=4067, MT Status=2, MTMSN=0 2020-12-11T23:59:20.871Z,1607731160.871 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-12-11T23:59:40.701Z,1607731180.701 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20201211T235525/Express0005.lzma 2020-12-11T23:59:41.703Z,1607731181.703 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0005.lzma.bak 2020-12-11T23:59:41.703Z,1607731181.703 [DataOverHttps](INFO): SBD MOMSN=13491704 2020-12-11T23:59:51.325Z,1607731191.325 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-11T23:59:52.181Z,1607731192.181 [Default:CheckIn:Read_Iridium] Stopped 2020-12-11T23:59:52.181Z,1607731192.181 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-11T23:59:52.181Z,1607731192.181 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:03:04.043Z,1607731384.043 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:03:15.763Z,1607731395.763 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:03:27.075Z,1607731407.075 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:03:38.391Z,1607731418.391 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:03:49.707Z,1607731429.707 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:04:00.615Z,1607731440.615 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:04:11.523Z,1607731451.523 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:04:23.233Z,1607731463.233 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:04:34.544Z,1607731474.544 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:04:45.857Z,1607731485.857 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:04:52.779Z,1607731492.779 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:04:52.779Z,1607731492.779 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:04:52.779Z,1607731492.779 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:04:52.780Z,1607731492.780 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:04:53.157Z,1607731493.157 [Default:CheckIn:D] Stopped 2020-12-12T00:04:53.157Z,1607731493.157 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:04:53.555Z,1607731493.555 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.739023 min 2020-12-12T00:04:53.555Z,1607731493.555 [Default:CheckIn:E] Stopped 2020-12-12T00:04:53.555Z,1607731493.555 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:04:53.555Z,1607731493.555 [Default:CheckIn] Stopped 2020-12-12T00:04:53.556Z,1607731493.556 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:04:53.556Z,1607731493.556 [Default:CheckIn](INFO): Running loop #2 2020-12-12T00:04:53.556Z,1607731493.556 [Default:CheckIn] Running Loop=2 2020-12-12T00:04:53.556Z,1607731493.556 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:04:53.556Z,1607731493.556 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:04:55.559Z,1607731495.559 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000401.00,A,3648.17600,N,12147.28545,W,0.000,0.00,121220,,,D*78 2020-12-12T00:04:55.561Z,1607731495.561 [NAL9602](INFO): GPS fix at 20201212T000401: (36.802933, -121.788091) 2020-12-12T00:04:55.572Z,1607731495.572 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:04:55.572Z,1607731495.572 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:04:57.575Z,1607731497.575 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:05:05.284Z,1607731505.284 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201211T235525/Courier0007.lzma 2020-12-12T00:05:06.286Z,1607731506.286 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0007.lzma.bak 2020-12-12T00:05:06.286Z,1607731506.286 [DataOverHttps](INFO): SBD MOMSN=13491729 2020-12-12T00:05:08.891Z,1607731508.891 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:05:12.927Z,1607731512.927 [NAL9602](INFO): SBD MO Status=1, MOMSN=4067, MT Status=0, MTMSN=0 2020-12-12T00:05:12.927Z,1607731512.927 [NAL9602](INFO): No messages in MT queue 2020-12-12T00:05:20.197Z,1607731520.197 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:05:28.361Z,1607731528.361 [DataOverHttps](INFO): Sending 160 bytes from file Logs/20201211T235525/Express0008.lzma 2020-12-12T00:05:29.362Z,1607731529.362 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0008.lzma.bak 2020-12-12T00:05:29.363Z,1607731529.363 [DataOverHttps](INFO): SBD MOMSN=13491732 2020-12-12T00:05:38.920Z,1607731538.920 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:05:38.920Z,1607731538.920 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:05:38.920Z,1607731538.920 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:05:43.390Z,1607731543.390 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:07:41.899Z,1607731661.899 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7). 2020-12-12T00:10:39.651Z,1607731839.651 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:10:39.651Z,1607731839.651 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:10:39.651Z,1607731839.651 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:10:39.651Z,1607731839.651 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:10:40.060Z,1607731840.060 [Default:CheckIn:D] Stopped 2020-12-12T00:10:40.060Z,1607731840.060 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:10:40.451Z,1607731840.451 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.520741 min 2020-12-12T00:10:40.451Z,1607731840.451 [Default:CheckIn:E] Stopped 2020-12-12T00:10:40.452Z,1607731840.452 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:10:40.452Z,1607731840.452 [Default:CheckIn] Stopped 2020-12-12T00:10:40.452Z,1607731840.452 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:10:40.452Z,1607731840.452 [Default:CheckIn](INFO): Running loop #3 2020-12-12T00:10:40.452Z,1607731840.452 [Default:CheckIn] Running Loop=3 2020-12-12T00:10:40.452Z,1607731840.452 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:10:40.452Z,1607731840.452 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:10:42.463Z,1607731842.463 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000949.00,A,3648.17542,N,12147.28651,W,0.019,0.00,121220,,,D*72 2020-12-12T00:10:42.465Z,1607731842.465 [NAL9602](INFO): GPS fix at 20201212T000949: (36.802924, -121.788109) 2020-12-12T00:10:42.476Z,1607731842.476 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:10:42.476Z,1607731842.476 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:10:51.453Z,1607731851.453 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201211T235525/Courier0010.lzma 2020-12-12T00:10:52.454Z,1607731852.454 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0010.lzma.bak 2020-12-12T00:10:52.454Z,1607731852.454 [DataOverHttps](INFO): SBD MOMSN=13491804 2020-12-12T00:11:05.103Z,1607731865.103 [NAL9602](INFO): SBD MO Status=1, MOMSN=4068, MT Status=0, MTMSN=0 2020-12-12T00:11:05.103Z,1607731865.103 [NAL9602](INFO): No messages in MT queue 2020-12-12T00:11:12.972Z,1607731872.972 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20201211T235525/Express0011.lzma 2020-12-12T00:11:13.974Z,1607731873.974 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0011.lzma.bak 2020-12-12T00:11:13.975Z,1607731873.975 [DataOverHttps](INFO): SBD MOMSN=13491807 2020-12-12T00:11:20.946Z,1607731880.946 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:11:20.946Z,1607731880.946 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:11:20.946Z,1607731880.946 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:11:34.026Z,1607731894.026 [CBIT](INFO): Clearing failed state for component ElevatorServo 2020-12-12T00:11:34.026Z,1607731894.026 [ElevatorServo] No Fault, FailCount= 3 2020-12-12T00:11:35.875Z,1607731895.875 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:12:43.816Z,1607731963.816 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:12:55.539Z,1607731975.539 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:13:06.845Z,1607731986.845 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:13:18.163Z,1607731998.163 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:13:29.511Z,1607732009.511 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:13:41.241Z,1607732021.241 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:13:52.559Z,1607732032.559 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:14:03.867Z,1607732043.867 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:14:14.779Z,1607732054.779 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:14:26.090Z,1607732066.090 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:14:36.999Z,1607732076.999 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:14:48.709Z,1607732088.709 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:15:00.022Z,1607732100.022 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:16:21.642Z,1607732181.642 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:16:21.642Z,1607732181.642 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:16:21.642Z,1607732181.642 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:16:21.642Z,1607732181.642 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:16:22.047Z,1607732182.047 [Default:CheckIn:D] Stopped 2020-12-12T00:16:22.047Z,1607732182.047 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:16:22.459Z,1607732182.459 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.220524 min 2020-12-12T00:16:22.459Z,1607732182.459 [Default:CheckIn:E] Stopped 2020-12-12T00:16:22.459Z,1607732182.459 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:16:22.459Z,1607732182.459 [Default:CheckIn] Stopped 2020-12-12T00:16:22.459Z,1607732182.459 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:16:22.459Z,1607732182.459 [Default:CheckIn](INFO): Running loop #4 2020-12-12T00:16:22.459Z,1607732182.459 [Default:CheckIn] Running Loop=4 2020-12-12T00:16:22.460Z,1607732182.460 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:16:22.460Z,1607732182.460 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:16:24.459Z,1607732184.459 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001531.00,A,3648.17620,N,12147.28555,W,0.019,0.00,121220,,,D*70 2020-12-12T00:16:24.461Z,1607732184.461 [NAL9602](INFO): GPS fix at 20201212T001531: (36.802937, -121.788093) 2020-12-12T00:16:24.619Z,1607732184.619 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:16:24.620Z,1607732184.620 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:16:29.602Z,1607732189.602 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201211T235525/Courier0013.lzma 2020-12-12T00:16:30.606Z,1607732190.606 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0013.lzma.bak 2020-12-12T00:16:30.607Z,1607732190.607 [DataOverHttps](INFO): SBD MOMSN=13491824 2020-12-12T00:16:38.691Z,1607732198.691 [NAL9602](INFO): SBD MO Status=1, MOMSN=4069, MT Status=0, MTMSN=0 2020-12-12T00:16:38.692Z,1607732198.692 [NAL9602](INFO): No messages in MT queue 2020-12-12T00:16:50.973Z,1607732210.973 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20201211T235525/Express0014.lzma 2020-12-12T00:16:51.974Z,1607732211.974 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0014.lzma.bak 2020-12-12T00:16:51.975Z,1607732211.975 [DataOverHttps](INFO): SBD MOMSN=13491827 2020-12-12T00:16:57.697Z,1607732217.697 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:16:57.697Z,1607732217.697 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:16:57.697Z,1607732217.697 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:17:09.391Z,1607732229.391 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:21:58.378Z,1607732518.378 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:21:58.378Z,1607732518.378 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:21:58.378Z,1607732518.378 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:21:58.378Z,1607732518.378 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:21:58.768Z,1607732518.768 [Default:CheckIn:D] Stopped 2020-12-12T00:21:58.768Z,1607732518.768 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:21:59.152Z,1607732519.152 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.832548 min 2020-12-12T00:21:59.152Z,1607732519.152 [Default:CheckIn:E] Stopped 2020-12-12T00:21:59.152Z,1607732519.152 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:21:59.152Z,1607732519.152 [Default:CheckIn] Stopped 2020-12-12T00:21:59.157Z,1607732519.157 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:21:59.157Z,1607732519.157 [Default:CheckIn](INFO): Running loop #5 2020-12-12T00:21:59.157Z,1607732519.157 [Default:CheckIn] Running Loop=5 2020-12-12T00:21:59.157Z,1607732519.157 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:21:59.157Z,1607732519.157 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:22:01.152Z,1607732521.152 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002108.00,A,3648.17548,N,12147.28454,W,0.000,0.00,121220,,,D*78 2020-12-12T00:22:01.154Z,1607732521.154 [NAL9602](INFO): GPS fix at 20201212T002108: (36.802925, -121.788076) 2020-12-12T00:22:01.164Z,1607732521.164 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:22:01.164Z,1607732521.164 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:22:10.792Z,1607732530.792 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20201211T235525/Courier0016.lzma 2020-12-12T00:22:11.794Z,1607732531.794 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0016.lzma.bak 2020-12-12T00:22:11.795Z,1607732531.795 [DataOverHttps](INFO): SBD MOMSN=13491891 2020-12-12T00:22:19.735Z,1607732539.735 [NAL9602](INFO): SBD MO Status=1, MOMSN=4070, MT Status=0, MTMSN=0 2020-12-12T00:22:19.735Z,1607732539.735 [NAL9602](INFO): No messages in MT queue 2020-12-12T00:22:21.755Z,1607732541.755 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:22:32.064Z,1607732552.064 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20201211T235525/Express0017.lzma 2020-12-12T00:22:33.067Z,1607732553.067 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0017.lzma.bak 2020-12-12T00:22:33.067Z,1607732553.067 [DataOverHttps](INFO): SBD MOMSN=13491894 2020-12-12T00:22:33.475Z,1607732553.475 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:22:40.369Z,1607732560.369 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:22:40.369Z,1607732560.369 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:22:40.369Z,1607732560.369 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:22:45.186Z,1607732565.186 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:22:50.441Z,1607732570.441 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:22:56.498Z,1607732576.498 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:23:07.815Z,1607732587.815 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:23:19.531Z,1607732599.531 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:23:30.863Z,1607732610.863 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:23:42.627Z,1607732622.627 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:23:53.935Z,1607732633.935 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:24:05.646Z,1607732645.646 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:24:17.363Z,1607732657.363 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:24:28.678Z,1607732668.678 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:24:39.991Z,1607732679.991 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2020-12-12T00:26:37.604Z,1607732797.604 [BPC1](INFO): Calculating totals. Valid battery stick count: 47. Valid reserve battery stick count: 5. 2020-12-12T00:26:37.606Z,1607732797.606 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle. 2020-12-12T00:27:41.110Z,1607732861.110 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:27:41.111Z,1607732861.111 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:27:41.111Z,1607732861.111 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:27:41.111Z,1607732861.111 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:27:41.473Z,1607732861.473 [Default:CheckIn:D] Stopped 2020-12-12T00:27:41.473Z,1607732861.473 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:27:41.914Z,1607732861.914 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.544287 min 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn:E] Stopped 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn] Stopped 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn](INFO): Running loop #6 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn] Running Loop=6 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:27:41.915Z,1607732861.915 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:27:43.883Z,1607732863.883 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002651.00,A,3648.17590,N,12147.28714,W,0.039,0.00,121220,,,D*7B 2020-12-12T00:27:43.886Z,1607732863.886 [NAL9602](INFO): GPS fix at 20201212T002651: (36.802932, -121.788119) 2020-12-12T00:27:43.896Z,1607732863.896 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:27:43.896Z,1607732863.896 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:27:53.669Z,1607732873.669 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20201211T235525/Courier0019.lzma 2020-12-12T00:27:54.671Z,1607732874.671 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0019.lzma.bak 2020-12-12T00:27:54.671Z,1607732874.671 [DataOverHttps](INFO): SBD MOMSN=13491918 2020-12-12T00:28:16.116Z,1607732896.116 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20201211T235525/Express0020.lzma 2020-12-12T00:28:17.118Z,1607732897.118 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0020.lzma.bak 2020-12-12T00:28:17.119Z,1607732897.119 [DataOverHttps](INFO): SBD MOMSN=13491921 2020-12-12T00:28:23.106Z,1607732903.106 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:28:23.106Z,1607732903.106 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:28:23.106Z,1607732903.106 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:28:30.355Z,1607732910.355 [NAL9602](INFO): SBD MO Status=1, MOMSN=4071, MT Status=0, MTMSN=0 2020-12-12T00:28:30.355Z,1607732910.355 [NAL9602](INFO): No messages in MT queue 2020-12-12T00:29:01.055Z,1607732941.055 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:33:23.767Z,1607733203.767 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:33:23.767Z,1607733203.767 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:33:23.767Z,1607733203.767 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:33:23.767Z,1607733203.767 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:33:24.173Z,1607733204.173 [Default:CheckIn:D] Stopped 2020-12-12T00:33:24.173Z,1607733204.173 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:33:24.575Z,1607733204.575 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.255961 min 2020-12-12T00:33:24.575Z,1607733204.575 [Default:CheckIn:E] Stopped 2020-12-12T00:33:24.575Z,1607733204.575 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:33:24.575Z,1607733204.575 [Default:CheckIn] Stopped 2020-12-12T00:33:24.575Z,1607733204.575 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:33:24.576Z,1607733204.576 [Default:CheckIn](INFO): Running loop #7 2020-12-12T00:33:24.576Z,1607733204.576 [Default:CheckIn] Running Loop=7 2020-12-12T00:33:24.576Z,1607733204.576 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:33:24.576Z,1607733204.576 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:33:26.583Z,1607733206.583 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,003233.00,A,3648.16868,N,12147.27584,W,0.428,253.93,121220,,,D*7F 2020-12-12T00:33:26.586Z,1607733206.586 [NAL9602](INFO): GPS fix at 20201212T003233: (36.802811, -121.787931) 2020-12-12T00:33:26.596Z,1607733206.596 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:33:26.596Z,1607733206.596 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:33:36.208Z,1607733216.208 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201211T235525/Courier0022.lzma 2020-12-12T00:33:37.210Z,1607733217.210 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0022.lzma.bak 2020-12-12T00:33:37.211Z,1607733217.211 [DataOverHttps](INFO): SBD MOMSN=13491977 2020-12-12T00:33:57.237Z,1607733237.237 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20201211T235525/Express0023.lzma 2020-12-12T00:33:58.239Z,1607733238.239 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0023.lzma.bak 2020-12-12T00:33:58.239Z,1607733238.239 [DataOverHttps](INFO): SBD MOMSN=13491980 2020-12-12T00:34:04.179Z,1607733244.179 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:34:04.179Z,1607733244.179 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:34:04.180Z,1607733244.180 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:38:28.370Z,1607733508.370 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-12-12T00:38:59.077Z,1607733539.077 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:39:04.763Z,1607733544.763 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:39:04.763Z,1607733544.763 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:39:04.763Z,1607733544.763 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:39:04.763Z,1607733544.763 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:39:05.175Z,1607733545.175 [Default:CheckIn:D] Stopped 2020-12-12T00:39:05.175Z,1607733545.175 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:39:05.547Z,1607733545.547 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.939331 min 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn:E] Stopped 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn] Stopped 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn](INFO): Running loop #8 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn] Running Loop=8 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:39:05.548Z,1607733545.548 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:39:07.557Z,1607733547.557 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,003814.00,A,3648.17089,N,12147.25684,W,0.952,131.76,121220,,,A*7E 2020-12-12T00:39:07.559Z,1607733547.559 [NAL9602](INFO): GPS fix at 20201212T003814: (36.802848, -121.787614) 2020-12-12T00:39:07.590Z,1607733547.590 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:39:07.590Z,1607733547.590 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:39:17.000Z,1607733557.000 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20201211T235525/Courier0025.lzma 2020-12-12T00:39:18.002Z,1607733558.002 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0025.lzma.bak 2020-12-12T00:39:18.003Z,1607733558.003 [DataOverHttps](INFO): SBD MOMSN=13491997 2020-12-12T00:39:38.153Z,1607733578.153 [DataOverHttps](INFO): Sending 232 bytes from file Logs/20201211T235525/Express0026.lzma 2020-12-12T00:39:38.262Z,1607733578.262 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2020-12-12T00:39:38.337Z,1607733578.337 [NAL9602](FAULT): received: +CSQ:0 OK71, 0, 0, 0, 0 OK 2020-12-12T00:39:38.337Z,1607733578.337 [NAL9602] Data Fault, FailCount= 1 2020-12-12T00:39:38.337Z,1607733578.337 [NAL9602](ERROR): Data Fault 2020-12-12T00:39:38.356Z,1607733578.356 [CBIT](ERROR): Data Fault in component: NAL9602 2020-12-12T00:39:38.663Z,1607733578.663 [NAL9602](INFO): Powering down 2020-12-12T00:39:39.154Z,1607733579.154 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0026.lzma.bak 2020-12-12T00:39:39.155Z,1607733579.155 [DataOverHttps](INFO): SBD MOMSN=13492000 2020-12-12T00:39:39.495Z,1607733579.495 [CBIT](INFO): Clearing failed state for component NAL9602 2020-12-12T00:39:39.495Z,1607733579.495 [NAL9602] No Fault, FailCount= 1 2020-12-12T00:39:45.182Z,1607733585.182 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:39:45.182Z,1607733585.182 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:39:45.182Z,1607733585.182 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:40:08.963Z,1607733608.963 [NAL9602](INFO): Powering up NAL9602 2020-12-12T00:40:19.876Z,1607733619.876 [NAL9602](INFO): NAL9602 initialized 2020-12-12T00:40:50.981Z,1607733650.981 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:44:45.719Z,1607733885.719 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-12-12T00:44:45.719Z,1607733885.719 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:44:45.719Z,1607733885.719 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:44:45.719Z,1607733885.719 [Default:CheckIn:D] Running Loop=1 2020-12-12T00:44:46.123Z,1607733886.123 [Default:CheckIn:D] Stopped 2020-12-12T00:44:46.123Z,1607733886.123 [Default:CheckIn:E] Running Loop=1 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.621794 min 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn:E] Stopped 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn] Stopped 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn](INFO): Running loop #9 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn] Running Loop=9 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-12-12T00:44:46.530Z,1607733886.530 [Default:CheckIn:Read_GPS] Running Loop=1 2020-12-12T00:44:50.147Z,1607733890.147 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-12-12T00:49:46.715Z,1607734186.715 [Default:CheckIn:Read_GPS](INFO): Timed out from 2020-12-12T00:44:46.5Z 2020-12-12T00:49:46.715Z,1607734186.715 [Default:CheckIn:Read_GPS] Stopped 2020-12-12T00:49:46.715Z,1607734186.715 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-12-12T00:49:56.492Z,1607734196.492 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20201211T235525/Courier0028.lzma 2020-12-12T00:49:57.494Z,1607734197.494 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Courier0028.lzma.bak 2020-12-12T00:49:57.495Z,1607734197.495 [DataOverHttps](INFO): SBD MOMSN=13492070 2020-12-12T00:50:19.062Z,1607734219.062 [DataOverHttps](INFO): Sending 244 bytes from file Logs/20201211T235525/Express0029.lzma 2020-12-12T00:50:19.409Z,1607734219.409 [NAL9602](INFO): Not Powering down - fast GPS 2020-12-12T00:50:20.062Z,1607734220.062 [DataOverHttps](INFO): Moved sent file to Logs/20201211T235525/Express0029.lzma.bak 2020-12-12T00:50:20.063Z,1607734220.063 [DataOverHttps](INFO): SBD MOMSN=13492072 2020-12-12T00:50:25.895Z,1607734225.895 [Default:CheckIn:Read_Iridium] Stopped 2020-12-12T00:50:25.895Z,1607734225.895 [Default:CheckIn:C.Wait] Running Loop=1 2020-12-12T00:50:25.896Z,1607734225.896 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-12-12T00:50:29.733Z,1607734229.733 [CommandLine](IMPORTANT): got command quit 2020-12-12T00:50:30.737Z,1607734230.737 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:30.737Z,1607734230.737 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:30.812Z,1607734230.812 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2020-12-12T00:50:30.813Z,1607734230.813 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:30.813Z,1607734230.813 [CommandLine](INFO): Join timeout helper Thread ID is 6171 2020-12-12T00:50:30.814Z,1607734230.814 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2020-12-12T00:50:30.814Z,1607734230.814 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:30.814Z,1607734230.814 [NavChartDb](INFO): Join timeout helper Thread ID is 6172 2020-12-12T00:50:30.909Z,1607734230.909 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:30.909Z,1607734230.909 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:30.913Z,1607734230.913 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2020-12-12T00:50:30.913Z,1607734230.913 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:30.913Z,1607734230.913 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 6173 2020-12-12T00:50:30.957Z,1607734230.957 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:30.957Z,1607734230.957 [WetLabsBB2FL](INFO): Powering down 2020-12-12T00:50:30.958Z,1607734230.958 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:30.973Z,1607734230.973 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2020-12-12T00:50:30.973Z,1607734230.973 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:30.973Z,1607734230.973 [CTD_Seabird](INFO): Join timeout helper Thread ID is 6174 2020-12-12T00:50:31.153Z,1607734231.153 [CTD_Seabird](INFO): Powering down 2020-12-12T00:50:31.165Z,1607734231.165 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:31.165Z,1607734231.165 [CTD_Seabird](INFO): Powering down 2020-12-12T00:50:31.177Z,1607734231.177 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:31.185Z,1607734231.185 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2020-12-12T00:50:31.185Z,1607734231.185 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:31.185Z,1607734231.185 [Radio_Surface](INFO): Join timeout helper Thread ID is 6175 2020-12-12T00:50:31.261Z,1607734231.261 [Radio_Surface](INFO): Powering down 2020-12-12T00:50:31.261Z,1607734231.261 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:31.262Z,1607734231.262 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:31.273Z,1607734231.273 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler 2020-12-12T00:50:31.274Z,1607734231.274 [Onboard ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:31.274Z,1607734231.274 [Onboard](INFO): Join timeout helper Thread ID is 6176 2020-12-12T00:50:34.689Z,1607734234.689 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:34.689Z,1607734234.689 [Onboard ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:34.697Z,1607734234.697 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2020-12-12T00:50:34.697Z,1607734234.697 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:34.698Z,1607734234.698 [DataOverHttps](INFO): Join timeout helper Thread ID is 6177 2020-12-12T00:50:35.517Z,1607734235.517 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:35.520Z,1607734235.520 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.534Z,1607734235.534 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2020-12-12T00:50:35.534Z,1607734235.534 [logger ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.534Z,1607734235.534 [logger](INFO): Join timeout helper Thread ID is 6178 2020-12-12T00:50:35.565Z,1607734235.565 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:35.565Z,1607734235.565 [logger ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.573Z,1607734235.573 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2020-12-12T00:50:35.574Z,1607734235.574 [CommandLine ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.574Z,1607734235.574 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2020-12-12T00:50:35.574Z,1607734235.574 [controlThread ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.574Z,1607734235.574 [controlThread](INFO): Join timeout helper Thread ID is 6179 2020-12-12T00:50:35.591Z,1607734235.591 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2020-12-12T00:50:35.591Z,1607734235.591 [controlThread](DEBUG): Uninitializing ControlThread 2020-12-12T00:50:35.591Z,1607734235.591 [AHRS_M2](INFO): Powering down 2020-12-12T00:50:35.661Z,1607734235.661 [NAL9602](INFO): Powering down 2020-12-12T00:50:35.662Z,1607734235.662 [DAT](INFO): Powering down 2020-12-12T00:50:35.783Z,1607734235.783 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2020-12-12T00:50:35.784Z,1607734235.784 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2020-12-12T00:50:35.784Z,1607734235.784 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2020-12-12T00:50:35.785Z,1607734235.785 [MissionManager](INFO): Uninitializing Mission Default 2020-12-12T00:50:35.785Z,1607734235.785 [Default] Stopped 2020-12-12T00:50:35.785Z,1607734235.785 [Default](DEBUG): Aggregate::uninitialize Default 2020-12-12T00:50:35.785Z,1607734235.785 [Default:B.GoToSurface] Stopped 2020-12-12T00:50:35.785Z,1607734235.785 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-12-12T00:50:35.785Z,1607734235.785 [Default:CheckIn] Stopped 2020-12-12T00:50:35.785Z,1607734235.785 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-12-12T00:50:35.785Z,1607734235.785 [Default:CheckIn:C.Wait] Stopped 2020-12-12T00:50:35.785Z,1607734235.785 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-12-12T00:50:35.788Z,1607734235.788 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2020-12-12T00:50:35.788Z,1607734235.788 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2020-12-12T00:50:35.788Z,1607734235.788 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2020-12-12T00:50:35.789Z,1607734235.789 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2020-12-12T00:50:35.789Z,1607734235.789 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2020-12-12T00:50:35.789Z,1607734235.789 [BuoyancyServo](INFO): Powering down 2020-12-12T00:50:35.801Z,1607734235.801 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2020-12-12T00:50:35.801Z,1607734235.801 [ElevatorServo](INFO): Powering down 2020-12-12T00:50:35.802Z,1607734235.802 [MassServo](DEBUG): Uninitialize Mass Servo. 2020-12-12T00:50:35.802Z,1607734235.802 [MassServo](INFO): Powering down 2020-12-12T00:50:35.802Z,1607734235.802 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2020-12-12T00:50:35.802Z,1607734235.802 [RudderServo](INFO): Powering down 2020-12-12T00:50:35.803Z,1607734235.803 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2020-12-12T00:50:35.803Z,1607734235.803 [ThrusterServo](INFO): Powering down 2020-12-12T00:50:35.804Z,1607734235.804 [SBIT](DEBUG): Uninitialize SBIT Component. 2020-12-12T00:50:35.804Z,1607734235.804 [IBIT](DEBUG): Uninitialize IBIT Component. 2020-12-12T00:50:35.805Z,1607734235.805 [CBIT](DEBUG): Uninitialize CBIT Component. 2020-12-12T00:50:35.805Z,1607734235.805 [CBIT](DEBUG): Powering off loads. 2020-12-12T00:50:35.816Z,1607734235.816 [CBIT](DEBUG): Disabling WDT. 2020-12-12T00:50:35.828Z,1607734235.828 [CBIT](DEBUG): Opening all GF detection circuits. 2020-12-12T00:50:35.829Z,1607734235.829 [controlThread ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.930Z,1607734235.930 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.932Z,1607734235.932 [Onboard ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.938Z,1607734235.938 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.984Z,1607734235.984 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:35.990Z,1607734235.990 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:36.024Z,1607734236.024 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2020-12-12T00:50:36.102Z,1607734236.102 [logger ThreadHandler](INFO): Thread cancelled.