2019-11-18T22:52:56.886Z,1574117576.886 [Supervisor](DEBUG): Initializing supervisor. 2019-11-18T22:52:56.889Z,1574117576.889 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-11-18T22:52:56.889Z,1574117576.889 [SyncHandler](INFO): Protected caller Thread ID is 5632 2019-11-18T22:52:56.890Z,1574117576.890 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-11-18T22:52:56.891Z,1574117576.891 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-11-18T22:52:56.891Z,1574117576.891 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5633 2019-11-18T22:52:56.894Z,1574117576.894 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-11-18T22:52:56.906Z,1574117576.906 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-11-18T22:52:56.907Z,1574117576.907 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-11-18T22:52:56.907Z,1574117576.907 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5634 2019-11-18T22:52:56.908Z,1574117576.908 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-11-18T22:52:56.909Z,1574117576.909 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-11-18T22:52:56.909Z,1574117576.909 [logger ThreadHandler](INFO): Protected caller Thread ID is 5635 2019-11-18T22:52:56.911Z,1574117576.911 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-11-18T22:52:56.911Z,1574117576.911 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-11-18T22:52:56.943Z,1574117576.943 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-11-18T22:52:57.374Z,1574117577.374 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-11-18T22:52:57.375Z,1574117577.375 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-11-18T22:52:57.471Z,1574117577.471 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-11-18T22:52:57.472Z,1574117577.472 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-11-18T22:52:57.785Z,1574117577.785 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-11-18T22:52:57.786Z,1574117577.786 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-11-18T22:52:57.956Z,1574117577.956 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-11-18T22:52:57.956Z,1574117577.956 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-11-18T22:52:58.187Z,1574117578.187 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-11-18T22:52:58.188Z,1574117578.188 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-11-18T22:52:58.634Z,1574117578.634 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-11-18T22:52:58.635Z,1574117578.635 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-11-18T22:52:58.838Z,1574117578.838 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-11-18T22:52:58.839Z,1574117578.839 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-11-18T22:52:58.981Z,1574117578.981 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-11-18T22:52:58.981Z,1574117578.981 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-11-18T22:52:59.168Z,1574117579.168 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-11-18T22:52:59.169Z,1574117579.169 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-11-18T22:52:59.263Z,1574117579.263 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-11-18T22:52:59.264Z,1574117579.264 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-11-18T22:52:59.560Z,1574117579.560 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-11-18T22:52:59.561Z,1574117579.561 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-11-18T22:52:59.640Z,1574117579.640 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-11-18T22:52:59.740Z,1574117579.740 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-11-18T22:52:59.741Z,1574117579.741 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-11-18T22:53:00.386Z,1574117580.386 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-11-18T22:53:00.387Z,1574117580.387 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-11-18T22:53:00.790Z,1574117580.790 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-11-18T22:53:00.792Z,1574117580.792 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/ 2019-11-18T22:53:00.793Z,1574117580.793 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg 2019-11-18T22:53:00.996Z,1574117580.996 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg 2019-11-18T22:53:01.092Z,1574117581.092 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg 2019-11-18T22:53:01.188Z,1574117581.188 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg 2019-11-18T22:53:01.416Z,1574117581.416 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-11-18T22:53:01.416Z,1574117581.416 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg 2019-11-18T22:53:01.499Z,1574117581.499 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg 2019-11-18T22:53:01.590Z,1574117581.590 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg 2019-11-18T22:53:01.685Z,1574117581.685 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg 2019-11-18T22:53:01.766Z,1574117581.766 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg 2019-11-18T22:53:01.912Z,1574117581.912 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg 2019-11-18T22:53:02.260Z,1574117582.260 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg 2019-11-18T22:53:02.506Z,1574117582.506 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/ 2019-11-18T22:53:02.507Z,1574117582.507 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-11-18T22:53:02.523Z,1574117582.523 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-11-18T22:53:03.117Z,1574117583.117 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2019-11-18T22:53:03.123Z,1574117583.123 [AHRS_M2](INFO): created writer for : platform_orientation 2019-11-18T22:53:03.125Z,1574117583.125 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2019-11-18T22:53:03.130Z,1574117583.130 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2019-11-18T22:53:03.131Z,1574117583.131 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2019-11-18T22:53:03.136Z,1574117583.136 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2019-11-18T22:53:03.137Z,1574117583.137 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2019-11-18T22:53:03.142Z,1574117583.142 [AHRS_M2](INFO): created writer for : platform_roll_angle 2019-11-18T22:53:03.215Z,1574117583.215 [AHRS_M2] Loaded 2019-11-18T22:53:03.216Z,1574117583.216 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-11-18T22:53:03.294Z,1574117583.294 [DataOverHttps] Loaded 2019-11-18T22:53:03.294Z,1574117583.294 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-11-18T22:53:03.295Z,1574117583.295 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407684E0 2019-11-18T22:53:03.295Z,1574117583.295 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5715 2019-11-18T22:53:03.315Z,1574117583.315 [DDM] Loaded 2019-11-18T22:53:03.316Z,1574117583.316 [ComponentRegistry](DEBUG): SyncComponent "DDM" handled in the control thread. 2019-11-18T22:53:03.329Z,1574117583.329 [Depth_Keller] Loaded 2019-11-18T22:53:03.330Z,1574117583.330 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-11-18T22:53:03.335Z,1574117583.335 [DropWeight] Loaded 2019-11-18T22:53:03.335Z,1574117583.335 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-11-18T22:53:03.398Z,1574117583.398 [DUSBL_Hydroid] Loaded 2019-11-18T22:53:03.399Z,1574117583.399 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread. 2019-11-18T22:53:03.447Z,1574117583.447 [Micromodem] Loaded 2019-11-18T22:53:03.447Z,1574117583.447 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2019-11-18T22:53:03.548Z,1574117583.548 [NAL9602] Loaded 2019-11-18T22:53:03.549Z,1574117583.549 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-11-18T22:53:03.565Z,1574117583.565 [Onboard] Loaded 2019-11-18T22:53:03.565Z,1574117583.565 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-11-18T22:53:03.571Z,1574117583.571 [PowerOnly] Loaded 2019-11-18T22:53:03.571Z,1574117583.571 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2019-11-18T22:53:03.578Z,1574117583.578 [Radio_Surface] Loaded 2019-11-18T22:53:03.578Z,1574117583.578 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-11-18T22:53:03.579Z,1574117583.579 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407984E0 2019-11-18T22:53:03.579Z,1574117583.579 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5716 2019-11-18T22:53:03.625Z,1574117583.625 [RDI_Pathfinder] Loaded 2019-11-18T22:53:03.625Z,1574117583.625 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2019-11-18T22:53:05.170Z,1574117585.170 [BPC1] Loaded 2019-11-18T22:53:05.170Z,1574117585.170 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-11-18T22:53:05.171Z,1574117585.171 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-11-18T22:53:05.171Z,1574117585.171 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-11-18T22:53:05.185Z,1574117585.185 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-11-18T22:53:05.186Z,1574117585.186 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-11-18T22:53:05.293Z,1574117585.293 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-11-18T22:53:05.293Z,1574117585.293 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-11-18T22:53:05.314Z,1574117585.314 [NavChart] Loaded 2019-11-18T22:53:05.314Z,1574117585.314 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-11-18T22:53:05.318Z,1574117585.318 [UniversalFixResidualReporter] Loaded 2019-11-18T22:53:05.318Z,1574117585.318 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-11-18T22:53:05.319Z,1574117585.319 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-11-18T22:53:05.319Z,1574117585.319 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-11-18T22:53:05.433Z,1574117585.433 [BuoyancyServo] Loaded 2019-11-18T22:53:05.434Z,1574117585.434 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-11-18T22:53:05.449Z,1574117585.449 [ElevatorServo] Loaded 2019-11-18T22:53:05.450Z,1574117585.450 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-11-18T22:53:05.465Z,1574117585.465 [MassServo] Loaded 2019-11-18T22:53:05.465Z,1574117585.465 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-11-18T22:53:05.480Z,1574117585.480 [RudderServo] Loaded 2019-11-18T22:53:05.480Z,1574117585.480 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-11-18T22:53:05.495Z,1574117585.495 [ThrusterServo] Loaded 2019-11-18T22:53:05.495Z,1574117585.495 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-11-18T22:53:05.495Z,1574117585.495 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-11-18T22:53:05.496Z,1574117585.496 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-11-18T22:53:05.758Z,1574117585.758 [CTD_NeilBrown] Loaded 2019-11-18T22:53:05.758Z,1574117585.758 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-11-18T22:53:05.759Z,1574117585.759 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E34E0 2019-11-18T22:53:05.760Z,1574117585.760 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5717 2019-11-18T22:53:05.775Z,1574117585.775 [PAR_Licor] Loaded 2019-11-18T22:53:05.775Z,1574117585.775 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-11-18T22:53:05.820Z,1574117585.820 [WetLabsSeaOWL_UV_A] Loaded 2019-11-18T22:53:05.820Z,1574117585.820 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2019-11-18T22:53:05.821Z,1574117585.821 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409134E0 2019-11-18T22:53:05.821Z,1574117585.821 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 5718 2019-11-18T22:53:05.822Z,1574117585.822 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-11-18T22:53:05.822Z,1574117585.822 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-11-18T22:53:06.156Z,1574117586.156 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-11-18T22:53:06.157Z,1574117586.157 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-11-18T22:53:06.199Z,1574117586.199 [DepthRateCalculator] Loaded 2019-11-18T22:53:06.200Z,1574117586.200 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-11-18T22:53:06.205Z,1574117586.205 [PitchRateCalculator] Loaded 2019-11-18T22:53:06.206Z,1574117586.206 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-11-18T22:53:06.218Z,1574117586.218 [SpeedCalculator] Loaded 2019-11-18T22:53:06.218Z,1574117586.218 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-11-18T22:53:06.239Z,1574117586.239 [TempGradientCalculator] Loaded 2019-11-18T22:53:06.239Z,1574117586.239 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-11-18T22:53:06.245Z,1574117586.245 [YawRateCalculator] Loaded 2019-11-18T22:53:06.245Z,1574117586.245 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-11-18T22:53:06.286Z,1574117586.286 [ElevatorOffsetCalculator] Loaded 2019-11-18T22:53:06.286Z,1574117586.286 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-11-18T22:53:06.286Z,1574117586.286 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-11-18T22:53:06.287Z,1574117586.287 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-11-18T22:53:06.435Z,1574117586.435 [SBIT](DEBUG): Construct Startup Built In Test. 2019-11-18T22:53:06.457Z,1574117586.457 [SBIT] Loaded 2019-11-18T22:53:06.458Z,1574117586.458 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-11-18T22:53:06.458Z,1574117586.458 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-11-18T22:53:06.470Z,1574117586.470 [IBIT] Loaded 2019-11-18T22:53:06.471Z,1574117586.471 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-11-18T22:53:06.474Z,1574117586.474 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-11-18T22:53:06.612Z,1574117586.612 [CBIT] Loaded 2019-11-18T22:53:06.612Z,1574117586.612 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-11-18T22:53:06.612Z,1574117586.612 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-11-18T22:53:06.613Z,1574117586.613 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-11-18T22:53:06.702Z,1574117586.702 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-11-18T22:53:06.703Z,1574117586.703 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-11-18T22:53:06.811Z,1574117586.811 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-11-18T22:53:06.811Z,1574117586.811 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-11-18T22:53:06.883Z,1574117586.883 [VerticalControl](DEBUG): Construct VerticalControl. 2019-11-18T22:53:06.966Z,1574117586.966 [VerticalControl] Loaded 2019-11-18T22:53:06.967Z,1574117586.967 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-11-18T22:53:06.967Z,1574117586.967 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-11-18T22:53:07.025Z,1574117587.025 [HorizontalControl] Loaded 2019-11-18T22:53:07.025Z,1574117587.025 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-11-18T22:53:07.026Z,1574117587.026 [SpeedControl](DEBUG): Construct SpeedControl. 2019-11-18T22:53:07.028Z,1574117587.028 [SpeedControl] Loaded 2019-11-18T22:53:07.028Z,1574117587.028 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-11-18T22:53:07.029Z,1574117587.029 [LoopControl](DEBUG): Construct LoopControl. 2019-11-18T22:53:07.029Z,1574117587.029 [LoopControl] Loaded 2019-11-18T22:53:07.030Z,1574117587.030 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-11-18T22:53:07.030Z,1574117587.030 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-11-18T22:53:07.031Z,1574117587.031 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-11-18T22:53:07.092Z,1574117587.092 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-11-18T22:53:07.095Z,1574117587.095 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-11-18T22:53:07.096Z,1574117587.096 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-11-18T22:53:07.102Z,1574117587.102 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-11-18T22:53:07.104Z,1574117587.104 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AF74E0 2019-11-18T22:53:07.104Z,1574117587.104 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5719 2019-11-18T22:53:07.108Z,1574117587.108 [Supervisor](INFO): Main Thread ID is 5631 2019-11-18T22:53:07.108Z,1574117587.108 [Supervisor](DEBUG): Running supervisor. 2019-11-18T22:53:07.109Z,1574117587.109 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5720 2019-11-18T22:53:07.112Z,1574117587.112 [controlThread ThreadHandler](INFO): Handler Thread ID is 5721 2019-11-18T22:53:07.112Z,1574117587.112 [controlThread](DEBUG): Initializing ControlThread 2019-11-18T22:53:07.118Z,1574117587.118 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-11-18T22:53:07.119Z,1574117587.119 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-11-18T22:53:07.123Z,1574117587.123 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-11-18T22:53:07.124Z,1574117587.124 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-11-18T22:53:07.124Z,1574117587.124 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-11-18T22:53:07.124Z,1574117587.124 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-11-18T22:53:07.125Z,1574117587.125 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-11-18T22:53:07.125Z,1574117587.125 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-11-18T22:53:07.126Z,1574117587.126 [SBIT](INFO): Initialize SBIT Component. 2019-11-18T22:53:07.126Z,1574117587.126 [SBIT](IMPORTANT): git: 2019-11-13-3-ge29a3b2 2019-11-18T22:53:07.126Z,1574117587.126 [SBIT](INFO): git hash: e29a3b2fb0608240c94b4b893f361a3ce971c194 2019-11-18T22:53:07.127Z,1574117587.127 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-11-18T22:53:07.128Z,1574117587.128 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #2 PREEMPT Wed May 15 08:34:03 PDT 2019 2019-11-18T22:53:07.129Z,1574117587.129 [SBIT](INFO): Beginning SBIT in 34.000000 seconds. 2019-11-18T22:53:07.130Z,1574117587.130 [IBIT](INFO): Initialize IBIT Component. 2019-11-18T22:53:07.130Z,1574117587.130 [CBIT](DEBUG): Initialize CBIT Component. 2019-11-18T22:53:07.131Z,1574117587.131 [logger ThreadHandler](INFO): Handler Thread ID is 5722 2019-11-18T22:53:07.143Z,1574117587.143 [CBIT](DEBUG): Initialized mux pins. 2019-11-18T22:53:07.143Z,1574117587.143 [CBIT](DEBUG): Initializing the watchdog timer. 2019-11-18T22:53:07.151Z,1574117587.151 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5723 2019-11-18T22:53:07.152Z,1574117587.152 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-11-18T22:53:07.163Z,1574117587.163 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5724 2019-11-18T22:53:07.167Z,1574117587.167 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-11-18T22:53:07.167Z,1574117587.167 [CBIT](DEBUG): Initializing heartbeat. 2019-11-18T22:53:07.175Z,1574117587.175 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5725 2019-11-18T22:53:07.176Z,1574117587.176 [CTD_NeilBrown](INFO): Powering down 2019-11-18T22:53:07.204Z,1574117587.204 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 5726 2019-11-18T22:53:07.204Z,1574117587.204 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-11-18T22:53:07.231Z,1574117587.231 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5727 2019-11-18T22:53:07.234Z,1574117587.234 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-11-18T22:53:07.235Z,1574117587.235 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-11-18T22:53:07.235Z,1574117587.235 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-11-18T22:53:07.235Z,1574117587.235 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-11-18T22:53:07.235Z,1574117587.235 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-11-18T22:53:07.236Z,1574117587.236 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-11-18T22:53:07.236Z,1574117587.236 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-11-18T22:53:07.236Z,1574117587.236 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-11-18T22:53:07.236Z,1574117587.236 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-11-18T22:53:07.236Z,1574117587.236 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-11-18T22:53:07.236Z,1574117587.236 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-11-18T22:53:07.237Z,1574117587.237 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-11-18T22:53:07.237Z,1574117587.237 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-11-18T22:53:07.237Z,1574117587.237 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-11-18T22:53:07.237Z,1574117587.237 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-11-18T22:53:07.237Z,1574117587.237 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-11-18T22:53:07.239Z,1574117587.239 [CBIT](DEBUG): Deactivating GF circuits. 2019-11-18T22:53:07.239Z,1574117587.239 [CBIT](DEBUG): Deactivating emergency mode. 2019-11-18T22:53:07.275Z,1574117587.275 [CBIT](DEBUG): Backplane powered. 2019-11-18T22:53:07.276Z,1574117587.276 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-11-18T22:53:07.277Z,1574117587.277 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-11-18T22:53:07.278Z,1574117587.278 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-11-18T22:53:07.278Z,1574117587.278 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-11-18T22:53:07.279Z,1574117587.279 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-11-18T22:53:07.289Z,1574117587.289 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-11-18T22:53:07.300Z,1574117587.300 [MissionManager](DEBUG): 2019-11-18T22:53:07.301Z,1574117587.301 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-11-18T22:53:07.368Z,1574117587.368 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-11-18T22:53:07.369Z,1574117587.369 [Default:A.Wait](DEBUG): Construct Wait. 2019-11-18T22:53:07.387Z,1574117587.387 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-11-18T22:53:07.414Z,1574117587.414 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-11-18T22:53:07.416Z,1574117587.416 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-11-18T22:53:07.438Z,1574117587.438 [Default:E.Execute](DEBUG): Construct Execute. 2019-11-18T22:53:07.441Z,1574117587.441 [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-11-18T22:53:07.457Z,1574117587.457 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,DDM,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-11-18T22:53:07.477Z,1574117587.477 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-11-18T22:53:07.514Z,1574117587.514 [DDM](INFO): Powering up 2019-11-18T22:53:07.514Z,1574117587.514 [DDM](DEBUG): Initializing DDM. 2019-11-18T22:53:07.541Z,1574117587.541 [DUSBL_Hydroid](INFO): Powering up 2019-11-18T22:53:07.542Z,1574117587.542 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid. 2019-11-18T22:53:07.568Z,1574117587.568 [Radio_Surface](INFO): Powering up 2019-11-18T22:53:07.737Z,1574117587.737 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-11-18T22:53:07.743Z,1574117587.743 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-11-18T22:53:07.744Z,1574117587.744 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-11-18T22:53:07.751Z,1574117587.751 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-11-18T22:53:07.752Z,1574117587.752 [MassServo](DEBUG): Initializing EZServoServo. 2019-11-18T22:53:07.759Z,1574117587.759 [MassServo](DEBUG): Initializing MassServo. 2019-11-18T22:53:07.760Z,1574117587.760 [RudderServo](DEBUG): Initializing EZServoServo. 2019-11-18T22:53:07.771Z,1574117587.771 [RudderServo](DEBUG): Initializing RudderServo. 2019-11-18T22:53:07.772Z,1574117587.772 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-11-18T22:53:07.779Z,1574117587.779 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-11-18T22:53:07.882Z,1574117587.882 [Micromodem](INFO): Powering up 2019-11-18T22:53:07.882Z,1574117587.882 [Micromodem](DEBUG): Initializing Micromodem. 2019-11-18T22:53:08.631Z,1574117588.631 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-11-18T22:53:08.631Z,1574117588.631 [RudderServo](FAULT): Rudder failed to initialize 2019-11-18T22:53:08.631Z,1574117588.631 [RudderServo] Communications Fault, FailCount= 1 2019-11-18T22:53:08.631Z,1574117588.631 [RudderServo](ERROR): Communications Fault 2019-11-18T22:53:08.742Z,1574117588.742 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-11-18T22:53:08.956Z,1574117588.956 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-11-18T22:53:08.956Z,1574117588.956 [RudderServo](INFO): Powering down 2019-11-18T22:53:09.619Z,1574117589.619 [RudderServo](DEBUG): Initializing EZServoServo. 2019-11-18T22:53:09.752Z,1574117589.752 [RudderServo](DEBUG): Initializing RudderServo. 2019-11-18T22:53:09.756Z,1574117589.756 [CBIT](INFO): Clearing failed state for component RudderServo 2019-11-18T22:53:09.756Z,1574117589.756 [RudderServo] No Fault, FailCount= 1 2019-11-18T22:53:12.835Z,1574117592.835 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33 2019-11-18T22:53:13.238Z,1574117593.238 [Micromodem](INFO): Nmea in: $CATMG,2019-11-18T22:53:11.905012Z,RTC,RTC*5A 2019-11-18T22:53:13.238Z,1574117593.238 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-11-18T22:53:11.905012Z,RTC,RTC*5A 2019-11-18T22:53:13.641Z,1574117593.641 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31 2019-11-18T22:53:13.642Z,1574117593.642 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31 2019-11-18T22:53:14.053Z,1574117594.053 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33 2019-11-18T22:53:14.053Z,1574117594.053 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64 2019-11-18T22:53:14.454Z,1574117594.454 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66 2019-11-18T22:53:14.454Z,1574117594.454 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F 2019-11-18T22:53:14.854Z,1574117594.854 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D 2019-11-18T22:53:14.854Z,1574117594.854 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E 2019-11-18T22:53:15.269Z,1574117595.269 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C 2019-11-18T22:53:15.269Z,1574117595.269 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46 2019-11-18T22:53:15.662Z,1574117595.662 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44 2019-11-18T22:53:15.662Z,1574117595.662 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63 2019-11-18T22:53:16.075Z,1574117596.075 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61 2019-11-18T22:53:16.076Z,1574117596.076 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A 2019-11-18T22:53:16.446Z,1574117596.446 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38 2019-11-18T22:53:16.446Z,1574117596.446 [Micromodem](INFO): Nmea out: $CCCLK,2019,11,18,22,53,17*47 2019-11-18T22:53:16.851Z,1574117596.851 [Micromodem](INFO): Nmea in: $CACLK,2019,11,18,22,53,17*45 2019-11-18T22:53:17.254Z,1574117597.254 [Micromodem](INFO): Nmea in: $CATMS,0,2019-11-18T22:53:18Z*7A 2019-11-18T22:53:17.255Z,1574117597.255 [Micromodem](INFO): Nmea in: $CATMG,2019-11-18T22:53:18.027106Z,USER_CMD,RTC*1F 2019-11-18T22:53:18.061Z,1574117598.061 [DDM](INFO): Dynamic Docking Module:E 2019-11-18T22:53:18.850Z,1574117598.850 [DDM](INFO): Retracting Whiskers. 2019-11-18T22:53:20.915Z,1574117600.915 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-11-18T22:53:25.469Z,1574117605.469 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004443 2019-11-18T22:53:25.725Z,1574117605.725 [DUSBL_Hydroid](INFO): DUSBL Version:O 2019-11-18T22:53:26.168Z,1574117606.168 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-18T22:53:26.168Z,1574117606.168 [RDI_Pathfinder](ERROR): Failed to parse: :TS,191118160524 -0.1, 0.0,1448.9, 0 2019-11-18T22:53:33.805Z,1574117613.805 [NAL9602](INFO): Powering up NAL9602 2019-11-18T22:53:41.542Z,1574117621.542 [SBIT](IMPORTANT): Beginning Startup BIT 2019-11-18T22:53:41.551Z,1574117621.551 [CBIT](IMPORTANT): Beginning ground fault scan 2019-11-18T22:53:44.869Z,1574117624.869 [NAL9602](INFO): NAL9602 initialized 2019-11-18T22:53:52.652Z,1574117632.652 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.021783 CHAN A1 (24V): -0.027896 CHAN A2 (12V): -0.006680 CHAN A3 (5V): -0.002131 CHAN B0 (3.3V): 0.000358 CHAN B1 (3.15aV): 0.000092 CHAN B2 (3.15bV): -0.000096 CHAN B3 (GND): 0.001909 OPEN: 0.005561 Full Scale Calc: 4.765 mA, -1.589 mA 2019-11-18T22:54:35.258Z,1574117675.258 [SBIT](IMPORTANT): SBIT PASSED 2019-11-18T22:54:35.299Z,1574117675.299 [CommandLine](IMPORTANT): got command configSet list 2019-11-18T22:54:35.300Z,1574117675.300 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): DDM.loadAtStartup=1 bool; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): DDM.verbosity=3 count; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=75 count; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=40 millisecond; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.acoustic_contact_range 1.000000 meter; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 degree; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): Express linearApproximation platform_orientation 5.000000 degree; 2019-11-18T22:54:35.301Z,1574117675.301 [CommandLine](IMPORTANT): Express linearApproximation platform_x_velocity_wrt_ground 0.100000 meter_per_second; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): Express linearApproximation platform_y_velocity_wrt_ground 0.100000 meter_per_second; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): HorizontalControl.kiHeading=0.002 reciprocal_second; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): PowerOnly.sampleTime=90 second; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup=1 bool; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=350 cubic_centimeter; 2019-11-18T22:54:35.302Z,1574117675.302 [CommandLine](IMPORTANT): VerticalControl.massDefault=3.6 millimeter; 2019-11-18T22:54:35.654Z,1574117675.654 [MissionManager](IMPORTANT): Started mission Startup 2019-11-18T22:54:35.655Z,1574117675.655 [Startup] Running Loop=1 2019-11-18T22:54:35.655Z,1574117675.655 [Startup](DEBUG): Aggregate::initialize Startup 2019-11-18T22:54:35.655Z,1574117675.655 [Startup:A.GoToSurface] Running Loop=1 2019-11-18T22:54:35.655Z,1574117675.655 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-11-18T22:54:35.656Z,1574117675.656 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-11-18T22:54:35.656Z,1574117675.656 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-11-18T22:54:35.657Z,1574117675.657 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-11-18T22:54:35.657Z,1574117675.657 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-11-18T22:54:35.657Z,1574117675.657 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-11-18T22:54:35.659Z,1574117675.659 [Startup:StartupSatComms] Running Loop=1 2019-11-18T22:54:35.659Z,1574117675.659 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-11-18T22:54:35.659Z,1574117675.659 [Startup:StartupSatComms:A] Running Loop=1 2019-11-18T22:54:36.080Z,1574117676.080 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-11-18T22:55:36.006Z,1574117736.006 [Startup:StartupSatComms:A](INFO): Timed out from 2019-11-18T22:54:35.7Z 2019-11-18T22:55:36.006Z,1574117736.006 [Startup:StartupSatComms:A] Stopped 2019-11-18T22:55:36.006Z,1574117736.006 [Startup:StartupSatComms:B] Running Loop=1 2019-11-18T22:55:36.240Z,1574117736.240 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-11-18T22:55:39.249Z,1574117739.249 [DataOverHttps](INFO): Sending 237 bytes from file Logs/20191114T234619/Express0034.lzma 2019-11-18T22:55:40.730Z,1574117740.730 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0034.lzma.bak 2019-11-18T22:55:40.730Z,1574117740.730 [DataOverHttps](INFO): SBD MOMSN=12070140 2019-11-18T22:56:00.927Z,1574117760.927 [DataOverHttps](INFO): Sending 581 bytes from file Logs/20191118T224243/Express0001.lzma 2019-11-18T22:56:02.933Z,1574117762.933 [DataOverHttps](INFO): Moved sent file to Logs/20191118T224243/Express0001.lzma.bak 2019-11-18T22:56:02.933Z,1574117762.933 [DataOverHttps](INFO): SBD MOMSN=12070145 2019-11-18T22:56:07.359Z,1574117767.359 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-11-18T22:56:07.359Z,1574117767.359 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T22:56:07.401Z,1574117767.401 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T22:56:07.769Z,1574117767.769 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T22:56:07.769Z,1574117767.769 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-11-18T22:56:23.100Z,1574117783.100 [DataOverHttps](INFO): Sending 1112 bytes from file Logs/20191118T225256/Express0001.lzma 2019-11-18T22:56:25.104Z,1574117785.104 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0001.lzma.bak 2019-11-18T22:56:25.105Z,1574117785.105 [DataOverHttps](INFO): SBD MOMSN=12070156 2019-11-18T22:56:26.741Z,1574117786.741 [Startup:StartupSatComms:B] Stopped 2019-11-18T22:56:26.741Z,1574117786.741 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-11-18T22:56:26.741Z,1574117786.741 [Startup:StartupSatComms] Stopped 2019-11-18T22:56:26.741Z,1574117786.741 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-11-18T22:56:26.742Z,1574117786.742 [Startup](INFO): Completed Startup 2019-11-18T22:56:26.742Z,1574117786.742 [MissionManager](INFO): Startup is completed. 2019-11-18T22:56:26.742Z,1574117786.742 [MissionManager](INFO): Uninitializing Mission Startup 2019-11-18T22:56:26.743Z,1574117786.743 [Startup] Stopped 2019-11-18T22:56:26.743Z,1574117786.743 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-11-18T22:56:26.743Z,1574117786.743 [Startup:A.GoToSurface] Stopped 2019-11-18T22:56:26.743Z,1574117786.743 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-11-18T22:56:27.155Z,1574117787.155 [MissionManager](IMPORTANT): Started mission Default 2019-11-18T22:56:27.155Z,1574117787.155 [Default] Running Loop=1 2019-11-18T22:56:27.155Z,1574117787.155 [Default](DEBUG): Aggregate::initialize Default 2019-11-18T22:56:27.155Z,1574117787.155 [Default:B.GoToSurface] Running Loop=1 2019-11-18T22:56:27.155Z,1574117787.155 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-11-18T22:56:27.156Z,1574117787.156 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-11-18T22:56:27.156Z,1574117787.156 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-11-18T22:56:27.156Z,1574117787.156 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-11-18T22:56:27.157Z,1574117787.157 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-11-18T22:56:27.157Z,1574117787.157 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-11-18T22:56:27.157Z,1574117787.157 [Default:A.Wait] Running Loop=1 2019-11-18T22:56:27.157Z,1574117787.157 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-11-18T22:56:40.492Z,1574117800.492 [Default:A.Wait](INFO): Done Waiting. 2019-11-18T22:56:40.492Z,1574117800.492 [Default:A.Wait] Stopped 2019-11-18T22:56:40.492Z,1574117800.492 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-11-18T22:56:40.978Z,1574117800.978 [Default:CheckIn] Running Loop=1 2019-11-18T22:56:40.978Z,1574117800.978 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-18T22:56:40.978Z,1574117800.978 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-18T22:56:41.299Z,1574117801.299 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-11-18T22:58:48.109Z,1574117928.109 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-18T22:59:08.388Z,1574117948.388 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2019-11-18T22:59:08.388Z,1574117948.388 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T22:59:08.402Z,1574117948.402 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T22:59:08.796Z,1574117948.796 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T22:59:08.796Z,1574117948.796 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2019-11-18T23:00:34.805Z,1574118034.805 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-18T23:00:34.808Z,1574118034.808 [BPC1](INFO): Received data from all battery sticks. 2019-11-18T23:00:51.777Z,1574118051.777 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-18T23:01:41.070Z,1574118101.070 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-18T22:56:40.0Z 2019-11-18T23:01:41.070Z,1574118101.070 [Default:CheckIn:Read_GPS] Stopped 2019-11-18T23:01:41.070Z,1574118101.070 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-18T23:01:41.473Z,1574118101.473 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-11-18T23:01:50.874Z,1574118110.874 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20191118T225256/Courier0004.lzma 2019-11-18T23:01:52.880Z,1574118112.880 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Courier0004.lzma.bak 2019-11-18T23:01:52.881Z,1574118112.881 [DataOverHttps](INFO): SBD MOMSN=12070187 2019-11-18T23:02:09.357Z,1574118129.357 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2019-11-18T23:02:09.357Z,1574118129.357 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:02:09.391Z,1574118129.391 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:02:09.765Z,1574118129.765 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:02:09.765Z,1574118129.765 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2019-11-18T23:02:10.907Z,1574118130.907 [DataOverHttps](INFO): Sending 200 bytes from file Logs/20191118T225256/Express0005.lzma 2019-11-18T23:02:12.912Z,1574118132.912 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0005.lzma.bak 2019-11-18T23:02:12.913Z,1574118132.913 [DataOverHttps](INFO): SBD MOMSN=12070191 2019-11-18T23:02:14.609Z,1574118134.609 [Default:CheckIn:Read_Iridium] Stopped 2019-11-18T23:02:14.609Z,1574118134.609 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-18T23:02:14.609Z,1574118134.609 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-18T23:03:48.283Z,1574118228.283 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-18T23:03:48.283Z,1574118228.283 [NAL9602] Data Fault, FailCount= 1 2019-11-18T23:03:48.283Z,1574118228.283 [NAL9602](ERROR): Data Fault 2019-11-18T23:03:48.324Z,1574118228.324 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-18T23:03:48.685Z,1574118228.685 [NAL9602](INFO): Powering down 2019-11-18T23:03:49.541Z,1574118229.541 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-18T23:03:49.541Z,1574118229.541 [NAL9602] No Fault, FailCount= 1 2019-11-18T23:04:14.982Z,1574118254.982 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-11-18T23:04:18.985Z,1574118258.985 [NAL9602](INFO): Powering up NAL9602 2019-11-18T23:04:29.885Z,1574118269.885 [NAL9602](INFO): NAL9602 initialized 2019-11-18T23:04:32.772Z,1574118272.772 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:04:32.772Z,1574118272.772 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3268,V 2019-11-18T23:05:10.340Z,1574118310.340 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2019-11-18T23:05:10.340Z,1574118310.340 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:05:10.350Z,1574118310.350 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:05:10.781Z,1574118310.781 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:05:10.781Z,1574118310.781 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2019-11-18T23:07:15.153Z,1574118435.153 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-18T23:07:15.153Z,1574118435.153 [Default:CheckIn:C.Wait] Stopped 2019-11-18T23:07:15.153Z,1574118435.153 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-18T23:07:15.153Z,1574118435.153 [Default:CheckIn:D] Running Loop=1 2019-11-18T23:07:15.558Z,1574118435.558 [Default:CheckIn:D] Stopped 2019-11-18T23:07:15.558Z,1574118435.558 [Default:CheckIn:E] Running Loop=1 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.806713 min 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn:E] Stopped 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn] Stopped 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn](INFO): Running loop #2 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn] Running Loop=2 2019-11-18T23:07:15.978Z,1574118435.978 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-18T23:07:15.979Z,1574118435.979 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-18T23:08:11.320Z,1574118491.320 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2019-11-18T23:08:11.320Z,1574118491.320 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:08:11.330Z,1574118491.330 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:08:11.763Z,1574118491.763 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:08:11.763Z,1574118491.763 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2019-11-18T23:10:50.488Z,1574118650.488 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-18T23:10:50.488Z,1574118650.488 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-18T23:11:12.328Z,1574118672.328 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6 2019-11-18T23:11:12.328Z,1574118672.328 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:11:12.338Z,1574118672.338 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:11:12.772Z,1574118672.772 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:11:12.772Z,1574118672.772 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6 2019-11-18T23:12:16.148Z,1574118736.148 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-18T23:07:15.0Z 2019-11-18T23:12:16.148Z,1574118736.148 [Default:CheckIn:Read_GPS] Stopped 2019-11-18T23:12:16.148Z,1574118736.148 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-18T23:12:24.427Z,1574118744.427 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20191118T225256/Express0008.lzma 2019-11-18T23:12:26.432Z,1574118746.432 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0008.lzma.bak 2019-11-18T23:12:26.433Z,1574118746.433 [DataOverHttps](INFO): SBD MOMSN=12070199 2019-11-18T23:12:28.279Z,1574118748.279 [Default:CheckIn:Read_Iridium] Stopped 2019-11-18T23:12:28.279Z,1574118748.279 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-18T23:12:28.279Z,1574118748.279 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-18T23:13:15.117Z,1574118795.117 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:13:15.117Z,1574118795.117 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.-32768,-32768,-32768,-32768,V 2019-11-18T23:14:13.304Z,1574118853.304 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7 2019-11-18T23:14:13.304Z,1574118853.304 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:14:13.314Z,1574118853.314 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:14:13.764Z,1574118853.764 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:14:13.765Z,1574118853.765 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7 2019-11-18T23:14:31.038Z,1574118871.038 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-18T23:14:31.038Z,1574118871.038 [NAL9602] Data Fault, FailCount= 2 2019-11-18T23:14:31.038Z,1574118871.038 [NAL9602](ERROR): Data Fault 2019-11-18T23:14:31.114Z,1574118871.114 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-18T23:14:31.449Z,1574118871.450 [NAL9602](INFO): Powering down 2019-11-18T23:14:32.285Z,1574118872.285 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-18T23:14:32.285Z,1574118872.285 [NAL9602] No Fault, FailCount= 2 2019-11-18T23:15:01.760Z,1574118901.760 [NAL9602](INFO): Powering up NAL9602 2019-11-18T23:15:12.658Z,1574118912.658 [NAL9602](INFO): NAL9602 initialized 2019-11-18T23:17:14.304Z,1574119034.304 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8 2019-11-18T23:17:14.304Z,1574119034.304 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:17:14.314Z,1574119034.314 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:17:14.765Z,1574119034.765 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:17:14.765Z,1574119034.765 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8 2019-11-18T23:17:28.853Z,1574119048.853 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-18T23:17:28.853Z,1574119048.853 [Default:CheckIn:C.Wait] Stopped 2019-11-18T23:17:28.853Z,1574119048.853 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-18T23:17:28.853Z,1574119048.853 [Default:CheckIn:D] Running Loop=1 2019-11-18T23:17:29.267Z,1574119049.267 [Default:CheckIn:D] Stopped 2019-11-18T23:17:29.267Z,1574119049.267 [Default:CheckIn:E] Running Loop=1 2019-11-18T23:17:29.639Z,1574119049.639 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.035203 min 2019-11-18T23:17:29.639Z,1574119049.639 [Default:CheckIn:E] Stopped 2019-11-18T23:17:29.640Z,1574119049.640 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-18T23:17:29.640Z,1574119049.640 [Default:CheckIn] Stopped 2019-11-18T23:17:29.640Z,1574119049.640 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-18T23:17:29.640Z,1574119049.640 [Default:CheckIn](INFO): Running loop #3 2019-11-18T23:17:29.640Z,1574119049.640 [Default:CheckIn] Running Loop=3 2019-11-18T23:17:29.640Z,1574119049.640 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-18T23:17:29.640Z,1574119049.640 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-18T23:20:15.307Z,1574119215.307 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9 2019-11-18T23:20:15.308Z,1574119215.308 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:20:15.325Z,1574119215.325 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:20:15.704Z,1574119215.704 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:20:15.704Z,1574119215.704 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9 2019-11-18T23:22:29.808Z,1574119349.808 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-18T23:17:29.6Z 2019-11-18T23:22:29.808Z,1574119349.808 [Default:CheckIn:Read_GPS] Stopped 2019-11-18T23:22:29.808Z,1574119349.808 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-18T23:22:39.642Z,1574119359.642 [DataOverHttps](INFO): Sending 170 bytes from file Logs/20191118T225256/Express0011.lzma 2019-11-18T23:22:41.648Z,1574119361.648 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0011.lzma.bak 2019-11-18T23:22:41.649Z,1574119361.649 [DataOverHttps](INFO): SBD MOMSN=12070205 2019-11-18T23:22:43.577Z,1574119363.577 [Default:CheckIn:Read_Iridium] Stopped 2019-11-18T23:22:43.577Z,1574119363.577 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-18T23:22:43.577Z,1574119363.577 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-18T23:23:16.333Z,1574119396.333 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10 2019-11-18T23:23:16.333Z,1574119396.333 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:23:16.424Z,1574119396.424 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:23:16.693Z,1574119396.693 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:23:16.694Z,1574119396.694 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10 2019-11-18T23:23:43.756Z,1574119423.756 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-18T23:23:43.756Z,1574119423.756 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.0 +0.00, +0.00, 0.00,1822.86 2019-11-18T23:23:59.112Z,1574119439.112 [RDI_Pathfinder](ERROR): Failed to parse: 00, 0.00, 0.00, 0.00, 0.00 2019-11-18T23:24:22.123Z,1574119462.123 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-18T23:24:22.123Z,1574119462.123 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111816362079,35.0, 0.0,1448.9, 0 2019-11-18T23:24:43.137Z,1574119483.137 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-18T23:24:43.137Z,1574119483.137 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111816364179,35.0, -0.11448.9, 0 2019-11-18T23:25:14.206Z,1574119514.206 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-18T23:25:14.206Z,1574119514.206 [NAL9602] Data Fault, FailCount= 3 2019-11-18T23:25:14.206Z,1574119514.206 [NAL9602](ERROR): Data Fault 2019-11-18T23:25:14.241Z,1574119514.241 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-18T23:25:14.619Z,1574119514.619 [NAL9602](INFO): Powering down 2019-11-18T23:25:15.462Z,1574119515.462 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-18T23:25:15.462Z,1574119515.462 [NAL9602] No Fault, FailCount= 3 2019-11-18T23:25:23.133Z,1574119523.133 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-18T23:25:23.133Z,1574119523.133 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111816372179,35.0, -0.1, 0.0, 0 2019-11-18T23:25:44.917Z,1574119544.917 [NAL9602](INFO): Powering up NAL9602 2019-11-18T23:25:55.825Z,1574119555.825 [NAL9602](INFO): NAL9602 initialized 2019-11-18T23:26:17.284Z,1574119577.284 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11 2019-11-18T23:26:17.284Z,1574119577.284 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:26:17.294Z,1574119577.294 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:26:17.691Z,1574119577.691 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:26:17.691Z,1574119577.691 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11 2019-11-18T23:26:24.952Z,1574119584.952 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-11-18T23:27:44.146Z,1574119664.146 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:27:44.146Z,1574119664.146 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3768,V 2019-11-18T23:27:44.161Z,1574119664.161 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-18T23:27:44.161Z,1574119664.161 [Default:CheckIn:C.Wait] Stopped 2019-11-18T23:27:44.161Z,1574119664.161 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-18T23:27:44.161Z,1574119664.161 [Default:CheckIn:D] Running Loop=1 2019-11-18T23:27:44.542Z,1574119664.542 [Default:CheckIn:D] Stopped 2019-11-18T23:27:44.542Z,1574119664.542 [Default:CheckIn:E] Running Loop=1 2019-11-18T23:27:44.944Z,1574119664.944 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.289775 min 2019-11-18T23:27:44.944Z,1574119664.944 [Default:CheckIn:E] Stopped 2019-11-18T23:27:44.944Z,1574119664.944 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-18T23:27:44.944Z,1574119664.944 [Default:CheckIn] Stopped 2019-11-18T23:27:44.944Z,1574119664.944 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-18T23:27:44.945Z,1574119664.945 [Default:CheckIn](INFO): Running loop #4 2019-11-18T23:27:44.945Z,1574119664.945 [Default:CheckIn] Running Loop=4 2019-11-18T23:27:44.945Z,1574119664.945 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-18T23:27:44.945Z,1574119664.945 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-18T23:28:20.501Z,1574119700.501 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:28:20.501Z,1574119700.501 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-2768,-32768,V 2019-11-18T23:28:25.778Z,1574119705.778 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-32768,V 2019-11-18T23:29:18.262Z,1574119758.262 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12 2019-11-18T23:29:18.262Z,1574119758.262 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:29:18.272Z,1574119758.272 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:29:18.673Z,1574119758.673 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:29:18.673Z,1574119758.673 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12 2019-11-18T23:29:24.749Z,1574119764.749 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:29:24.749Z,1574119764.749 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3276,-32768,V 2019-11-18T23:32:19.289Z,1574119939.289 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13 2019-11-18T23:32:19.289Z,1574119939.289 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:32:19.307Z,1574119939.307 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:32:19.672Z,1574119939.672 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:32:19.673Z,1574119939.673 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13 2019-11-18T23:32:45.139Z,1574119965.139 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-18T23:27:44.9Z 2019-11-18T23:32:45.139Z,1574119965.139 [Default:CheckIn:Read_GPS] Stopped 2019-11-18T23:32:45.139Z,1574119965.139 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-18T23:32:54.891Z,1574119974.891 [DataOverHttps](INFO): Sending 171 bytes from file Logs/20191118T225256/Express0014.lzma 2019-11-18T23:32:56.896Z,1574119976.896 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0014.lzma.bak 2019-11-18T23:32:56.897Z,1574119976.897 [DataOverHttps](INFO): SBD MOMSN=12070213 2019-11-18T23:32:58.845Z,1574119978.845 [Default:CheckIn:Read_Iridium] Stopped 2019-11-18T23:32:58.845Z,1574119978.845 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-18T23:32:58.845Z,1574119978.845 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-18T23:35:20.242Z,1574120120.242 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14 2019-11-18T23:35:20.242Z,1574120120.242 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:35:20.272Z,1574120120.272 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:35:20.733Z,1574120120.733 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:35:20.734Z,1574120120.734 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14 2019-11-18T23:35:30.777Z,1574120130.777 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-18T23:35:30.777Z,1574120130.777 [RDI_Pathfinder](ERROR): Failed to parse: :BD, , +0.00, +0.00, 29.72 2019-11-18T23:35:58.191Z,1574120158.191 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-18T23:35:58.191Z,1574120158.191 [NAL9602] Data Fault, FailCount= 4 2019-11-18T23:35:58.191Z,1574120158.191 [NAL9602](ERROR): Data Fault 2019-11-18T23:35:58.244Z,1574120158.244 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-18T23:35:58.590Z,1574120158.590 [NAL9602](INFO): Powering down 2019-11-18T23:35:59.470Z,1574120159.470 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-18T23:35:59.470Z,1574120159.470 [NAL9602] No Fault, FailCount= 4 2019-11-18T23:36:28.894Z,1574120188.894 [NAL9602](INFO): Powering up NAL9602 2019-11-18T23:36:39.798Z,1574120199.798 [NAL9602](INFO): NAL9602 initialized 2019-11-18T23:37:59.439Z,1574120279.439 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-18T23:37:59.439Z,1574120279.439 [Default:CheckIn:C.Wait] Stopped 2019-11-18T23:37:59.439Z,1574120279.439 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-18T23:37:59.440Z,1574120279.440 [Default:CheckIn:D] Running Loop=1 2019-11-18T23:37:59.821Z,1574120279.821 [Default:CheckIn:D] Stopped 2019-11-18T23:37:59.821Z,1574120279.821 [Default:CheckIn:E] Running Loop=1 2019-11-18T23:38:00.232Z,1574120280.232 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.544434 min 2019-11-18T23:38:00.232Z,1574120280.232 [Default:CheckIn:E] Stopped 2019-11-18T23:38:00.232Z,1574120280.232 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-18T23:38:00.232Z,1574120280.232 [Default:CheckIn] Stopped 2019-11-18T23:38:00.232Z,1574120280.232 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-18T23:38:00.233Z,1574120280.233 [Default:CheckIn](INFO): Running loop #5 2019-11-18T23:38:00.233Z,1574120280.233 [Default:CheckIn] Running Loop=5 2019-11-18T23:38:00.233Z,1574120280.233 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-18T23:38:00.233Z,1574120280.233 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-18T23:38:21.259Z,1574120301.259 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15 2019-11-18T23:38:21.259Z,1574120301.259 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:38:21.277Z,1574120301.277 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:38:21.680Z,1574120301.680 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:38:21.681Z,1574120301.681 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15 2019-11-18T23:38:47.923Z,1574120327.923 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-18T23:38:47.923Z,1574120327.923 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 2019-11-18T23:39:11.759Z,1574120351.759 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-18T23:39:11.759Z,1574120351.759 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-3:BE,-32768,-32768,-32768,V 2019-11-18T23:40:48.284Z,1574120448.284 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-18T23:40:48.284Z,1574120448.284 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111816524679,35.0, -0.11448.9, 0 2019-11-18T23:41:22.250Z,1574120482.250 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16 2019-11-18T23:41:22.250Z,1574120482.250 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:41:22.266Z,1574120482.266 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:41:22.645Z,1574120482.645 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:41:22.645Z,1574120482.645 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16 2019-11-18T23:41:28.305Z,1574120488.305 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:41:28.305Z,1574120488.305 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3276,V 2019-11-18T23:43:00.408Z,1574120580.408 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-18T23:38:00.2Z 2019-11-18T23:43:00.408Z,1574120580.408 [Default:CheckIn:Read_GPS] Stopped 2019-11-18T23:43:00.408Z,1574120580.408 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-18T23:43:08.502Z,1574120588.502 [DataOverHttps](INFO): Sending 164 bytes from file Logs/20191118T225256/Express0017.lzma 2019-11-18T23:43:10.509Z,1574120590.509 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0017.lzma.bak 2019-11-18T23:43:10.509Z,1574120590.509 [DataOverHttps](INFO): SBD MOMSN=12070221 2019-11-18T23:43:12.129Z,1574120592.129 [Default:CheckIn:Read_Iridium] Stopped 2019-11-18T23:43:12.129Z,1574120592.129 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-18T23:43:12.129Z,1574120592.129 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-18T23:44:12.744Z,1574120652.744 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-18T23:44:12.744Z,1574120652.744 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-18T23:44:23.236Z,1574120663.236 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17 2019-11-18T23:44:23.236Z,1574120663.236 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:44:23.251Z,1574120663.251 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:44:23.668Z,1574120663.668 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:44:23.668Z,1574120663.668 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17 2019-11-18T23:44:32.124Z,1574120672.124 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-18T23:45:55.765Z,1574120755.765 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-18T23:46:12.742Z,1574120772.742 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:46:12.742Z,1574120772.742 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3268,-32768,V 2019-11-18T23:46:41.358Z,1574120801.358 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-18T23:46:41.358Z,1574120801.358 [NAL9602] Data Fault, FailCount= 5 2019-11-18T23:46:41.358Z,1574120801.358 [NAL9602](ERROR): Data Fault 2019-11-18T23:46:41.402Z,1574120801.402 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-18T23:46:41.402Z,1574120801.402 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-11-18T23:46:41.765Z,1574120801.765 [NAL9602](INFO): Powering down 2019-11-18T23:46:41.819Z,1574120801.819 [CommandLine](FAULT): Scheduling is paused 2019-11-18T23:46:41.819Z,1574120801.819 [CBIT](INFO): Critical error at 20191118T234641 2019-11-18T23:46:41.820Z,1574120801.820 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2019-11-18T23:46:49.469Z,1574120809.469 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-18T23:47:24.224Z,1574120844.224 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 18 2019-11-18T23:47:24.224Z,1574120844.224 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:47:24.234Z,1574120844.234 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:47:24.630Z,1574120844.630 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:47:24.630Z,1574120844.630 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 18 2019-11-18T23:47:50.469Z,1574120870.469 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-11-18T23:47:54.095Z,1574120874.095 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-18T23:47:54.102Z,1574120874.102 [RDI_Pathfinder](ERROR): Failed to parse: :TS6595279,35.0, -0.1, 0.0,1448.9, 0 2019-11-18T23:48:12.732Z,1574120892.732 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-18T23:48:12.732Z,1574120892.732 [Default:CheckIn:C.Wait] Stopped 2019-11-18T23:48:12.732Z,1574120892.732 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-18T23:48:12.733Z,1574120892.733 [Default:CheckIn:D] Running Loop=1 2019-11-18T23:48:13.108Z,1574120893.108 [Default:CheckIn:D] Stopped 2019-11-18T23:48:13.108Z,1574120893.108 [Default:CheckIn:E] Running Loop=1 2019-11-18T23:48:13.508Z,1574120893.508 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 51.765877 min 2019-11-18T23:48:13.508Z,1574120893.508 [Default:CheckIn:E] Stopped 2019-11-18T23:48:13.508Z,1574120893.508 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-18T23:48:13.508Z,1574120893.508 [Default:CheckIn] Stopped 2019-11-18T23:48:13.509Z,1574120893.509 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-18T23:48:13.509Z,1574120893.509 [Default:CheckIn](INFO): Running loop #6 2019-11-18T23:48:13.509Z,1574120893.509 [Default:CheckIn] Running Loop=6 2019-11-18T23:48:13.509Z,1574120893.509 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-18T23:48:13.509Z,1574120893.509 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-18T23:48:41.380Z,1574120921.380 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-18T23:48:41.380Z,1574120921.380 [NAL9602] No Fault, FailCount= 5 2019-11-18T23:48:41.759Z,1574120921.759 [NAL9602](INFO): Powering up NAL9602 2019-11-18T23:48:52.663Z,1574120932.663 [NAL9602](INFO): NAL9602 initialized 2019-11-18T23:49:16.142Z,1574120956.142 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-18T23:49:16.142Z,1574120956.142 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-18T23:49:31.082Z,1574120971.082 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-18T23:49:31.082Z,1574120971.082 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-18T23:50:25.207Z,1574121025.207 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 19 2019-11-18T23:50:25.207Z,1574121025.207 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:50:25.245Z,1574121025.245 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:50:25.655Z,1574121025.655 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:50:25.659Z,1574121025.659 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 19 2019-11-18T23:51:35.117Z,1574121095.117 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-18T23:51:35.117Z,1574121095.117 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-18T23:53:13.700Z,1574121193.700 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-18T23:48:13.5Z 2019-11-18T23:53:13.701Z,1574121193.701 [Default:CheckIn:Read_GPS] Stopped 2019-11-18T23:53:13.701Z,1574121193.701 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-18T23:53:23.696Z,1574121203.696 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20191118T225256/Courier0019.lzma 2019-11-18T23:53:25.698Z,1574121205.698 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Courier0019.lzma.bak 2019-11-18T23:53:25.698Z,1574121205.698 [DataOverHttps](INFO): SBD MOMSN=12070229 2019-11-18T23:53:26.208Z,1574121206.208 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 20 2019-11-18T23:53:26.208Z,1574121206.208 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:53:26.218Z,1574121206.218 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:53:26.624Z,1574121206.624 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:53:26.624Z,1574121206.624 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 20 2019-11-18T23:53:43.935Z,1574121223.935 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20191118T225256/Express0020.lzma 2019-11-18T23:53:45.941Z,1574121225.941 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0020.lzma.bak 2019-11-18T23:53:45.941Z,1574121225.941 [DataOverHttps](INFO): SBD MOMSN=12070232 2019-11-18T23:53:47.625Z,1574121227.625 [Default:CheckIn:Read_Iridium] Stopped 2019-11-18T23:53:47.625Z,1574121227.625 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-18T23:53:47.625Z,1574121227.625 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-18T23:55:01.151Z,1574121301.151 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-18T23:55:01.152Z,1574121301.152 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, BI,-32768,-32768,-32768,-32768,V 2019-11-18T23:56:27.196Z,1574121387.196 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 21 2019-11-18T23:56:27.196Z,1574121387.196 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:56:27.206Z,1574121387.206 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:56:27.620Z,1574121387.620 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:56:27.620Z,1574121387.620 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 21 2019-11-18T23:58:48.221Z,1574121528.221 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-18T23:58:48.221Z,1574121528.221 [Default:CheckIn:C.Wait] Stopped 2019-11-18T23:58:48.221Z,1574121528.221 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-18T23:58:48.221Z,1574121528.221 [Default:CheckIn:D] Running Loop=1 2019-11-18T23:58:48.597Z,1574121528.597 [Default:CheckIn:D] Stopped 2019-11-18T23:58:48.597Z,1574121528.597 [Default:CheckIn:E] Running Loop=1 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 62.357369 min 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn:E] Stopped 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn] Stopped 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn](INFO): Running loop #7 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn] Running Loop=7 2019-11-18T23:58:49.004Z,1574121529.004 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-18T23:58:49.005Z,1574121529.005 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-18T23:58:56.241Z,1574121536.241 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-18T23:58:56.241Z,1574121536.241 [NAL9602] Data Fault, FailCount= 1 2019-11-18T23:58:56.241Z,1574121536.241 [NAL9602](ERROR): Data Fault 2019-11-18T23:58:56.329Z,1574121536.329 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-18T23:58:56.654Z,1574121536.654 [NAL9602](INFO): Powering down 2019-11-18T23:58:57.541Z,1574121537.541 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-18T23:58:57.541Z,1574121537.541 [NAL9602] No Fault, FailCount= 1 2019-11-18T23:59:26.942Z,1574121566.942 [NAL9602](INFO): Powering up NAL9602 2019-11-18T23:59:28.198Z,1574121568.198 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 22 2019-11-18T23:59:28.198Z,1574121568.198 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-18T23:59:28.208Z,1574121568.208 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-18T23:59:28.616Z,1574121568.616 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-18T23:59:28.617Z,1574121568.617 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 22 2019-11-18T23:59:37.858Z,1574121577.858 [NAL9602](INFO): NAL9602 initialized 2019-11-19T00:00:41.749Z,1574121641.749 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-19T00:00:41.749Z,1574121641.749 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0.00, , 0.00,4040.35 2019-11-19T00:01:47.165Z,1574121707.165 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-19T00:01:47.165Z,1574121707.165 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 2019-11-19T00:02:23.953Z,1574121743.953 [RDI_Pathfinder](ERROR): Failed to parse: +0.00, +0.00, +0.00, 0.00,4141.31 2019-11-19T00:02:29.206Z,1574121749.206 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 23 2019-11-19T00:02:29.206Z,1574121749.206 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-19T00:02:29.216Z,1574121749.216 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-19T00:02:29.615Z,1574121749.615 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-19T00:02:29.615Z,1574121749.615 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 23 2019-11-19T00:03:25.768Z,1574121805.768 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-19T00:03:25.768Z,1574121805.768 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3268,V 2019-11-19T00:03:38.262Z,1574121818.262 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-19T00:03:38.262Z,1574121818.262 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111817153679,35.0 0.0,1448.9, 0 2019-11-19T00:03:39.473Z,1574121819.473 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-19T00:03:49.208Z,1574121829.208 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-18T23:58:49.0Z 2019-11-19T00:03:49.208Z,1574121829.208 [Default:CheckIn:Read_GPS] Stopped 2019-11-19T00:03:49.208Z,1574121829.208 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-19T00:03:59.394Z,1574121839.394 [DataOverHttps](INFO): Sending 158 bytes from file Logs/20191118T225256/Express0023.lzma 2019-11-19T00:04:00.099Z,1574121840.099 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-19T00:04:00.099Z,1574121840.099 [RDI_Pathfinder](ERROR): Failed to parse: :BD, , +0.00, +0.00, 0.00,4238.26 2019-11-19T00:04:01.401Z,1574121841.401 [DataOverHttps](INFO): Moved sent file to Logs/20191118T225256/Express0023.lzma.bak 2019-11-19T00:04:01.401Z,1574121841.401 [DataOverHttps](INFO): SBD MOMSN=12070241 2019-11-19T00:04:03.332Z,1574121843.332 [Default:CheckIn:Read_Iridium] Stopped 2019-11-19T00:04:03.332Z,1574121843.332 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-19T00:04:03.332Z,1574121843.332 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-19T00:04:23.112Z,1574121863.112 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-19T00:04:23.113Z,1574121863.113 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111817162179,35.0, -0.1, 09, 0 2019-11-19T00:05:30.180Z,1574121930.180 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 24 2019-11-19T00:05:30.180Z,1574121930.180 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-19T00:05:30.202Z,1574121930.202 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-19T00:05:30.668Z,1574121930.668 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-19T00:05:30.668Z,1574121930.668 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 24 2019-11-19T00:07:46.407Z,1574122066.407 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2019-11-19T00:08:01.729Z,1574122081.729 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-19T00:08:01.730Z,1574122081.730 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-19T00:08:03.308Z,1574122083.308 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-19T00:08:03.310Z,1574122083.310 [BPC1](INFO): Received data from all battery sticks. 2019-11-19T00:08:30.058Z,1574122110.058 [CommandLine](IMPORTANT): got command restart application 2019-11-19T00:08:31.075Z,1574122111.075 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:31.075Z,1574122111.075 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.123Z,1574122111.123 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-11-19T00:08:31.123Z,1574122111.123 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.124Z,1574122111.124 [CommandLine](INFO): Join timeout helper Thread ID is 5816 2019-11-19T00:08:31.124Z,1574122111.124 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-11-19T00:08:31.124Z,1574122111.124 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.125Z,1574122111.125 [NavChartDb](INFO): Join timeout helper Thread ID is 5817 2019-11-19T00:08:31.198Z,1574122111.198 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 25 2019-11-19T00:08:31.198Z,1574122111.198 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-11-19T00:08:31.208Z,1574122111.208 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-11-19T00:08:31.403Z,1574122111.403 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:31.403Z,1574122111.403 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.415Z,1574122111.415 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2019-11-19T00:08:31.415Z,1574122111.415 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.415Z,1574122111.415 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 5818 2019-11-19T00:08:31.597Z,1574122111.597 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-11-19T00:08:31.597Z,1574122111.597 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 25 2019-11-19T00:08:31.811Z,1574122111.811 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:31.811Z,1574122111.811 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-11-19T00:08:31.812Z,1574122111.812 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.819Z,1574122111.819 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-11-19T00:08:31.819Z,1574122111.819 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.819Z,1574122111.819 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5819 2019-11-19T00:08:31.895Z,1574122111.895 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:31.896Z,1574122111.896 [CTD_NeilBrown](INFO): Powering down 2019-11-19T00:08:31.907Z,1574122111.907 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.923Z,1574122111.923 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-11-19T00:08:31.923Z,1574122111.923 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:31.923Z,1574122111.923 [Radio_Surface](INFO): Join timeout helper Thread ID is 5820 2019-11-19T00:08:32.199Z,1574122112.199 [Radio_Surface](INFO): Powering down 2019-11-19T00:08:32.200Z,1574122112.200 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:32.200Z,1574122112.200 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:32.204Z,1574122112.204 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-11-19T00:08:32.204Z,1574122112.204 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:32.204Z,1574122112.204 [DataOverHttps](INFO): Join timeout helper Thread ID is 5821 2019-11-19T00:08:32.607Z,1574122112.607 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:32.607Z,1574122112.607 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:32.628Z,1574122112.628 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-11-19T00:08:32.628Z,1574122112.628 [logger ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:32.628Z,1574122112.628 [logger](INFO): Join timeout helper Thread ID is 5822 2019-11-19T00:08:32.629Z,1574122112.629 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:32.629Z,1574122112.629 [logger ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:32.630Z,1574122112.630 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-11-19T00:08:32.630Z,1574122112.630 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:32.630Z,1574122112.630 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-11-19T00:08:32.631Z,1574122112.631 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:32.631Z,1574122112.631 [controlThread](INFO): Join timeout helper Thread ID is 5823 2019-11-19T00:08:32.755Z,1574122112.755 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-19T00:08:32.755Z,1574122112.755 [controlThread](DEBUG): Uninitializing ControlThread 2019-11-19T00:08:32.756Z,1574122112.756 [AHRS_M2](INFO): Powering down 2019-11-19T00:08:32.827Z,1574122112.827 [DDM](INFO): Powering down 2019-11-19T00:08:32.920Z,1574122112.920 [DUSBL_Hydroid](INFO): Powering down 2019-11-19T00:08:33.011Z,1574122113.011 [Micromodem](INFO): Powering down 2019-11-19T00:08:33.107Z,1574122113.107 [NAL9602](INFO): Powering down 2019-11-19T00:08:33.179Z,1574122113.179 [RDI_Pathfinder](INFO): Powering down 2019-11-19T00:08:33.181Z,1574122113.181 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-11-19T00:08:33.182Z,1574122113.182 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-11-19T00:08:33.182Z,1574122113.182 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-11-19T00:08:33.182Z,1574122113.182 [MissionManager](INFO): Uninitializing Mission Default 2019-11-19T00:08:33.183Z,1574122113.183 [Default] Stopped 2019-11-19T00:08:33.183Z,1574122113.183 [Default](DEBUG): Aggregate::uninitialize Default 2019-11-19T00:08:33.183Z,1574122113.183 [Default:B.GoToSurface] Stopped 2019-11-19T00:08:33.183Z,1574122113.183 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-11-19T00:08:33.183Z,1574122113.183 [Default:CheckIn] Stopped 2019-11-19T00:08:33.183Z,1574122113.183 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-19T00:08:33.183Z,1574122113.183 [Default:CheckIn:C.Wait] Stopped 2019-11-19T00:08:33.183Z,1574122113.183 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-19T00:08:33.186Z,1574122113.186 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-11-19T00:08:33.186Z,1574122113.186 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-11-19T00:08:33.186Z,1574122113.186 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-11-19T00:08:33.187Z,1574122113.187 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-11-19T00:08:33.187Z,1574122113.187 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-11-19T00:08:33.187Z,1574122113.187 [BuoyancyServo](INFO): Powering down 2019-11-19T00:08:33.199Z,1574122113.199 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-11-19T00:08:33.199Z,1574122113.199 [ElevatorServo](INFO): Powering down 2019-11-19T00:08:33.200Z,1574122113.200 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-11-19T00:08:33.200Z,1574122113.200 [MassServo](INFO): Powering down 2019-11-19T00:08:33.201Z,1574122113.201 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-11-19T00:08:33.201Z,1574122113.201 [RudderServo](INFO): Powering down 2019-11-19T00:08:33.202Z,1574122113.202 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-11-19T00:08:33.202Z,1574122113.202 [ThrusterServo](INFO): Powering down 2019-11-19T00:08:33.202Z,1574122113.202 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-11-19T00:08:33.203Z,1574122113.203 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-11-19T00:08:33.203Z,1574122113.203 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-11-19T00:08:33.203Z,1574122113.203 [CBIT](DEBUG): Powering off loads. 2019-11-19T00:08:33.215Z,1574122113.215 [CBIT](DEBUG): Disabling WDT. 2019-11-19T00:08:33.227Z,1574122113.227 [CBIT](DEBUG): Opening all GF detection circuits. 2019-11-19T00:08:33.228Z,1574122113.228 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:33.273Z,1574122113.273 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:33.283Z,1574122113.283 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:33.333Z,1574122113.333 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:33.336Z,1574122113.336 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:33.409Z,1574122113.409 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-19T00:08:33.469Z,1574122113.469 [logger ThreadHandler](INFO): Thread cancelled.