2019-10-21T22:47:28.458Z,1571698048.458 [Supervisor](DEBUG): Initializing supervisor. 2019-10-21T22:47:28.461Z,1571698048.461 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-10-21T22:47:28.461Z,1571698048.461 [SyncHandler](INFO): Protected caller Thread ID is 806 2019-10-21T22:47:28.462Z,1571698048.462 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-10-21T22:47:28.463Z,1571698048.463 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-10-21T22:47:28.463Z,1571698048.463 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807 2019-10-21T22:47:28.465Z,1571698048.465 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-10-21T22:47:28.476Z,1571698048.476 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-10-21T22:47:28.477Z,1571698048.477 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-10-21T22:47:28.478Z,1571698048.478 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808 2019-10-21T22:47:28.478Z,1571698048.478 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-10-21T22:47:28.479Z,1571698048.479 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-10-21T22:47:28.480Z,1571698048.480 [logger ThreadHandler](INFO): Protected caller Thread ID is 809 2019-10-21T22:47:28.482Z,1571698048.482 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-10-21T22:47:28.482Z,1571698048.482 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-10-21T22:47:28.486Z,1571698048.486 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-10-21T22:47:28.687Z,1571698048.687 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-10-21T22:47:28.689Z,1571698048.689 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-10-21T22:47:28.771Z,1571698048.771 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-10-21T22:47:29.194Z,1571698049.194 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-10-21T22:47:29.195Z,1571698049.195 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-10-21T22:47:29.515Z,1571698049.515 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-10-21T22:47:29.517Z,1571698049.517 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-10-21T22:47:29.612Z,1571698049.612 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-10-21T22:47:29.614Z,1571698049.614 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-10-21T22:47:29.904Z,1571698049.904 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-10-21T22:47:29.905Z,1571698049.905 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-10-21T22:47:30.111Z,1571698050.111 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-10-21T22:47:30.113Z,1571698050.113 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-10-21T22:47:30.556Z,1571698050.556 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-10-21T22:47:30.557Z,1571698050.557 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-10-21T22:47:30.661Z,1571698050.661 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-10-21T22:47:30.663Z,1571698050.663 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-10-21T22:47:30.762Z,1571698050.762 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-10-21T22:47:30.763Z,1571698050.763 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-10-21T22:47:31.375Z,1571698051.375 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-10-21T22:47:31.375Z,1571698051.375 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-10-21T22:47:31.761Z,1571698051.761 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-10-21T22:47:31.763Z,1571698051.763 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-10-21T22:47:31.962Z,1571698051.962 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-10-21T22:47:32.422Z,1571698052.422 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-10-21T22:47:32.791Z,1571698052.791 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-10-21T22:47:32.791Z,1571698052.791 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-10-21T22:47:32.940Z,1571698052.940 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-10-21T22:47:32.942Z,1571698052.942 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2019-10-21T22:47:32.945Z,1571698052.945 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2019-10-21T22:47:33.035Z,1571698053.035 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2019-10-21T22:47:33.120Z,1571698053.120 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2019-10-21T22:47:33.265Z,1571698053.265 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2019-10-21T22:47:33.347Z,1571698053.347 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2019-10-21T22:47:33.442Z,1571698053.442 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2019-10-21T22:47:33.542Z,1571698053.542 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2019-10-21T22:47:33.744Z,1571698053.744 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2019-10-21T22:47:33.820Z,1571698053.820 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2019-10-21T22:47:33.982Z,1571698053.982 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2019-10-21T22:47:34.113Z,1571698054.113 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2019-10-21T22:47:34.228Z,1571698054.228 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2019-10-21T22:47:34.452Z,1571698054.452 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-10-21T22:47:34.453Z,1571698054.453 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-10-21T22:47:34.464Z,1571698054.464 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-10-21T22:47:34.552Z,1571698054.552 [VerticalControl](DEBUG): Construct VerticalControl. 2019-10-21T22:47:34.663Z,1571698054.663 [VerticalControl] Loaded 2019-10-21T22:47:34.663Z,1571698054.663 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-10-21T22:47:34.664Z,1571698054.664 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-10-21T22:47:34.732Z,1571698054.732 [HorizontalControl] Loaded 2019-10-21T22:47:34.732Z,1571698054.732 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-10-21T22:47:34.733Z,1571698054.733 [SpeedControl](DEBUG): Construct SpeedControl. 2019-10-21T22:47:34.738Z,1571698054.738 [SpeedControl] Loaded 2019-10-21T22:47:34.738Z,1571698054.738 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-10-21T22:47:34.739Z,1571698054.739 [LoopControl](DEBUG): Construct LoopControl. 2019-10-21T22:47:34.739Z,1571698054.739 [LoopControl] Loaded 2019-10-21T22:47:34.740Z,1571698054.740 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-10-21T22:47:34.740Z,1571698054.740 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-10-21T22:47:34.741Z,1571698054.741 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-10-21T22:47:34.765Z,1571698054.765 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-10-21T22:47:34.765Z,1571698054.765 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-10-21T22:47:34.889Z,1571698054.889 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-10-21T22:47:34.890Z,1571698054.890 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-10-21T22:47:35.053Z,1571698055.053 [BuoyancyServo] Loaded 2019-10-21T22:47:35.053Z,1571698055.053 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-10-21T22:47:35.064Z,1571698055.064 [ElevatorServo] Loaded 2019-10-21T22:47:35.065Z,1571698055.065 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-10-21T22:47:35.081Z,1571698055.081 [MassServo] Loaded 2019-10-21T22:47:35.081Z,1571698055.081 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-10-21T22:47:35.092Z,1571698055.092 [RudderServo] Loaded 2019-10-21T22:47:35.092Z,1571698055.092 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-10-21T22:47:35.103Z,1571698055.103 [ThrusterServo] Loaded 2019-10-21T22:47:35.103Z,1571698055.103 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-10-21T22:47:35.104Z,1571698055.104 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-10-21T22:47:35.104Z,1571698055.104 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-10-21T22:47:35.227Z,1571698055.227 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-10-21T22:47:35.227Z,1571698055.227 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-10-21T22:47:35.247Z,1571698055.247 [NavChart] Loaded 2019-10-21T22:47:35.248Z,1571698055.248 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-10-21T22:47:35.252Z,1571698055.252 [UniversalFixResidualReporter] Loaded 2019-10-21T22:47:35.252Z,1571698055.252 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-10-21T22:47:35.252Z,1571698055.252 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-10-21T22:47:35.253Z,1571698055.253 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-10-21T22:47:35.365Z,1571698055.365 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-10-21T22:47:35.366Z,1571698055.366 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-10-21T22:47:35.822Z,1571698055.822 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2019-10-21T22:47:35.827Z,1571698055.827 [AHRS_M2](INFO): created writer for : platform_orientation 2019-10-21T22:47:35.829Z,1571698055.829 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2019-10-21T22:47:35.834Z,1571698055.834 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2019-10-21T22:47:35.834Z,1571698055.834 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2019-10-21T22:47:35.839Z,1571698055.839 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2019-10-21T22:47:35.840Z,1571698055.840 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2019-10-21T22:47:35.845Z,1571698055.845 [AHRS_M2](INFO): created writer for : platform_roll_angle 2019-10-21T22:47:36.021Z,1571698056.021 [AHRS_M2] Loaded 2019-10-21T22:47:36.021Z,1571698056.021 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-10-21T22:47:36.167Z,1571698056.167 [DataOverHttps] Loaded 2019-10-21T22:47:36.167Z,1571698056.167 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-10-21T22:47:36.168Z,1571698056.168 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4086C4E0 2019-10-21T22:47:36.169Z,1571698056.169 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 892 2019-10-21T22:47:36.182Z,1571698056.182 [Depth_Keller] Loaded 2019-10-21T22:47:36.183Z,1571698056.183 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-10-21T22:47:36.187Z,1571698056.187 [DropWeight] Loaded 2019-10-21T22:47:36.188Z,1571698056.188 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-10-21T22:47:36.283Z,1571698056.283 [NAL9602] Loaded 2019-10-21T22:47:36.283Z,1571698056.283 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-10-21T22:47:36.299Z,1571698056.299 [Onboard] Loaded 2019-10-21T22:47:36.299Z,1571698056.299 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-10-21T22:47:36.302Z,1571698056.302 [Radio_Surface] Loaded 2019-10-21T22:47:36.303Z,1571698056.303 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-10-21T22:47:36.304Z,1571698056.304 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4089C4E0 2019-10-21T22:47:36.304Z,1571698056.304 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 893 2019-10-21T22:47:38.034Z,1571698058.034 [BPC1] Loaded 2019-10-21T22:47:38.034Z,1571698058.034 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-10-21T22:47:38.035Z,1571698058.035 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-10-21T22:47:38.035Z,1571698058.035 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-10-21T22:47:38.090Z,1571698058.090 [DepthRateCalculator] Loaded 2019-10-21T22:47:38.091Z,1571698058.091 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-10-21T22:47:38.096Z,1571698058.096 [PitchRateCalculator] Loaded 2019-10-21T22:47:38.096Z,1571698058.096 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-10-21T22:47:38.108Z,1571698058.108 [SpeedCalculator] Loaded 2019-10-21T22:47:38.108Z,1571698058.108 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-10-21T22:47:38.129Z,1571698058.129 [TempGradientCalculator] Loaded 2019-10-21T22:47:38.129Z,1571698058.129 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-10-21T22:47:38.134Z,1571698058.134 [YawRateCalculator] Loaded 2019-10-21T22:47:38.135Z,1571698058.135 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-10-21T22:47:38.164Z,1571698058.164 [ElevatorOffsetCalculator] Loaded 2019-10-21T22:47:38.164Z,1571698058.164 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-10-21T22:47:38.164Z,1571698058.164 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-10-21T22:47:38.165Z,1571698058.165 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-10-21T22:47:38.421Z,1571698058.421 [Aanderaa_O2] Loaded 2019-10-21T22:47:38.421Z,1571698058.421 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2019-10-21T22:47:38.433Z,1571698058.433 [CANONSampler] Loaded 2019-10-21T22:47:38.433Z,1571698058.433 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread. 2019-10-21T22:47:38.443Z,1571698058.443 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2019-10-21T22:47:38.448Z,1571698058.448 [CTD_Seabird](INFO): created writer for : sea_water_density 2019-10-21T22:47:38.448Z,1571698058.448 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2019-10-21T22:47:38.453Z,1571698058.453 [CTD_Seabird](INFO): created writer for : depth 2019-10-21T22:47:38.453Z,1571698058.453 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2019-10-21T22:47:38.458Z,1571698058.458 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2019-10-21T22:47:38.459Z,1571698058.459 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2019-10-21T22:47:38.464Z,1571698058.464 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2019-10-21T22:47:38.465Z,1571698058.465 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2019-10-21T22:47:38.469Z,1571698058.469 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2019-10-21T22:47:38.470Z,1571698058.470 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2019-10-21T22:47:38.476Z,1571698058.476 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2019-10-21T22:47:38.476Z,1571698058.476 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2019-10-21T22:47:38.481Z,1571698058.481 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2019-10-21T22:47:38.508Z,1571698058.508 [CTD_Seabird] Loaded 2019-10-21T22:47:38.508Z,1571698058.508 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2019-10-21T22:47:38.509Z,1571698058.509 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4099F4E0 2019-10-21T22:47:38.510Z,1571698058.510 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 894 2019-10-21T22:47:38.524Z,1571698058.524 [PAR_Licor] Loaded 2019-10-21T22:47:38.524Z,1571698058.524 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-10-21T22:47:38.572Z,1571698058.572 [WetLabsBB2FL] Loaded 2019-10-21T22:47:38.572Z,1571698058.572 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2019-10-21T22:47:38.573Z,1571698058.573 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409CF4E0 2019-10-21T22:47:38.573Z,1571698058.573 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 895 2019-10-21T22:47:38.574Z,1571698058.574 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-10-21T22:47:38.575Z,1571698058.575 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-10-21T22:47:38.623Z,1571698058.623 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-10-21T22:47:38.624Z,1571698058.624 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-10-21T22:47:38.966Z,1571698058.966 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-10-21T22:47:38.967Z,1571698058.967 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-10-21T22:47:39.126Z,1571698059.126 [SBIT](DEBUG): Construct Startup Built In Test. 2019-10-21T22:47:39.137Z,1571698059.137 [SBIT] Loaded 2019-10-21T22:47:39.137Z,1571698059.137 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-10-21T22:47:39.138Z,1571698059.138 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-10-21T22:47:39.150Z,1571698059.150 [IBIT] Loaded 2019-10-21T22:47:39.150Z,1571698059.150 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-10-21T22:47:39.153Z,1571698059.153 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-10-21T22:47:39.290Z,1571698059.290 [CBIT] Loaded 2019-10-21T22:47:39.290Z,1571698059.290 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-10-21T22:47:39.290Z,1571698059.290 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-10-21T22:47:39.294Z,1571698059.294 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-10-21T22:47:39.295Z,1571698059.295 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-10-21T22:47:39.301Z,1571698059.301 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-10-21T22:47:39.302Z,1571698059.302 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACE4E0 2019-10-21T22:47:39.303Z,1571698059.303 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 896 2019-10-21T22:47:39.307Z,1571698059.307 [Supervisor](INFO): Main Thread ID is 802 2019-10-21T22:47:39.307Z,1571698059.307 [Supervisor](DEBUG): Running supervisor. 2019-10-21T22:47:39.308Z,1571698059.308 [CommandLine ThreadHandler](INFO): Handler Thread ID is 897 2019-10-21T22:47:39.310Z,1571698059.310 [controlThread ThreadHandler](INFO): Handler Thread ID is 898 2019-10-21T22:47:39.311Z,1571698059.311 [controlThread](DEBUG): Initializing ControlThread 2019-10-21T22:47:39.312Z,1571698059.312 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-10-21T22:47:39.313Z,1571698059.313 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-10-21T22:47:39.314Z,1571698059.314 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-10-21T22:47:39.314Z,1571698059.314 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-10-21T22:47:39.316Z,1571698059.316 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-10-21T22:47:39.316Z,1571698059.316 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-10-21T22:47:39.323Z,1571698059.323 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-10-21T22:47:39.323Z,1571698059.323 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-10-21T22:47:39.323Z,1571698059.323 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-10-21T22:47:39.324Z,1571698059.324 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-10-21T22:47:39.324Z,1571698059.324 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-10-21T22:47:39.325Z,1571698059.325 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-10-21T22:47:39.329Z,1571698059.329 [SBIT](INFO): Initialize SBIT Component. 2019-10-21T22:47:39.330Z,1571698059.330 [SBIT](IMPORTANT): git: 2019-10-18 2019-10-21T22:47:39.330Z,1571698059.330 [SBIT](INFO): git hash: 6ae7fb07418ec55f2c4bd6dfbf631ba443720c7a 2019-10-21T22:47:39.330Z,1571698059.330 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-10-21T22:47:39.331Z,1571698059.331 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018 2019-10-21T22:47:39.332Z,1571698059.332 [SBIT](INFO): Beginning SBIT in 39.000000 seconds. 2019-10-21T22:47:39.333Z,1571698059.333 [IBIT](INFO): Initialize IBIT Component. 2019-10-21T22:47:39.334Z,1571698059.334 [CBIT](DEBUG): Initialize CBIT Component. 2019-10-21T22:47:39.335Z,1571698059.335 [logger ThreadHandler](INFO): Handler Thread ID is 899 2019-10-21T22:47:39.345Z,1571698059.345 [CBIT](DEBUG): Initialized mux pins. 2019-10-21T22:47:39.345Z,1571698059.345 [CBIT](DEBUG): Initializing the watchdog timer. 2019-10-21T22:47:39.353Z,1571698059.353 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 900 2019-10-21T22:47:39.354Z,1571698059.354 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-10-21T22:47:39.365Z,1571698059.365 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 901 2019-10-21T22:47:39.369Z,1571698059.369 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-10-21T22:47:39.369Z,1571698059.369 [CBIT](DEBUG): Initializing heartbeat. 2019-10-21T22:47:39.377Z,1571698059.377 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 902 2019-10-21T22:47:39.378Z,1571698059.378 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2019-10-21T22:47:39.381Z,1571698059.381 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20 2019-10-21T22:47:39.382Z,1571698059.382 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 904 2019-10-21T22:47:39.384Z,1571698059.384 [WetLabsBB2FL](INFO): Powering down 2019-10-21T22:47:39.405Z,1571698059.405 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 905 2019-10-21T22:47:39.413Z,1571698059.413 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-10-21T22:47:39.414Z,1571698059.414 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-10-21T22:47:39.414Z,1571698059.414 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-10-21T22:47:39.414Z,1571698059.414 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-10-21T22:47:39.414Z,1571698059.414 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-10-21T22:47:39.414Z,1571698059.414 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-10-21T22:47:39.415Z,1571698059.415 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-10-21T22:47:39.415Z,1571698059.415 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-10-21T22:47:39.415Z,1571698059.415 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-10-21T22:47:39.415Z,1571698059.415 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-10-21T22:47:39.415Z,1571698059.415 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-10-21T22:47:39.416Z,1571698059.416 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-10-21T22:47:39.416Z,1571698059.416 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-10-21T22:47:39.416Z,1571698059.416 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-10-21T22:47:39.416Z,1571698059.416 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-10-21T22:47:39.416Z,1571698059.416 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-10-21T22:47:39.441Z,1571698059.441 [CBIT](DEBUG): Deactivating GF circuits. 2019-10-21T22:47:39.441Z,1571698059.441 [CBIT](DEBUG): Deactivating emergency mode. 2019-10-21T22:47:39.477Z,1571698059.477 [CBIT](DEBUG): Backplane powered. 2019-10-21T22:47:39.478Z,1571698059.478 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-10-21T22:47:39.503Z,1571698059.503 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-10-21T22:47:39.513Z,1571698059.513 [MissionManager](DEBUG): 2019-10-21T22:47:39.514Z,1571698059.514 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-10-21T22:47:39.576Z,1571698059.576 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-10-21T22:47:39.593Z,1571698059.593 [Default:A.Wait](DEBUG): Construct Wait. 2019-10-21T22:47:39.595Z,1571698059.595 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-10-21T22:47:39.622Z,1571698059.622 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-10-21T22:47:39.624Z,1571698059.624 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-10-21T22:47:39.660Z,1571698059.660 [Default:E.Execute](DEBUG): Construct Execute. 2019-10-21T22:47:39.678Z,1571698059.678 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2019-10-21T22:47:39.683Z,1571698059.683 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,BPC1,Aanderaa_O2,CANONSampler,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-10-21T22:47:39.689Z,1571698059.689 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-10-21T22:47:39.769Z,1571698059.769 [Radio_Surface](INFO): Powering up 2019-10-21T22:47:39.871Z,1571698059.871 [CANONSampler](INFO): Powering down 2019-10-21T22:47:40.002Z,1571698060.002 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-10-21T22:47:40.009Z,1571698060.009 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-10-21T22:47:40.010Z,1571698060.010 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-10-21T22:47:40.017Z,1571698060.017 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-10-21T22:47:40.018Z,1571698060.018 [MassServo](DEBUG): Initializing EZServoServo. 2019-10-21T22:47:40.025Z,1571698060.025 [MassServo](DEBUG): Initializing MassServo. 2019-10-21T22:47:40.026Z,1571698060.026 [RudderServo](DEBUG): Initializing EZServoServo. 2019-10-21T22:47:40.033Z,1571698060.033 [RudderServo](DEBUG): Initializing RudderServo. 2019-10-21T22:47:40.034Z,1571698060.034 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-10-21T22:47:40.041Z,1571698060.041 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-10-21T22:47:40.865Z,1571698060.865 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-10-21T22:47:40.865Z,1571698060.865 [RudderServo](FAULT): Rudder failed to initialize 2019-10-21T22:47:40.865Z,1571698060.865 [RudderServo] Communications Fault, FailCount= 1 2019-10-21T22:47:40.865Z,1571698060.865 [RudderServo](ERROR): Communications Fault 2019-10-21T22:47:41.060Z,1571698061.060 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-10-21T22:47:41.262Z,1571698061.262 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-10-21T22:47:41.262Z,1571698061.262 [RudderServo](INFO): Powering down 2019-10-21T22:47:41.951Z,1571698061.951 [RudderServo](DEBUG): Initializing EZServoServo. 2019-10-21T22:47:42.070Z,1571698062.070 [RudderServo](DEBUG): Initializing RudderServo. 2019-10-21T22:47:42.074Z,1571698062.074 [CBIT](INFO): Clearing failed state for component RudderServo 2019-10-21T22:47:42.074Z,1571698062.074 [RudderServo] No Fault, FailCount= 1 2019-10-21T22:47:43.297Z,1571698063.297 [Aanderaa_O2](INFO): Powering down 2019-10-21T22:48:06.358Z,1571698086.358 [NAL9602](INFO): Powering up NAL9602 2019-10-21T22:48:17.258Z,1571698097.258 [NAL9602](INFO): NAL9602 initialized 2019-10-21T22:48:18.986Z,1571698098.986 [SBIT](IMPORTANT): Beginning Startup BIT 2019-10-21T22:48:18.990Z,1571698098.990 [CBIT](IMPORTANT): Beginning ground fault scan 2019-10-21T22:48:29.991Z,1571698109.991 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.012102 CHAN A1 (24V): -0.180591 CHAN A2 (12V): -0.002239 CHAN A3 (5V): -0.001038 CHAN B0 (3.3V): 4.766929 CHAN B1 (3.15aV): -0.000304 CHAN B2 (3.15bV): 0.000034 CHAN B3 (GND): 0.000424 OPEN: -0.000589 Full Scale Calc: 4.765 mA, -1.589 mA 2019-10-21T22:49:12.964Z,1571698152.964 [SBIT](IMPORTANT): SBIT PASSED 2019-10-21T22:49:13.002Z,1571698153.002 [CommandLine](IMPORTANT): got command configSet list 2019-10-21T22:49:13.002Z,1571698153.002 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-10-21T22:49:13.003Z,1571698153.003 [CommandLine](IMPORTANT): CBIT.gf24Offset=154 microampere; 2019-10-21T22:49:13.003Z,1571698153.003 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool; 2019-10-21T22:49:13.003Z,1571698153.003 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool; 2019-10-21T22:49:13.003Z,1571698153.003 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool; 2019-10-21T22:49:13.003Z,1571698153.003 [CommandLine](IMPORTANT): VerticalControl.massDefault=-0.5 centimeter; 2019-10-21T22:49:13.367Z,1571698153.367 [MissionManager](IMPORTANT): Started mission Startup 2019-10-21T22:49:13.367Z,1571698153.367 [Startup] Running Loop=1 2019-10-21T22:49:13.367Z,1571698153.367 [Startup](DEBUG): Aggregate::initialize Startup 2019-10-21T22:49:13.367Z,1571698153.367 [Startup:A.GoToSurface] Running Loop=1 2019-10-21T22:49:13.367Z,1571698153.367 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-10-21T22:49:13.368Z,1571698153.368 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-10-21T22:49:13.368Z,1571698153.368 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-10-21T22:49:13.369Z,1571698153.369 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-10-21T22:49:13.369Z,1571698153.369 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-10-21T22:49:13.370Z,1571698153.370 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-10-21T22:49:13.371Z,1571698153.371 [Startup:StartupSatComms] Running Loop=1 2019-10-21T22:49:13.371Z,1571698153.371 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-10-21T22:49:13.371Z,1571698153.371 [Startup:StartupSatComms:A] Running Loop=1 2019-10-21T22:49:13.888Z,1571698153.888 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-10-21T22:49:39.994Z,1571698179.994 [CommandLine](IMPORTANT): got command failComponent 2019-10-21T22:49:39.994Z,1571698179.994 [CommandLine](IMPORTANT): Failed components: 2019-10-21T22:49:39.994Z,1571698179.994 [CommandLine](IMPORTANT): No failed Components. 2019-10-21T22:50:13.558Z,1571698213.558 [Startup:StartupSatComms:A](INFO): Timed out from 2019-10-21T22:49:13.4Z 2019-10-21T22:50:13.558Z,1571698213.558 [Startup:StartupSatComms:A] Stopped 2019-10-21T22:50:13.559Z,1571698213.559 [Startup:StartupSatComms:B] Running Loop=1 2019-10-21T22:50:13.964Z,1571698213.964 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-10-21T22:50:39.429Z,1571698239.429 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-10-21T22:50:39.429Z,1571698239.429 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-10-21T22:50:39.454Z,1571698239.454 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-10-21T22:50:39.591Z,1571698239.591 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005181 2019-10-21T22:50:39.858Z,1571698239.858 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-10-21T22:50:39.858Z,1571698239.858 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-10-21T22:50:52.765Z,1571698252.765 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20191021T002758/Courier0381.lzma 2019-10-21T22:50:54.772Z,1571698254.772 [DataOverHttps](INFO): Moved sent file to Logs/20191021T002758/Courier0381.lzma.bak 2019-10-21T22:50:54.772Z,1571698254.772 [DataOverHttps](INFO): SBD MOMSN=11932191 2019-10-21T22:51:11.600Z,1571698271.600 [DataOverHttps](INFO): Sending 96 bytes from file Logs/20191021T223010/Courier0007.lzma 2019-10-21T22:51:13.606Z,1571698273.606 [DataOverHttps](INFO): Moved sent file to Logs/20191021T223010/Courier0007.lzma.bak 2019-10-21T22:51:13.606Z,1571698273.606 [DataOverHttps](INFO): SBD MOMSN=11932193 2019-10-21T22:51:13.739Z,1571698273.739 [Startup:StartupSatComms:B](INFO): Timed out from 2019-10-21T22:50:13.6Z 2019-10-21T22:51:13.740Z,1571698273.740 [Startup:StartupSatComms:B] Stopped 2019-10-21T22:51:13.740Z,1571698273.740 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-10-21T22:51:13.740Z,1571698273.740 [Startup:StartupSatComms] Stopped 2019-10-21T22:51:13.740Z,1571698273.740 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-10-21T22:51:13.745Z,1571698273.745 [Startup](INFO): Completed Startup 2019-10-21T22:51:13.745Z,1571698273.745 [MissionManager](INFO): Startup is completed. 2019-10-21T22:51:13.745Z,1571698273.745 [MissionManager](INFO): Uninitializing Mission Startup 2019-10-21T22:51:13.745Z,1571698273.745 [Startup] Stopped 2019-10-21T22:51:13.745Z,1571698273.745 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-10-21T22:51:13.745Z,1571698273.745 [Startup:A.GoToSurface] Stopped 2019-10-21T22:51:13.745Z,1571698273.745 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-10-21T22:51:14.206Z,1571698274.206 [MissionManager](IMPORTANT): Started mission Default 2019-10-21T22:51:14.206Z,1571698274.206 [Default] Running Loop=1 2019-10-21T22:51:14.206Z,1571698274.206 [Default](DEBUG): Aggregate::initialize Default 2019-10-21T22:51:14.206Z,1571698274.206 [Default:B.GoToSurface] Running Loop=1 2019-10-21T22:51:14.206Z,1571698274.206 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-10-21T22:51:14.206Z,1571698274.206 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-10-21T22:51:14.207Z,1571698274.207 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-10-21T22:51:14.207Z,1571698274.207 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-10-21T22:51:14.207Z,1571698274.207 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-10-21T22:51:14.208Z,1571698274.208 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-10-21T22:51:14.208Z,1571698274.208 [Default:A.Wait] Running Loop=1 2019-10-21T22:51:14.208Z,1571698274.208 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-10-21T22:51:27.544Z,1571698287.544 [Default:A.Wait](INFO): Done Waiting. 2019-10-21T22:51:27.544Z,1571698287.544 [Default:A.Wait] Stopped 2019-10-21T22:51:27.544Z,1571698287.544 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T22:51:27.876Z,1571698287.876 [Default:CheckIn] Running Loop=1 2019-10-21T22:51:27.876Z,1571698287.876 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T22:51:27.876Z,1571698287.876 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T22:51:28.303Z,1571698288.303 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-10-21T22:53:20.569Z,1571698400.569 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-10-21T22:53:40.402Z,1571698420.402 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2019-10-21T22:53:40.402Z,1571698420.402 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-10-21T22:53:40.428Z,1571698420.428 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-10-21T22:53:40.814Z,1571698420.814 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-10-21T22:53:40.815Z,1571698420.815 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2019-10-21T22:55:29.865Z,1571698529.865 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-10-21T22:55:29.868Z,1571698529.868 [BPC1](INFO): Received data from all battery sticks. 2019-10-21T22:56:28.067Z,1571698588.067 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-21T22:51:27.9Z 2019-10-21T22:56:28.067Z,1571698588.067 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T22:56:28.068Z,1571698588.068 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T22:56:28.471Z,1571698588.471 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-10-21T22:56:35.620Z,1571698595.620 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191021T224215/Courier0004.lzma 2019-10-21T22:56:37.626Z,1571698597.626 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224215/Courier0004.lzma.bak 2019-10-21T22:56:37.626Z,1571698597.626 [DataOverHttps](INFO): SBD MOMSN=11932204 2019-10-21T22:56:41.393Z,1571698601.393 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2019-10-21T22:56:41.393Z,1571698601.393 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-10-21T22:56:41.411Z,1571698601.411 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-10-21T22:56:41.812Z,1571698601.812 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-10-21T22:56:41.812Z,1571698601.812 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2019-10-21T22:56:54.192Z,1571698614.192 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20191021T224215/Courier0007.lzma 2019-10-21T22:56:56.198Z,1571698616.198 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224215/Courier0007.lzma.bak 2019-10-21T22:56:56.198Z,1571698616.198 [DataOverHttps](INFO): SBD MOMSN=11932207 2019-10-21T22:57:12.768Z,1571698632.768 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20191021T224728/Courier0004.lzma 2019-10-21T22:57:14.771Z,1571698634.771 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0004.lzma.bak 2019-10-21T22:57:14.771Z,1571698634.771 [DataOverHttps](INFO): SBD MOMSN=11932209 2019-10-21T22:57:31.304Z,1571698651.304 [DataOverHttps](INFO): Sending 96 bytes from file Logs/20191021T225202/Courier0000.lzma 2019-10-21T22:57:33.310Z,1571698653.310 [DataOverHttps](INFO): Moved sent file to Logs/20191021T225202/Courier0000.lzma.bak 2019-10-21T22:57:33.310Z,1571698653.310 [DataOverHttps](INFO): SBD MOMSN=11932212 2019-10-21T22:57:49.904Z,1571698669.904 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20191021T002758/Express0382.lzma 2019-10-21T22:57:51.911Z,1571698671.911 [DataOverHttps](INFO): Moved sent file to Logs/20191021T002758/Express0382.lzma.bak 2019-10-21T22:57:51.911Z,1571698671.911 [DataOverHttps](INFO): SBD MOMSN=11932216 2019-10-21T22:58:08.621Z,1571698688.621 [DataOverHttps](INFO): Sending 1520 bytes from file Logs/20191021T223010/Express0008.lzma 2019-10-21T22:58:10.623Z,1571698690.623 [DataOverHttps](INFO): Moved sent file to Logs/20191021T223010/Express0008.lzma.bak 2019-10-21T22:58:10.623Z,1571698690.623 [DataOverHttps](IMPORTANT): SBD MOMSN=11932219, MTMSN=20191021T225741 2019-10-21T22:58:17.889Z,1571698697.889 [DataOverHttps](INFO): Received command:configSet VerticalControl.buoyancyNeutral 315 cc persist;configSet VerticalControl.massDefault -1 cm persist 2019-10-21T22:58:18.448Z,1571698698.448 [CommandLine](IMPORTANT): got command configSet VerticalControl.buoyancyNeutral 315.000000 cubic_centimeter persist 2019-10-21T22:58:18.452Z,1571698698.452 [CommandLine](IMPORTANT): got command configSet VerticalControl.massDefault -1.000000 centimeter persist 2019-10-21T22:58:18.718Z,1571698698.718 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-10-21T22:58:18.718Z,1571698698.718 [NAL9602] Data Fault, FailCount= 1 2019-10-21T22:58:18.718Z,1571698698.718 [NAL9602](ERROR): Data Fault 2019-10-21T22:58:18.778Z,1571698698.778 [CBIT](ERROR): Data Fault in component: NAL9602 2019-10-21T22:58:19.118Z,1571698699.118 [NAL9602](INFO): Powering down 2019-10-21T22:58:19.522Z,1571698699.522 [NAL9602](FAULT): LCB fault: Software Overcurrent. 2019-10-21T22:58:19.522Z,1571698699.522 [NAL9602] Hardware Fault, FailCount= 1 2019-10-21T22:58:19.522Z,1571698699.522 [NAL9602](ERROR): Hardware Fault 2019-10-21T22:58:19.967Z,1571698699.967 [CBIT](INFO): Clearing failed state for component NAL9602 2019-10-21T22:58:19.967Z,1571698699.967 [NAL9602] No Fault, FailCount= 1 2019-10-21T22:58:27.290Z,1571698707.290 [DataOverHttps](INFO): Sending 743 bytes from file Logs/20191021T224215/Express0001.lzma 2019-10-21T22:58:29.294Z,1571698709.294 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224215/Express0001.lzma.bak 2019-10-21T22:58:29.295Z,1571698709.295 [DataOverHttps](INFO): SBD MOMSN=11932222 2019-10-21T22:58:46.296Z,1571698726.296 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191021T224728/Courier0007.lzma 2019-10-21T22:58:48.302Z,1571698728.302 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0007.lzma.bak 2019-10-21T22:58:48.302Z,1571698728.302 [DataOverHttps](INFO): SBD MOMSN=11932240 2019-10-21T22:58:49.446Z,1571698729.446 [NAL9602](INFO): Powering up NAL9602 2019-10-21T22:59:00.354Z,1571698740.354 [NAL9602](INFO): NAL9602 initialized 2019-10-21T22:59:04.845Z,1571698744.845 [DataOverHttps](INFO): Sending 175 bytes from file Logs/20191021T224215/Express0005.lzma 2019-10-21T22:59:06.851Z,1571698746.851 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224215/Express0005.lzma.bak 2019-10-21T22:59:06.852Z,1571698746.852 [DataOverHttps](INFO): SBD MOMSN=11932242 2019-10-21T22:59:10.746Z,1571698750.746 [CommandLine](IMPORTANT): got command show variable stopDepth 2019-10-21T22:59:10.781Z,1571698750.781 [CommandLine](IMPORTANT): VerticalControl.stopDepthExcursion (meter) 2019-10-21T22:59:10.788Z,1571698750.788 [CommandLine](IMPORTANT): CBIT.stopDepth (meter) 2019-10-21T22:59:16.394Z,1571698756.394 [CommandLine](IMPORTANT): got command get CBIT.stopDepth 2019-10-21T22:59:16.395Z,1571698756.395 [CommandLine](IMPORTANT): CBIT.stopDepth 205.000000 m 2019-10-21T22:59:19.906Z,1571698759.906 [CommandLine](IMPORTANT): got command show variable abortDepth 2019-10-21T22:59:19.974Z,1571698759.974 [CommandLine](IMPORTANT): CBIT.abortDepth (meter) 2019-10-21T22:59:19.975Z,1571698759.975 [CommandLine](IMPORTANT): CBIT.abortDepthTimeout (second) 2019-10-21T22:59:23.812Z,1571698763.812 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20191021T224215/Express0008.lzma 2019-10-21T22:59:25.214Z,1571698765.214 [CommandLine](IMPORTANT): got command get CBIT.abortDepth 2019-10-21T22:59:25.215Z,1571698765.215 [CommandLine](IMPORTANT): CBIT.abortDepth 250.000000 m 2019-10-21T22:59:25.819Z,1571698765.819 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224215/Express0008.lzma.bak 2019-10-21T22:59:25.819Z,1571698765.819 [DataOverHttps](INFO): SBD MOMSN=11932246 2019-10-21T22:59:37.646Z,1571698777.646 [CommandLine](IMPORTANT): got command show variable neutral 2019-10-21T22:59:37.668Z,1571698777.668 [CommandLine](IMPORTANT): Config/Simulator.buoyancyNeutralOffset (cubic_centimeter) 2019-10-21T22:59:37.686Z,1571698777.686 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral (cubic_centimeter) 2019-10-21T22:59:42.378Z,1571698782.378 [DataOverHttps](INFO): Sending 755 bytes from file Logs/20191021T224728/Express0001.lzma 2019-10-21T22:59:42.445Z,1571698782.445 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2019-10-21T22:59:42.445Z,1571698782.445 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-10-21T22:59:42.464Z,1571698782.464 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-10-21T22:59:42.587Z,1571698782.587 [CommandLine](IMPORTANT): got command get VerticalControl.buoyancyNeutral 2019-10-21T22:59:42.587Z,1571698782.587 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral 315.000000 cc 2019-10-21T22:59:42.824Z,1571698782.824 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-10-21T22:59:42.824Z,1571698782.824 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2019-10-21T22:59:44.362Z,1571698784.362 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0001.lzma.bak 2019-10-21T22:59:44.362Z,1571698784.362 [DataOverHttps](INFO): SBD MOMSN=11932248 2019-10-21T22:59:53.406Z,1571698793.406 [CommandLine](IMPORTANT): got command show variable massDefault 2019-10-21T22:59:53.441Z,1571698793.441 [CommandLine](IMPORTANT): VerticalControl.massDefault (centimeter) 2019-10-21T22:59:58.641Z,1571698798.641 [CommandLine](IMPORTANT): got command get VerticalControl.massDefault 2019-10-21T22:59:58.642Z,1571698798.642 [CommandLine](IMPORTANT): VerticalControl.massDefault -1.000000 cm 2019-10-21T23:00:01.789Z,1571698801.789 [DataOverHttps](INFO): Sending 175 bytes from file Logs/20191021T224728/Express0005.lzma 2019-10-21T23:00:03.794Z,1571698803.794 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0005.lzma.bak 2019-10-21T23:00:03.794Z,1571698803.794 [DataOverHttps](INFO): SBD MOMSN=11932269 2019-10-21T23:00:10.391Z,1571698810.391 [CommandLine](IMPORTANT): got command show variable limitFwd 2019-10-21T23:00:10.433Z,1571698810.433 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd (millimeter) 2019-10-21T23:00:15.229Z,1571698815.229 [CommandLine](IMPORTANT): got command get VerticalControl.massPositionLimitFwd 2019-10-21T23:00:15.230Z,1571698815.230 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd 25.000000 mm 2019-10-21T23:00:18.274Z,1571698818.274 [CommandLine](IMPORTANT): got command get VerticalControl.massPositionLimitAft 2019-10-21T23:00:18.275Z,1571698818.275 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft -35.000000 mm 2019-10-21T23:00:21.481Z,1571698821.481 [DataOverHttps](INFO): Sending 259 bytes from file Logs/20191021T224728/Express0008.lzma 2019-10-21T23:00:23.486Z,1571698823.486 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0008.lzma.bak 2019-10-21T23:00:23.487Z,1571698823.487 [DataOverHttps](INFO): SBD MOMSN=11932273 2019-10-21T23:00:34.631Z,1571698834.631 [CommandLine](IMPORTANT): got command show variable canonSampler.load 2019-10-21T23:00:34.692Z,1571698834.692 [CommandLine](IMPORTANT): CANONSampler.loadControl (none) 2019-10-21T23:00:34.712Z,1571698834.712 [CommandLine](IMPORTANT): CANONSampler.loadAtStartup (bool) 2019-10-21T23:00:40.070Z,1571698840.070 [DataOverHttps](INFO): Sending 674 bytes from file Logs/20191021T225202/Express0001.lzma 2019-10-21T23:00:41.368Z,1571698841.368 [CommandLine](IMPORTANT): got command get CANONSampler.loadAtStartup 2019-10-21T23:00:41.368Z,1571698841.368 [CommandLine](IMPORTANT): CANONSampler.loadAtStartup 1 bool 2019-10-21T23:00:42.075Z,1571698842.075 [DataOverHttps](INFO): Moved sent file to Logs/20191021T225202/Express0001.lzma.bak 2019-10-21T23:00:42.075Z,1571698842.075 [DataOverHttps](INFO): SBD MOMSN=11932279 2019-10-21T23:00:43.823Z,1571698843.823 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:00:43.823Z,1571698843.823 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:00:43.823Z,1571698843.823 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:02:14.209Z,1571698934.209 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-21T23:02:43.416Z,1571698963.416 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2019-10-21T23:02:43.416Z,1571698963.416 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-10-21T23:02:43.426Z,1571698963.426 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-10-21T23:02:43.846Z,1571698963.846 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-10-21T23:02:43.846Z,1571698963.846 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2019-10-21T23:05:17.297Z,1571699117.297 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-21T23:05:44.403Z,1571699144.403 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6 2019-10-21T23:05:44.403Z,1571699144.403 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-10-21T23:05:44.404Z,1571699144.404 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:05:44.404Z,1571699144.404 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:05:44.404Z,1571699144.404 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:05:44.404Z,1571699144.404 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:05:44.413Z,1571699144.413 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-10-21T23:05:44.804Z,1571699144.804 [Default:CheckIn:D] Stopped 2019-10-21T23:05:44.804Z,1571699144.804 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:05:44.813Z,1571699144.813 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-10-21T23:05:44.813Z,1571699144.813 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6 2019-10-21T23:05:45.203Z,1571699145.203 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 14.509968 min 2019-10-21T23:05:45.203Z,1571699145.203 [Default:CheckIn:E] Stopped 2019-10-21T23:05:45.203Z,1571699145.203 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:05:45.203Z,1571699145.203 [Default:CheckIn] Stopped 2019-10-21T23:05:45.203Z,1571699145.203 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:05:45.203Z,1571699145.203 [Default:CheckIn](INFO): Running loop #2 2019-10-21T23:05:45.204Z,1571699145.204 [Default:CheckIn] Running Loop=2 2019-10-21T23:05:45.204Z,1571699145.204 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:05:45.204Z,1571699145.204 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:05:48.421Z,1571699148.421 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-21T23:07:44.359Z,1571699264.359 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230714.00,A,3648.15392,N,12147.27845,W,0.641,0.00,211019,,,A*7E 2019-10-21T23:07:44.362Z,1571699264.362 [NAL9602](INFO): GPS fix at 20191021T230714: (36.802565, -121.787974) 2019-10-21T23:07:44.386Z,1571699264.386 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:07:44.386Z,1571699264.386 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:07:53.785Z,1571699273.785 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20191021T224728/Courier0010.lzma 2019-10-21T23:07:55.790Z,1571699275.790 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0010.lzma.bak 2019-10-21T23:07:55.790Z,1571699275.790 [DataOverHttps](INFO): SBD MOMSN=11932306 2019-10-21T23:08:14.001Z,1571699294.001 [DataOverHttps](INFO): Sending 743 bytes from file Logs/20191021T224728/Express0011.lzma 2019-10-21T23:08:16.006Z,1571699296.006 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0011.lzma.bak 2019-10-21T23:08:16.006Z,1571699296.006 [DataOverHttps](INFO): SBD MOMSN=11932309 2019-10-21T23:08:17.174Z,1571699297.174 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:08:17.610Z,1571699297.610 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:08:17.610Z,1571699297.610 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:08:17.610Z,1571699297.610 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:09:46.706Z,1571699386.706 [CommandLine](IMPORTANT): got command failComponent 2019-10-21T23:09:46.706Z,1571699386.706 [CommandLine](IMPORTANT): Failed components: 2019-10-21T23:09:46.707Z,1571699386.707 [CommandLine](IMPORTANT): No failed Components. 2019-10-21T23:13:18.202Z,1571699598.202 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:13:18.202Z,1571699598.202 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:13:18.202Z,1571699598.202 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:13:18.202Z,1571699598.202 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:13:18.609Z,1571699598.609 [Default:CheckIn:D] Stopped 2019-10-21T23:13:18.609Z,1571699598.609 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:13:19.025Z,1571699599.025 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.073391 min 2019-10-21T23:13:19.025Z,1571699599.025 [Default:CheckIn:E] Stopped 2019-10-21T23:13:19.025Z,1571699599.025 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:13:19.025Z,1571699599.025 [Default:CheckIn] Stopped 2019-10-21T23:13:19.025Z,1571699599.025 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:13:19.026Z,1571699599.026 [Default:CheckIn](INFO): Running loop #3 2019-10-21T23:13:19.026Z,1571699599.026 [Default:CheckIn] Running Loop=3 2019-10-21T23:13:19.026Z,1571699599.026 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:13:19.026Z,1571699599.026 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:13:21.015Z,1571699601.015 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231250.00,A,3648.16627,N,12147.27756,W,0.272,348.79,211019,,,A*7A 2019-10-21T23:13:21.018Z,1571699601.018 [NAL9602](INFO): GPS fix at 20191021T231250: (36.802771, -121.787959) 2019-10-21T23:13:21.068Z,1571699601.068 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:13:21.068Z,1571699601.068 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:13:29.004Z,1571699609.004 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191021T224728/Courier0013.lzma 2019-10-21T23:13:31.010Z,1571699611.010 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0013.lzma.bak 2019-10-21T23:13:31.010Z,1571699611.010 [DataOverHttps](INFO): SBD MOMSN=11932458 2019-10-21T23:13:47.880Z,1571699627.880 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20191021T224728/Express0014.lzma 2019-10-21T23:13:49.886Z,1571699629.886 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0014.lzma.bak 2019-10-21T23:13:49.886Z,1571699629.886 [DataOverHttps](INFO): SBD MOMSN=11932464 2019-10-21T23:13:51.749Z,1571699631.749 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:13:51.749Z,1571699631.749 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:13:51.749Z,1571699631.749 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:14:29.715Z,1571699669.715 [NAL9602](INFO): SBD MO Status=2, MOMSN=16895, MT Status=2, MTMSN=0 2019-10-21T23:14:29.715Z,1571699669.715 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:15:12.551Z,1571699712.551 [NAL9602](INFO): SBD MO Status=2, MOMSN=16895, MT Status=2, MTMSN=0 2019-10-21T23:15:12.551Z,1571699712.551 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:15:35.967Z,1571699735.967 [NAL9602](INFO): SBD MO Status=2, MOMSN=16895, MT Status=2, MTMSN=0 2019-10-21T23:15:35.968Z,1571699735.968 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:15:57.383Z,1571699757.383 [NAL9602](INFO): SBD MO Status=2, MOMSN=16895, MT Status=2, MTMSN=0 2019-10-21T23:15:57.383Z,1571699757.383 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:16:17.179Z,1571699777.179 [NAL9602](INFO): SBD MO Status=2, MOMSN=16895, MT Status=2, MTMSN=0 2019-10-21T23:16:17.180Z,1571699777.180 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:17:14.955Z,1571699834.955 [NAL9602](INFO): SBD MO Status=2, MOMSN=16895, MT Status=2, MTMSN=0 2019-10-21T23:17:14.955Z,1571699834.955 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:18:23.624Z,1571699903.624 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-10-21T23:18:52.341Z,1571699932.341 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:18:52.341Z,1571699932.341 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:18:52.341Z,1571699932.341 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:18:52.341Z,1571699932.341 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:18:52.748Z,1571699932.748 [Default:CheckIn:D] Stopped 2019-10-21T23:18:52.748Z,1571699932.748 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:18:53.185Z,1571699933.185 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.642373 min 2019-10-21T23:18:53.185Z,1571699933.185 [Default:CheckIn:E] Stopped 2019-10-21T23:18:53.186Z,1571699933.186 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:18:53.186Z,1571699933.186 [Default:CheckIn] Stopped 2019-10-21T23:18:53.186Z,1571699933.186 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:18:53.186Z,1571699933.186 [Default:CheckIn](INFO): Running loop #4 2019-10-21T23:18:53.186Z,1571699933.186 [Default:CheckIn] Running Loop=4 2019-10-21T23:18:53.186Z,1571699933.186 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:18:53.186Z,1571699933.186 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:18:55.140Z,1571699935.140 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231824.00,A,3648.16779,N,12147.28301,W,0.136,333.74,211019,,,A*72 2019-10-21T23:18:55.142Z,1571699935.142 [NAL9602](INFO): GPS fix at 20191021T231824: (36.802796, -121.788050) 2019-10-21T23:18:55.183Z,1571699935.183 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:18:55.183Z,1571699935.183 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:19:03.236Z,1571699943.236 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191021T224728/Courier0016.lzma 2019-10-21T23:19:05.243Z,1571699945.243 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0016.lzma.bak 2019-10-21T23:19:05.243Z,1571699945.243 [DataOverHttps](INFO): SBD MOMSN=11932539 2019-10-21T23:19:22.128Z,1571699962.128 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191021T224728/Express0017.lzma 2019-10-21T23:19:24.134Z,1571699964.134 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0017.lzma.bak 2019-10-21T23:19:24.134Z,1571699964.134 [DataOverHttps](INFO): SBD MOMSN=11932546 2019-10-21T23:19:25.874Z,1571699965.874 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:19:25.874Z,1571699965.874 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:19:25.874Z,1571699965.874 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:19:27.051Z,1571699967.051 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:24:26.447Z,1571700266.447 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:24:26.447Z,1571700266.447 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:24:26.447Z,1571700266.447 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:24:26.447Z,1571700266.447 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:24:26.846Z,1571700266.846 [Default:CheckIn:D] Stopped 2019-10-21T23:24:26.846Z,1571700266.846 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:24:27.250Z,1571700267.250 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 33.210663 min 2019-10-21T23:24:27.250Z,1571700267.250 [Default:CheckIn:E] Stopped 2019-10-21T23:24:27.250Z,1571700267.250 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:24:27.250Z,1571700267.250 [Default:CheckIn] Stopped 2019-10-21T23:24:27.250Z,1571700267.250 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:24:27.250Z,1571700267.250 [Default:CheckIn](INFO): Running loop #5 2019-10-21T23:24:27.251Z,1571700267.251 [Default:CheckIn] Running Loop=5 2019-10-21T23:24:27.251Z,1571700267.251 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:24:27.251Z,1571700267.251 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:24:29.258Z,1571700269.258 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,232358.00,A,3648.16238,N,12147.27708,W,0.136,333.74,211019,,,A*73 2019-10-21T23:24:29.260Z,1571700269.260 [NAL9602](INFO): GPS fix at 20191021T232358: (36.802706, -121.787951) 2019-10-21T23:24:29.289Z,1571700269.289 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:24:29.289Z,1571700269.289 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:24:37.064Z,1571700277.064 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191021T224728/Courier0019.lzma 2019-10-21T23:24:39.070Z,1571700279.070 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0019.lzma.bak 2019-10-21T23:24:39.071Z,1571700279.071 [DataOverHttps](INFO): SBD MOMSN=11932840 2019-10-21T23:24:59.296Z,1571700299.296 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191021T224728/Express0020.lzma 2019-10-21T23:24:59.974Z,1571700299.974 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-10-21T23:25:00.049Z,1571700300.049 [NAL9602](FAULT): received: +CSQ:0 OK895, 2, 0, 0, 0 OK 2019-10-21T23:25:00.049Z,1571700300.049 [NAL9602] Data Fault, FailCount= 2 2019-10-21T23:25:00.049Z,1571700300.049 [NAL9602](ERROR): Data Fault 2019-10-21T23:25:00.112Z,1571700300.112 [CBIT](ERROR): Data Fault in component: NAL9602 2019-10-21T23:25:00.367Z,1571700300.367 [NAL9602](INFO): Powering down 2019-10-21T23:25:01.206Z,1571700301.206 [CBIT](INFO): Clearing failed state for component NAL9602 2019-10-21T23:25:01.206Z,1571700301.206 [NAL9602] No Fault, FailCount= 2 2019-10-21T23:25:01.302Z,1571700301.302 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0020.lzma.bak 2019-10-21T23:25:01.302Z,1571700301.302 [DataOverHttps](INFO): SBD MOMSN=11932849 2019-10-21T23:25:02.818Z,1571700302.818 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:25:02.818Z,1571700302.818 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:25:02.818Z,1571700302.818 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:25:30.671Z,1571700330.671 [NAL9602](INFO): Powering up NAL9602 2019-10-21T23:25:41.607Z,1571700341.607 [NAL9602](INFO): NAL9602 initialized 2019-10-21T23:26:12.687Z,1571700372.687 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:30:03.402Z,1571700603.402 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:30:03.403Z,1571700603.403 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:30:03.403Z,1571700603.403 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:30:03.403Z,1571700603.403 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:30:03.817Z,1571700603.817 [Default:CheckIn:D] Stopped 2019-10-21T23:30:03.817Z,1571700603.817 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:30:04.202Z,1571700604.202 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.826847 min 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn:E] Stopped 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn] Stopped 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn](INFO): Running loop #6 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn] Running Loop=6 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:30:04.203Z,1571700604.203 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:30:06.207Z,1571700606.207 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,232933.00,A,3648.14230,N,12147.24306,W,0.078,98.87,211019,,,A*42 2019-10-21T23:30:06.210Z,1571700606.210 [NAL9602](INFO): GPS fix at 20191021T232933: (36.802372, -121.787384) 2019-10-21T23:30:06.242Z,1571700606.242 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:30:06.242Z,1571700606.242 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:30:07.822Z,1571700607.822 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-10-21T23:30:14.228Z,1571700614.228 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191021T224728/Courier0022.lzma 2019-10-21T23:30:16.234Z,1571700616.234 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0022.lzma.bak 2019-10-21T23:30:16.234Z,1571700616.234 [DataOverHttps](INFO): SBD MOMSN=11932920 2019-10-21T23:30:33.228Z,1571700633.228 [DataOverHttps](INFO): Sending 178 bytes from file Logs/20191021T224728/Express0023.lzma 2019-10-21T23:30:35.234Z,1571700635.234 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0023.lzma.bak 2019-10-21T23:30:35.234Z,1571700635.234 [DataOverHttps](INFO): SBD MOMSN=11932926 2019-10-21T23:30:36.945Z,1571700636.945 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:30:36.945Z,1571700636.945 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:30:36.945Z,1571700636.945 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:30:38.522Z,1571700638.522 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:35:37.515Z,1571700937.515 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:35:37.515Z,1571700937.515 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:35:37.515Z,1571700937.515 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:35:37.515Z,1571700937.515 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:35:37.907Z,1571700937.907 [Default:CheckIn:D] Stopped 2019-10-21T23:35:37.907Z,1571700937.907 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:35:38.325Z,1571700938.325 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 44.395020 min 2019-10-21T23:35:38.325Z,1571700938.325 [Default:CheckIn:E] Stopped 2019-10-21T23:35:38.325Z,1571700938.325 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:35:38.326Z,1571700938.326 [Default:CheckIn] Stopped 2019-10-21T23:35:38.326Z,1571700938.326 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:35:38.326Z,1571700938.326 [Default:CheckIn](INFO): Running loop #7 2019-10-21T23:35:38.326Z,1571700938.326 [Default:CheckIn] Running Loop=7 2019-10-21T23:35:38.326Z,1571700938.326 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:35:38.326Z,1571700938.326 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:35:40.315Z,1571700940.315 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,233507.00,A,3648.14272,N,12147.22898,W,0.039,88.88,211019,,,D*4A 2019-10-21T23:35:40.330Z,1571700940.330 [NAL9602](INFO): GPS fix at 20191021T233507: (36.802379, -121.787150) 2019-10-21T23:35:40.354Z,1571700940.354 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:35:40.354Z,1571700940.354 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:35:48.156Z,1571700948.156 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191021T224728/Courier0025.lzma 2019-10-21T23:35:50.482Z,1571700950.482 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0025.lzma.bak 2019-10-21T23:35:50.482Z,1571700950.482 [DataOverHttps](INFO): SBD MOMSN=11933375 2019-10-21T23:36:03.339Z,1571700963.339 [NAL9602](INFO): SBD MO Status=0, MOMSN=16895, MT Status=0, MTMSN=0 2019-10-21T23:36:03.339Z,1571700963.339 [NAL9602](INFO): No messages in MT queue 2019-10-21T23:36:07.233Z,1571700967.233 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20191021T224728/Express0026.lzma 2019-10-21T23:36:09.238Z,1571700969.238 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0026.lzma.bak 2019-10-21T23:36:09.238Z,1571700969.238 [DataOverHttps](INFO): SBD MOMSN=11933381 2019-10-21T23:36:11.055Z,1571700971.055 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:36:11.056Z,1571700971.056 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:36:11.056Z,1571700971.056 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:36:34.042Z,1571700994.042 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:41:11.620Z,1571701271.620 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:41:11.621Z,1571701271.621 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:41:11.621Z,1571701271.621 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:41:11.621Z,1571701271.621 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:41:12.029Z,1571701272.029 [Default:CheckIn:D] Stopped 2019-10-21T23:41:12.029Z,1571701272.029 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:41:12.432Z,1571701272.432 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.963708 min 2019-10-21T23:41:12.432Z,1571701272.432 [Default:CheckIn:E] Stopped 2019-10-21T23:41:12.432Z,1571701272.432 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:41:12.433Z,1571701272.433 [Default:CheckIn] Stopped 2019-10-21T23:41:12.433Z,1571701272.433 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:41:12.433Z,1571701272.433 [Default:CheckIn](INFO): Running loop #8 2019-10-21T23:41:12.433Z,1571701272.433 [Default:CheckIn] Running Loop=8 2019-10-21T23:41:12.433Z,1571701272.433 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:41:12.433Z,1571701272.433 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:41:14.424Z,1571701274.424 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234042.00,A,3648.15304,N,12147.22043,W,0.039,359.31,211019,,,D*7B 2019-10-21T23:41:14.438Z,1571701274.438 [NAL9602](INFO): GPS fix at 20191021T234042: (36.802551, -121.787007) 2019-10-21T23:41:14.482Z,1571701274.482 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:41:14.482Z,1571701274.482 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:41:22.004Z,1571701282.004 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191021T224728/Courier0028.lzma 2019-10-21T23:41:24.010Z,1571701284.010 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0028.lzma.bak 2019-10-21T23:41:24.011Z,1571701284.011 [DataOverHttps](INFO): SBD MOMSN=11933823 2019-10-21T23:41:28.563Z,1571701288.563 [NAL9602](INFO): SBD MO Status=0, MOMSN=16896, MT Status=0, MTMSN=0 2019-10-21T23:41:28.563Z,1571701288.563 [NAL9602](INFO): No messages in MT queue 2019-10-21T23:41:40.976Z,1571701300.976 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191021T224728/Express0029.lzma 2019-10-21T23:41:42.982Z,1571701302.982 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0029.lzma.bak 2019-10-21T23:41:42.982Z,1571701302.982 [DataOverHttps](INFO): SBD MOMSN=11933876 2019-10-21T23:41:44.756Z,1571701304.756 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:41:44.756Z,1571701304.756 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:41:44.756Z,1571701304.756 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:41:59.266Z,1571701319.266 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:46:45.336Z,1571701605.336 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:46:45.336Z,1571701605.336 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:46:45.336Z,1571701605.336 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:46:45.336Z,1571701605.336 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:46:45.747Z,1571701605.747 [Default:CheckIn:D] Stopped 2019-10-21T23:46:45.747Z,1571701605.747 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:46:46.133Z,1571701606.133 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.525671 min 2019-10-21T23:46:46.133Z,1571701606.133 [Default:CheckIn:E] Stopped 2019-10-21T23:46:46.133Z,1571701606.133 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:46:46.133Z,1571701606.133 [Default:CheckIn] Stopped 2019-10-21T23:46:46.134Z,1571701606.134 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:46:46.134Z,1571701606.134 [Default:CheckIn](INFO): Running loop #9 2019-10-21T23:46:46.134Z,1571701606.134 [Default:CheckIn] Running Loop=9 2019-10-21T23:46:46.134Z,1571701606.134 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:46:46.134Z,1571701606.134 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:46:48.148Z,1571701608.148 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234615.00,A,3648.15320,N,12147.22029,W,0.039,359.31,211019,,,D*75 2019-10-21T23:46:48.150Z,1571701608.150 [NAL9602](INFO): GPS fix at 20191021T234615: (36.802553, -121.787005) 2019-10-21T23:46:48.196Z,1571701608.196 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:46:48.196Z,1571701608.196 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:46:57.012Z,1571701617.012 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191021T224728/Courier0031.lzma 2019-10-21T23:46:59.019Z,1571701619.019 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0031.lzma.bak 2019-10-21T23:46:59.019Z,1571701619.019 [DataOverHttps](INFO): SBD MOMSN=11934814 2019-10-21T23:47:08.763Z,1571701628.763 [NAL9602](INFO): SBD MO Status=2, MOMSN=16897, MT Status=2, MTMSN=0 2019-10-21T23:47:08.764Z,1571701628.764 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:47:15.948Z,1571701635.948 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191021T224728/Express0032.lzma 2019-10-21T23:47:17.954Z,1571701637.954 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0032.lzma.bak 2019-10-21T23:47:17.954Z,1571701637.954 [DataOverHttps](INFO): SBD MOMSN=11934868 2019-10-21T23:47:19.708Z,1571701639.708 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:47:19.708Z,1571701639.708 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:47:19.708Z,1571701639.708 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:48:24.727Z,1571701704.727 [NAL9602](INFO): SBD MO Status=0, MOMSN=16897, MT Status=0, MTMSN=0 2019-10-21T23:48:24.727Z,1571701704.727 [NAL9602](INFO): No messages in MT queue 2019-10-21T23:48:55.426Z,1571701735.426 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:50:01.006Z,1571701801.006 [DataOverHttps](IMPORTANT): SBD MTMSN=20191021T234926 2019-10-21T23:50:08.676Z,1571701808.676 [DataOverHttps](INFO): Received command:ibit 2019-10-21T23:50:08.733Z,1571701808.733 [CommandLine](IMPORTANT): got command ibit 2019-10-21T23:50:08.992Z,1571701808.992 [IBIT](IMPORTANT): Beginning Initiated BIT 2019-10-21T23:50:08.992Z,1571701808.992 [IBIT](IMPORTANT): Beginning control surface checks. 2019-10-21T23:50:08.995Z,1571701808.995 [CBIT](IMPORTANT): Beginning ground fault scan 2019-10-21T23:50:10.584Z,1571701810.584 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234937.00,A,3648.15272,N,12147.22001,W,0.058,359.31,211019,,,A*74 2019-10-21T23:50:10.586Z,1571701810.586 [NAL9602](INFO): GPS fix at 20191021T234937: (36.802545, -121.787000) 2019-10-21T23:50:19.921Z,1571701819.921 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.012426 CHAN A1 (24V): -0.180668 CHAN A2 (12V): -0.002050 CHAN A3 (5V): -0.001254 CHAN B0 (3.3V): -0.000283 CHAN B1 (3.15aV): -0.000075 CHAN B2 (3.15bV): -0.000205 CHAN B3 (GND): -0.000444 OPEN: -0.000359 Full Scale Calc: 4.765 mA, -1.589 mA 2019-10-21T23:50:24.327Z,1571701824.327 [NAL9602](INFO): SBD MO Status=0, MOMSN=16898, MT Status=0, MTMSN=0 2019-10-21T23:50:24.328Z,1571701824.328 [NAL9602](INFO): No messages in MT queue 2019-10-21T23:50:25.536Z,1571701825.536 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234952.00,A,3648.15268,N,12147.22013,W,0.058,359.31,211019,,,A*7F 2019-10-21T23:50:25.538Z,1571701825.538 [NAL9602](INFO): GPS fix at 20191021T234952: (36.802545, -121.787002) 2019-10-21T23:50:28.763Z,1571701828.763 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234955.00,A,3648.15260,N,12147.22013,W,0.078,359.31,211019,,,A*72 2019-10-21T23:50:28.766Z,1571701828.766 [NAL9602](INFO): GPS fix at 20191021T234955: (36.802543, -121.787002) 2019-10-21T23:50:31.589Z,1571701831.589 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234958.00,A,3648.15256,N,12147.22015,W,0.039,359.31,211019,,,A*79 2019-10-21T23:50:31.592Z,1571701831.592 [NAL9602](INFO): GPS fix at 20191021T234958: (36.802543, -121.787002) 2019-10-21T23:50:34.431Z,1571701834.431 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235001.00,A,3648.15263,N,12147.22017,W,0.039,359.31,211019,,,A*79 2019-10-21T23:50:34.433Z,1571701834.433 [NAL9602](INFO): GPS fix at 20191021T235001: (36.802544, -121.787003) 2019-10-21T23:50:37.652Z,1571701837.652 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235004.00,A,3648.15277,N,12147.22026,W,0.058,359.31,211019,,,A*7C 2019-10-21T23:50:37.654Z,1571701837.654 [NAL9602](INFO): GPS fix at 20191021T235004: (36.802546, -121.787004) 2019-10-21T23:50:40.478Z,1571701840.478 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235007.00,A,3648.15279,N,12147.22026,W,0.019,359.31,211019,,,A*74 2019-10-21T23:50:40.480Z,1571701840.480 [NAL9602](INFO): GPS fix at 20191021T235007: (36.802546, -121.787004) 2019-10-21T23:50:43.710Z,1571701843.710 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235010.00,A,3648.15278,N,12147.22023,W,0.058,359.31,211019,,,A*73 2019-10-21T23:50:43.712Z,1571701843.712 [NAL9602](INFO): GPS fix at 20191021T235010: (36.802546, -121.787004) 2019-10-21T23:50:46.548Z,1571701846.548 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235013.00,A,3648.15282,N,12147.22022,W,0.058,359.31,211019,,,A*74 2019-10-21T23:50:46.550Z,1571701846.550 [NAL9602](INFO): GPS fix at 20191021T235013: (36.802547, -121.787004) 2019-10-21T23:50:49.780Z,1571701849.780 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235016.00,A,3648.15284,N,12147.22018,W,0.039,359.31,211019,,,A*79 2019-10-21T23:50:49.782Z,1571701849.782 [NAL9602](INFO): GPS fix at 20191021T235016: (36.802547, -121.787003) 2019-10-21T23:50:52.601Z,1571701852.601 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235019.00,A,3648.15290,N,12147.22016,W,0.019,359.31,211019,,,A*7F 2019-10-21T23:50:52.603Z,1571701852.603 [NAL9602](INFO): GPS fix at 20191021T235019: (36.802548, -121.787003) 2019-10-21T23:50:55.085Z,1571701855.085 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 5 Latitude: 36.802547 Longitude: -121.787003 2019-10-21T23:50:55.427Z,1571701855.427 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235022.00,A,3648.15296,N,12147.22016,W,0.019,359.31,211019,,,A*71 2019-10-21T23:50:55.430Z,1571701855.430 [NAL9602](INFO): GPS fix at 20191021T235022: (36.802549, -121.787003) 2019-10-21T23:50:55.462Z,1571701855.462 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 0.000000 Voltage: 0.000000 2019-10-21T23:50:55.463Z,1571701855.463 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah 2019-10-21T23:50:55.463Z,1571701855.463 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V 2019-10-21T23:50:55.930Z,1571701855.930 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2019-10-21T23:50:55.930Z,1571701855.930 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2019-10-21T23:50:55.931Z,1571701855.931 [IBIT](IMPORTANT): Pressure:8.106343 PSI 2019-10-21T23:50:55.931Z,1571701855.931 [IBIT](IMPORTANT): Humidity:5.188622 % 2019-10-21T23:50:56.326Z,1571701856.326 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m 2019-10-21T23:50:56.326Z,1571701856.326 [IBIT](IMPORTANT): buoyancyNeutral: 315.000000 cc 2019-10-21T23:50:56.326Z,1571701856.326 [IBIT](IMPORTANT): massDefault: -1.000000 cm 2019-10-21T23:50:56.327Z,1571701856.327 [IBIT](IMPORTANT): stopDepth: 205.000000 m 2019-10-21T23:50:56.327Z,1571701856.327 [IBIT](IMPORTANT): abortDepth: 250.000000 m 2019-10-21T23:50:56.327Z,1571701856.327 [IBIT](IMPORTANT): IBIT PASSED 2019-10-21T23:51:28.151Z,1571701888.151 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:52:20.309Z,1571701940.309 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:52:20.309Z,1571701940.309 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:52:20.309Z,1571701940.309 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:52:20.309Z,1571701940.309 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:52:20.701Z,1571701940.701 [Default:CheckIn:D] Stopped 2019-10-21T23:52:20.701Z,1571701940.701 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 61.108252 min 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn:E] Stopped 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn] Stopped 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn](INFO): Running loop #10 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn] Running Loop=10 2019-10-21T23:52:21.105Z,1571701941.105 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:52:21.106Z,1571701941.106 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:52:23.103Z,1571701943.103 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235149.00,A,3648.15289,N,12147.22061,W,0.039,359.31,211019,,,A*71 2019-10-21T23:52:23.106Z,1571701943.106 [NAL9602](INFO): GPS fix at 20191021T235149: (36.802548, -121.787010) 2019-10-21T23:52:23.129Z,1571701943.129 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:52:23.129Z,1571701943.129 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:52:30.884Z,1571701950.884 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191021T224728/Courier0034.lzma 2019-10-21T23:52:32.890Z,1571701952.890 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0034.lzma.bak 2019-10-21T23:52:32.890Z,1571701952.890 [DataOverHttps](INFO): SBD MOMSN=11935271 2019-10-21T23:52:36.834Z,1571701956.834 [NAL9602](INFO): SBD MO Status=0, MOMSN=16899, MT Status=0, MTMSN=0 2019-10-21T23:52:36.834Z,1571701956.834 [NAL9602](INFO): No messages in MT queue 2019-10-21T23:53:02.180Z,1571701982.180 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191021T224728/Courier0037.lzma 2019-10-21T23:53:04.186Z,1571701984.186 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0037.lzma.bak 2019-10-21T23:53:04.186Z,1571701984.186 [DataOverHttps](INFO): SBD MOMSN=11935281 2019-10-21T23:53:07.558Z,1571701987.558 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:53:21.226Z,1571702001.226 [DataOverHttps](INFO): Sending 718 bytes from file Logs/20191021T224728/Express0035.lzma 2019-10-21T23:53:23.230Z,1571702003.230 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0035.lzma.bak 2019-10-21T23:53:23.230Z,1571702003.230 [DataOverHttps](INFO): SBD MOMSN=11935285 2019-10-21T23:53:40.032Z,1571702020.032 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191021T224728/Express0038.lzma 2019-10-21T23:53:42.038Z,1571702022.038 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0038.lzma.bak 2019-10-21T23:53:42.038Z,1571702022.038 [DataOverHttps](INFO): SBD MOMSN=11935348 2019-10-21T23:53:43.548Z,1571702023.548 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:53:43.548Z,1571702023.548 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:53:43.548Z,1571702023.548 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:56:06.827Z,1571702166.827 [CommandLine](IMPORTANT): got command ibit 2019-10-21T23:56:06.975Z,1571702166.975 [IBIT](IMPORTANT): Beginning Initiated BIT 2019-10-21T23:56:06.975Z,1571702166.975 [IBIT](IMPORTANT): Beginning control surface checks. 2019-10-21T23:56:06.978Z,1571702166.978 [CBIT](IMPORTANT): Beginning ground fault scan 2019-10-21T23:56:08.552Z,1571702168.552 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235534.00,A,3648.15157,N,12147.22111,W,0.019,359.31,211019,,,A*7B 2019-10-21T23:56:08.554Z,1571702168.554 [NAL9602](INFO): GPS fix at 20191021T235534: (36.802526, -121.787019) 2019-10-21T23:56:17.892Z,1571702177.892 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.012201 CHAN A1 (24V): -0.180087 CHAN A2 (12V): 4.697929 CHAN A3 (5V): -0.002027 CHAN B0 (3.3V): -0.000280 CHAN B1 (3.15aV): -0.000170 CHAN B2 (3.15bV): -0.000401 CHAN B3 (GND): -0.000354 OPEN: -0.000351 Full Scale Calc: 4.765 mA, -1.589 mA 2019-10-21T23:56:53.428Z,1571702213.428 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 4 Latitude: 36.802525 Longitude: -121.787018 2019-10-21T23:56:53.840Z,1571702213.840 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 284.580994 Voltage: 15.751500 2019-10-21T23:56:53.841Z,1571702213.841 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah 2019-10-21T23:56:53.841Z,1571702213.841 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V 2019-10-21T23:56:54.254Z,1571702214.254 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2019-10-21T23:56:54.254Z,1571702214.254 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2019-10-21T23:56:54.255Z,1571702214.255 [IBIT](IMPORTANT): Pressure:8.104965 PSI 2019-10-21T23:56:54.255Z,1571702214.255 [IBIT](IMPORTANT): Humidity:5.188622 % 2019-10-21T23:56:54.649Z,1571702214.649 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m 2019-10-21T23:56:54.650Z,1571702214.650 [IBIT](IMPORTANT): buoyancyNeutral: 315.000000 cc 2019-10-21T23:56:54.650Z,1571702214.650 [IBIT](IMPORTANT): massDefault: -1.000000 cm 2019-10-21T23:56:54.650Z,1571702214.650 [IBIT](IMPORTANT): stopDepth: 205.000000 m 2019-10-21T23:56:54.651Z,1571702214.651 [IBIT](IMPORTANT): abortDepth: 250.000000 m 2019-10-21T23:56:54.651Z,1571702214.651 [IBIT](IMPORTANT): IBIT PASSED 2019-10-21T23:57:09.970Z,1571702229.970 [NAL9602](INFO): SBD MO Status=2, MOMSN=16900, MT Status=2, MTMSN=0 2019-10-21T23:57:09.970Z,1571702229.970 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-21T23:57:20.867Z,1571702240.867 [NAL9602](INFO): SBD MO Status=0, MOMSN=16900, MT Status=0, MTMSN=0 2019-10-21T23:57:20.867Z,1571702240.867 [NAL9602](INFO): No messages in MT queue 2019-10-21T23:57:51.570Z,1571702271.570 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-21T23:58:44.121Z,1571702324.121 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-21T23:58:44.121Z,1571702324.121 [Default:CheckIn:C.Wait] Stopped 2019-10-21T23:58:44.121Z,1571702324.121 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-21T23:58:44.121Z,1571702324.121 [Default:CheckIn:D] Running Loop=1 2019-10-21T23:58:44.540Z,1571702324.540 [Default:CheckIn:D] Stopped 2019-10-21T23:58:44.540Z,1571702324.540 [Default:CheckIn:E] Running Loop=1 2019-10-21T23:58:44.945Z,1571702324.945 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 67.505570 min 2019-10-21T23:58:44.945Z,1571702324.945 [Default:CheckIn:E] Stopped 2019-10-21T23:58:44.945Z,1571702324.945 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-21T23:58:44.945Z,1571702324.945 [Default:CheckIn] Stopped 2019-10-21T23:58:44.945Z,1571702324.945 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-21T23:58:44.945Z,1571702324.945 [Default:CheckIn](INFO): Running loop #11 2019-10-21T23:58:44.946Z,1571702324.946 [Default:CheckIn] Running Loop=11 2019-10-21T23:58:44.946Z,1571702324.946 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-21T23:58:44.946Z,1571702324.946 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-21T23:58:46.924Z,1571702326.924 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235812.00,A,3648.15126,N,12147.22026,W,0.039,359.31,211019,,,A*73 2019-10-21T23:58:46.926Z,1571702326.926 [NAL9602](INFO): GPS fix at 20191021T235812: (36.802521, -121.787004) 2019-10-21T23:58:46.950Z,1571702326.950 [Default:CheckIn:Read_GPS] Stopped 2019-10-21T23:58:46.950Z,1571702326.950 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-21T23:58:54.536Z,1571702334.536 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191021T224728/Courier0040.lzma 2019-10-21T23:58:56.542Z,1571702336.542 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0040.lzma.bak 2019-10-21T23:58:56.543Z,1571702336.543 [DataOverHttps](INFO): SBD MOMSN=11935657 2019-10-21T23:59:11.967Z,1571702351.967 [NAL9602](INFO): SBD MO Status=0, MOMSN=16901, MT Status=0, MTMSN=0 2019-10-21T23:59:11.967Z,1571702351.967 [NAL9602](INFO): No messages in MT queue 2019-10-21T23:59:13.542Z,1571702353.542 [DataOverHttps](INFO): Sending 686 bytes from file Logs/20191021T224728/Express0041.lzma 2019-10-21T23:59:15.546Z,1571702355.546 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0041.lzma.bak 2019-10-21T23:59:15.546Z,1571702355.546 [DataOverHttps](INFO): SBD MOMSN=11935673 2019-10-21T23:59:17.259Z,1571702357.259 [Default:CheckIn:Read_Iridium] Stopped 2019-10-21T23:59:17.259Z,1571702357.259 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-21T23:59:17.259Z,1571702357.259 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-21T23:59:42.667Z,1571702382.667 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-22T00:00:28.340Z,1571702428.340 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2019-10-22T00:01:08.769Z,1571702468.769 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2019-10-22T00:02:54.612Z,1571702574.612 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-10-22T00:02:54.614Z,1571702574.614 [BPC1](INFO): Received data from all battery sticks. 2019-10-22T00:04:17.879Z,1571702657.879 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-22T00:04:17.879Z,1571702657.879 [Default:CheckIn:C.Wait] Stopped 2019-10-22T00:04:17.879Z,1571702657.879 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-22T00:04:17.879Z,1571702657.879 [Default:CheckIn:D] Running Loop=1 2019-10-22T00:04:18.274Z,1571702658.274 [Default:CheckIn:D] Stopped 2019-10-22T00:04:18.274Z,1571702658.274 [Default:CheckIn:E] Running Loop=1 2019-10-22T00:04:18.681Z,1571702658.681 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 73.067798 min 2019-10-22T00:04:18.681Z,1571702658.681 [Default:CheckIn:E] Stopped 2019-10-22T00:04:18.682Z,1571702658.682 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-22T00:04:18.682Z,1571702658.682 [Default:CheckIn] Stopped 2019-10-22T00:04:18.682Z,1571702658.682 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-22T00:04:18.682Z,1571702658.682 [Default:CheckIn](INFO): Running loop #12 2019-10-22T00:04:18.682Z,1571702658.682 [Default:CheckIn] Running Loop=12 2019-10-22T00:04:18.682Z,1571702658.682 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-22T00:04:18.682Z,1571702658.682 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-22T00:04:20.676Z,1571702660.676 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000346.00,A,3648.15216,N,12147.22120,W,0.039,359.31,221019,,,A*79 2019-10-22T00:04:20.678Z,1571702660.678 [NAL9602](INFO): GPS fix at 20191022T000346: (36.802536, -121.787020) 2019-10-22T00:04:20.728Z,1571702660.728 [Default:CheckIn:Read_GPS] Stopped 2019-10-22T00:04:20.728Z,1571702660.728 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-22T00:04:27.876Z,1571702667.876 [DataOverHttps](INFO): Sending 80 bytes from file Logs/20191021T224728/Courier0043.lzma 2019-10-22T00:04:29.882Z,1571702669.882 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0043.lzma.bak 2019-10-22T00:04:29.882Z,1571702669.882 [DataOverHttps](INFO): SBD MOMSN=11935901 2019-10-22T00:04:46.857Z,1571702686.857 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191021T224728/Express0044.lzma 2019-10-22T00:04:48.862Z,1571702688.862 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0044.lzma.bak 2019-10-22T00:04:48.863Z,1571702688.863 [DataOverHttps](INFO): SBD MOMSN=11935924 2019-10-22T00:04:50.613Z,1571702690.613 [Default:CheckIn:Read_Iridium] Stopped 2019-10-22T00:04:50.613Z,1571702690.613 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-22T00:04:50.613Z,1571702690.613 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-22T00:05:54.012Z,1571702754.012 [NAL9602](INFO): SBD MO Status=0, MOMSN=16902, MT Status=0, MTMSN=0 2019-10-22T00:05:54.012Z,1571702754.012 [NAL9602](INFO): No messages in MT queue 2019-10-22T00:06:24.714Z,1571702784.714 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-22T00:09:51.245Z,1571702991.245 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-22T00:09:51.245Z,1571702991.245 [Default:CheckIn:C.Wait] Stopped 2019-10-22T00:09:51.245Z,1571702991.245 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-22T00:09:51.245Z,1571702991.245 [Default:CheckIn:D] Running Loop=1 2019-10-22T00:09:51.648Z,1571702991.648 [Default:CheckIn:D] Stopped 2019-10-22T00:09:51.648Z,1571702991.648 [Default:CheckIn:E] Running Loop=1 2019-10-22T00:09:52.039Z,1571702992.039 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 78.624032 min 2019-10-22T00:09:52.039Z,1571702992.039 [Default:CheckIn:E] Stopped 2019-10-22T00:09:52.039Z,1571702992.039 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-22T00:09:52.039Z,1571702992.039 [Default:CheckIn] Stopped 2019-10-22T00:09:52.039Z,1571702992.039 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-22T00:09:52.039Z,1571702992.039 [Default:CheckIn](INFO): Running loop #13 2019-10-22T00:09:52.040Z,1571702992.040 [Default:CheckIn] Running Loop=13 2019-10-22T00:09:52.040Z,1571702992.040 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-22T00:09:52.040Z,1571702992.040 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-22T00:09:54.042Z,1571702994.042 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000918.00,A,3648.15341,N,12147.22230,W,0.019,359.31,221019,,,A*7B 2019-10-22T00:09:54.044Z,1571702994.044 [NAL9602](INFO): GPS fix at 20191022T000918: (36.802557, -121.787038) 2019-10-22T00:09:54.073Z,1571702994.073 [Default:CheckIn:Read_GPS] Stopped 2019-10-22T00:09:54.073Z,1571702994.073 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-22T00:10:03.727Z,1571703003.727 [NAL9602](INFO): SBD MO Status=0, MOMSN=16903, MT Status=0, MTMSN=0 2019-10-22T00:10:03.727Z,1571703003.727 [NAL9602](INFO): No messages in MT queue 2019-10-22T00:10:21.044Z,1571703021.044 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191021T224728/Courier0046.lzma 2019-10-22T00:10:23.051Z,1571703023.051 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Courier0046.lzma.bak 2019-10-22T00:10:23.051Z,1571703023.051 [DataOverHttps](INFO): SBD MOMSN=11936645 2019-10-22T00:10:34.426Z,1571703034.426 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-22T00:10:40.140Z,1571703040.140 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20191021T224728/Express0047.lzma 2019-10-22T00:10:42.146Z,1571703042.146 [DataOverHttps](INFO): Moved sent file to Logs/20191021T224728/Express0047.lzma.bak 2019-10-22T00:10:42.147Z,1571703042.147 [DataOverHttps](INFO): SBD MOMSN=11936751 2019-10-22T00:10:43.745Z,1571703043.745 [Default:CheckIn:Read_Iridium] Stopped 2019-10-22T00:10:43.745Z,1571703043.745 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-22T00:10:43.745Z,1571703043.745 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-22T00:13:24.582Z,1571703204.582 [DataOverHttps](IMPORTANT): SBD MTMSN=20191022T001247 2019-10-22T00:13:32.212Z,1571703212.212 [DataOverHttps](INFO): Received command:restart app 2019-10-22T00:13:32.249Z,1571703212.249 [CommandLine](IMPORTANT): got command restart application 2019-10-22T00:13:33.253Z,1571703213.253 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2019-10-22T00:13:33.253Z,1571703213.253 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:33.253Z,1571703213.253 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:33.329Z,1571703213.329 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-10-22T00:13:33.329Z,1571703213.329 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:33.329Z,1571703213.329 [CommandLine](INFO): Join timeout helper Thread ID is 1208 2019-10-22T00:13:33.330Z,1571703213.330 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-10-22T00:13:33.330Z,1571703213.330 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:33.331Z,1571703213.331 [NavChartDb](INFO): Join timeout helper Thread ID is 1209 2019-10-22T00:13:33.345Z,1571703213.345 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:33.345Z,1571703213.345 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:33.349Z,1571703213.349 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-10-22T00:13:33.349Z,1571703213.349 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:33.349Z,1571703213.349 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1210 2019-10-22T00:13:33.553Z,1571703213.553 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:33.553Z,1571703213.553 [WetLabsBB2FL](INFO): Powering down 2019-10-22T00:13:33.554Z,1571703213.554 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:33.557Z,1571703213.557 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-10-22T00:13:33.557Z,1571703213.557 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:33.557Z,1571703213.557 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1211 2019-10-22T00:13:33.977Z,1571703213.977 [CTD_Seabird](INFO): Powering down 2019-10-22T00:13:33.989Z,1571703213.989 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:33.989Z,1571703213.989 [CTD_Seabird](INFO): Powering down 2019-10-22T00:13:34.001Z,1571703214.001 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.005Z,1571703214.005 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-10-22T00:13:34.005Z,1571703214.005 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.005Z,1571703214.005 [Radio_Surface](INFO): Join timeout helper Thread ID is 1212 2019-10-22T00:13:34.073Z,1571703214.073 [Radio_Surface](INFO): Powering down 2019-10-22T00:13:34.074Z,1571703214.074 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:34.074Z,1571703214.074 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.086Z,1571703214.086 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-10-22T00:13:34.086Z,1571703214.086 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.086Z,1571703214.086 [DataOverHttps](INFO): Join timeout helper Thread ID is 1213 2019-10-22T00:13:34.217Z,1571703214.217 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:34.221Z,1571703214.221 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.227Z,1571703214.227 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-10-22T00:13:34.227Z,1571703214.227 [logger ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.228Z,1571703214.228 [logger](INFO): Join timeout helper Thread ID is 1214 2019-10-22T00:13:34.261Z,1571703214.261 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:34.262Z,1571703214.262 [logger ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.266Z,1571703214.266 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-10-22T00:13:34.266Z,1571703214.266 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.266Z,1571703214.266 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-10-22T00:13:34.266Z,1571703214.266 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.266Z,1571703214.266 [controlThread](INFO): Join timeout helper Thread ID is 1215 2019-10-22T00:13:34.269Z,1571703214.269 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-22T00:13:34.270Z,1571703214.270 [controlThread](DEBUG): Uninitializing ControlThread 2019-10-22T00:13:34.270Z,1571703214.270 [AHRS_M2](INFO): Powering down 2019-10-22T00:13:34.341Z,1571703214.341 [NAL9602](INFO): Powering down 2019-10-22T00:13:34.343Z,1571703214.343 [Aanderaa_O2](INFO): Powering down 2019-10-22T00:13:34.345Z,1571703214.345 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-10-22T00:13:34.346Z,1571703214.346 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-10-22T00:13:34.346Z,1571703214.346 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-10-22T00:13:34.347Z,1571703214.347 [MissionManager](INFO): Uninitializing Mission Default 2019-10-22T00:13:34.347Z,1571703214.347 [Default] Stopped 2019-10-22T00:13:34.347Z,1571703214.347 [Default](DEBUG): Aggregate::uninitialize Default 2019-10-22T00:13:34.347Z,1571703214.347 [Default:B.GoToSurface] Stopped 2019-10-22T00:13:34.347Z,1571703214.347 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-10-22T00:13:34.347Z,1571703214.347 [Default:CheckIn] Stopped 2019-10-22T00:13:34.347Z,1571703214.347 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-22T00:13:34.347Z,1571703214.347 [Default:CheckIn:C.Wait] Stopped 2019-10-22T00:13:34.347Z,1571703214.347 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-22T00:13:34.350Z,1571703214.350 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-10-22T00:13:34.350Z,1571703214.350 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-10-22T00:13:34.351Z,1571703214.351 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-10-22T00:13:34.351Z,1571703214.351 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-10-22T00:13:34.351Z,1571703214.351 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-10-22T00:13:34.351Z,1571703214.351 [BuoyancyServo](INFO): Powering down 2019-10-22T00:13:34.365Z,1571703214.365 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-10-22T00:13:34.365Z,1571703214.365 [ElevatorServo](INFO): Powering down 2019-10-22T00:13:34.366Z,1571703214.366 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-10-22T00:13:34.366Z,1571703214.366 [MassServo](INFO): Powering down 2019-10-22T00:13:34.367Z,1571703214.367 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-10-22T00:13:34.367Z,1571703214.367 [RudderServo](INFO): Powering down 2019-10-22T00:13:34.367Z,1571703214.367 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-10-22T00:13:34.368Z,1571703214.368 [ThrusterServo](INFO): Powering down 2019-10-22T00:13:34.368Z,1571703214.368 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-10-22T00:13:34.369Z,1571703214.369 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-10-22T00:13:34.369Z,1571703214.369 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-10-22T00:13:34.369Z,1571703214.369 [CBIT](DEBUG): Powering off loads. 2019-10-22T00:13:34.381Z,1571703214.381 [CBIT](DEBUG): Disabling WDT. 2019-10-22T00:13:34.393Z,1571703214.393 [CBIT](DEBUG): Opening all GF detection circuits. 2019-10-22T00:13:34.394Z,1571703214.394 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.479Z,1571703214.479 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.485Z,1571703214.485 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.514Z,1571703214.514 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.516Z,1571703214.516 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.551Z,1571703214.551 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-10-22T00:13:34.608Z,1571703214.608 [logger ThreadHandler](INFO): Thread cancelled.