2020-08-26T17:45:51.065Z,1598463951.065 [Supervisor](DEBUG): Initializing supervisor. 2020-08-26T17:45:51.068Z,1598463951.068 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2020-08-26T17:45:51.069Z,1598463951.069 [SyncHandler](INFO): Protected caller Thread ID is 2677 2020-08-26T17:45:51.069Z,1598463951.069 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2020-08-26T17:45:51.070Z,1598463951.070 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2020-08-26T17:45:51.070Z,1598463951.070 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2678 2020-08-26T17:45:51.074Z,1598463951.074 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2020-08-26T17:45:51.087Z,1598463951.087 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2020-08-26T17:45:51.088Z,1598463951.088 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2020-08-26T17:45:51.089Z,1598463951.089 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2679 2020-08-26T17:45:51.089Z,1598463951.089 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2020-08-26T17:45:51.090Z,1598463951.090 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2020-08-26T17:45:51.091Z,1598463951.091 [logger ThreadHandler](INFO): Protected caller Thread ID is 2680 2020-08-26T17:45:51.093Z,1598463951.093 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2020-08-26T17:45:51.093Z,1598463951.093 [Supervisor](INFO): Looking for Config files in directory: Config/ 2020-08-26T17:45:51.095Z,1598463951.095 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2020-08-26T17:45:51.254Z,1598463951.254 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2020-08-26T17:45:51.255Z,1598463951.255 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2020-08-26T17:45:51.841Z,1598463951.841 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2020-08-26T17:45:51.842Z,1598463951.842 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2020-08-26T17:45:52.031Z,1598463952.031 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2020-08-26T17:45:52.032Z,1598463952.032 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2020-08-26T17:45:52.131Z,1598463952.131 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2020-08-26T17:45:52.132Z,1598463952.132 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2020-08-26T17:45:52.233Z,1598463952.233 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2020-08-26T17:45:52.234Z,1598463952.234 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2020-08-26T17:45:52.315Z,1598463952.315 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2020-08-26T17:45:52.452Z,1598463952.452 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2020-08-26T17:45:52.452Z,1598463952.452 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2020-08-26T17:45:52.736Z,1598463952.736 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2020-08-26T17:45:52.736Z,1598463952.736 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2020-08-26T17:45:53.182Z,1598463953.182 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2020-08-26T17:45:53.182Z,1598463953.182 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2020-08-26T17:45:53.325Z,1598463953.325 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2020-08-26T17:45:53.326Z,1598463953.326 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2020-08-26T17:45:53.516Z,1598463953.516 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2020-08-26T17:45:53.517Z,1598463953.517 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2020-08-26T17:45:53.976Z,1598463953.976 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2020-08-26T17:45:53.977Z,1598463953.977 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2020-08-26T17:45:54.191Z,1598463954.191 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2020-08-26T17:45:54.192Z,1598463954.192 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2020-08-26T17:45:54.392Z,1598463954.392 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2020-08-26T17:45:54.392Z,1598463954.392 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2020-08-26T17:45:54.793Z,1598463954.793 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2020-08-26T17:45:54.793Z,1598463954.793 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2020-08-26T17:45:55.311Z,1598463955.311 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2020-08-26T17:45:55.313Z,1598463955.313 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/ 2020-08-26T17:45:55.314Z,1598463955.314 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg 2020-08-26T17:45:55.911Z,1598463955.911 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg 2020-08-26T17:45:56.075Z,1598463956.075 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg 2020-08-26T17:45:56.182Z,1598463956.182 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg 2020-08-26T17:45:56.268Z,1598463956.268 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg 2020-08-26T17:45:56.361Z,1598463956.361 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg 2020-08-26T17:45:56.560Z,1598463956.560 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg 2020-08-26T17:45:56.790Z,1598463956.790 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2020-08-26T17:45:56.790Z,1598463956.790 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg 2020-08-26T17:45:56.884Z,1598463956.884 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg 2020-08-26T17:45:56.983Z,1598463956.983 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg 2020-08-26T17:45:57.112Z,1598463957.112 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg 2020-08-26T17:45:57.211Z,1598463957.211 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2020-08-26T17:45:57.225Z,1598463957.225 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2020-08-26T17:45:57.321Z,1598463957.321 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2020-08-26T17:45:57.322Z,1598463957.322 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2020-08-26T17:45:57.384Z,1598463957.384 [VerticalControl](DEBUG): Construct VerticalControl. 2020-08-26T17:45:57.493Z,1598463957.493 [VerticalControl] Loaded 2020-08-26T17:45:57.493Z,1598463957.493 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2020-08-26T17:45:57.494Z,1598463957.494 [HorizontalControl](DEBUG): Construct HorizontalControl. 2020-08-26T17:45:57.572Z,1598463957.572 [HorizontalControl] Loaded 2020-08-26T17:45:57.572Z,1598463957.572 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2020-08-26T17:45:57.573Z,1598463957.573 [SpeedControl](DEBUG): Construct SpeedControl. 2020-08-26T17:45:57.578Z,1598463957.578 [SpeedControl] Loaded 2020-08-26T17:45:57.578Z,1598463957.578 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2020-08-26T17:45:57.579Z,1598463957.579 [LoopControl](DEBUG): Construct LoopControl. 2020-08-26T17:45:57.579Z,1598463957.579 [LoopControl] Loaded 2020-08-26T17:45:57.580Z,1598463957.580 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2020-08-26T17:45:57.580Z,1598463957.580 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2020-08-26T17:45:57.581Z,1598463957.581 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2020-08-26T17:45:57.636Z,1598463957.636 [DepthRateCalculator] Loaded 2020-08-26T17:45:57.636Z,1598463957.636 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2020-08-26T17:45:57.641Z,1598463957.641 [PitchRateCalculator] Loaded 2020-08-26T17:45:57.641Z,1598463957.641 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2020-08-26T17:45:57.656Z,1598463957.656 [SpeedCalculator] Loaded 2020-08-26T17:45:57.657Z,1598463957.657 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2020-08-26T17:45:57.677Z,1598463957.677 [TempGradientCalculator] Loaded 2020-08-26T17:45:57.677Z,1598463957.677 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2020-08-26T17:45:57.682Z,1598463957.682 [YawRateCalculator] Loaded 2020-08-26T17:45:57.683Z,1598463957.683 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2020-08-26T17:45:57.711Z,1598463957.711 [ElevatorOffsetCalculator] Loaded 2020-08-26T17:45:57.711Z,1598463957.711 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2020-08-26T17:45:57.711Z,1598463957.711 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2020-08-26T17:45:57.712Z,1598463957.712 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2020-08-26T17:45:57.752Z,1598463957.752 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2020-08-26T17:45:57.753Z,1598463957.753 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2020-08-26T17:45:57.881Z,1598463957.881 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2020-08-26T17:45:57.882Z,1598463957.882 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2020-08-26T17:45:58.216Z,1598463958.216 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2020-08-26T17:45:58.216Z,1598463958.216 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2020-08-26T17:45:58.340Z,1598463958.340 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2020-08-26T17:45:58.341Z,1598463958.341 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2020-08-26T17:45:58.773Z,1598463958.773 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2020-08-26T17:45:58.778Z,1598463958.778 [AHRS_M2](INFO): created writer for : platform_orientation 2020-08-26T17:45:58.781Z,1598463958.781 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2020-08-26T17:45:58.787Z,1598463958.787 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2020-08-26T17:45:58.787Z,1598463958.787 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2020-08-26T17:45:58.792Z,1598463958.792 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2020-08-26T17:45:58.793Z,1598463958.793 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2020-08-26T17:45:58.798Z,1598463958.798 [AHRS_M2](INFO): created writer for : platform_roll_angle 2020-08-26T17:45:58.868Z,1598463958.868 [AHRS_M2] Loaded 2020-08-26T17:45:58.868Z,1598463958.868 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2020-08-26T17:45:58.944Z,1598463958.944 [DataOverHttps] Loaded 2020-08-26T17:45:58.944Z,1598463958.944 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2020-08-26T17:45:58.945Z,1598463958.945 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4090D4E0 2020-08-26T17:45:58.945Z,1598463958.945 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2762 2020-08-26T17:45:58.975Z,1598463958.975 [Depth_Keller] Loaded 2020-08-26T17:45:58.976Z,1598463958.976 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2020-08-26T17:45:59.088Z,1598463959.088 [NAL9602] Loaded 2020-08-26T17:45:59.088Z,1598463959.088 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2020-08-26T17:45:59.136Z,1598463959.136 [Onboard] Loaded 2020-08-26T17:45:59.137Z,1598463959.137 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2020-08-26T17:45:59.138Z,1598463959.138 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4093D4E0 2020-08-26T17:45:59.138Z,1598463959.138 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 2763 2020-08-26T17:45:59.157Z,1598463959.157 [Radio_Surface] Loaded 2020-08-26T17:45:59.157Z,1598463959.157 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2020-08-26T17:45:59.158Z,1598463959.158 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4096D4E0 2020-08-26T17:45:59.159Z,1598463959.159 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2764 2020-08-26T17:45:59.308Z,1598463959.308 [DAT] Loaded 2020-08-26T17:45:59.309Z,1598463959.309 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2020-08-26T17:46:00.808Z,1598463960.808 [BPC1] Loaded 2020-08-26T17:46:00.808Z,1598463960.808 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2020-08-26T17:46:00.840Z,1598463960.840 [AMEcho] Loaded 2020-08-26T17:46:00.840Z,1598463960.840 [ComponentRegistry](DEBUG): SyncComponent "AMEcho" handled in the control thread. 2020-08-26T17:46:00.840Z,1598463960.840 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2020-08-26T17:46:00.841Z,1598463960.841 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2020-08-26T17:46:01.318Z,1598463961.318 [DeadReckonUsingMultipleVelocitySources] Loaded 2020-08-26T17:46:01.318Z,1598463961.318 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2020-08-26T17:46:01.338Z,1598463961.338 [NavChart] Loaded 2020-08-26T17:46:01.338Z,1598463961.338 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2020-08-26T17:46:01.342Z,1598463961.342 [UniversalFixResidualReporter] Loaded 2020-08-26T17:46:01.342Z,1598463961.342 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2020-08-26T17:46:01.343Z,1598463961.343 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2020-08-26T17:46:01.344Z,1598463961.344 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2020-08-26T17:46:01.506Z,1598463961.506 [SBIT](DEBUG): Construct Startup Built In Test. 2020-08-26T17:46:01.517Z,1598463961.517 [SBIT] Loaded 2020-08-26T17:46:01.517Z,1598463961.517 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2020-08-26T17:46:01.518Z,1598463961.518 [IBIT](DEBUG): Construct Initiated Built In Test. 2020-08-26T17:46:01.530Z,1598463961.530 [IBIT] Loaded 2020-08-26T17:46:01.531Z,1598463961.531 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2020-08-26T17:46:01.534Z,1598463961.534 [CBIT](DEBUG): Construct Continuous Built In Test. 2020-08-26T17:46:01.669Z,1598463961.669 [CBIT] Loaded 2020-08-26T17:46:01.669Z,1598463961.669 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2020-08-26T17:46:01.670Z,1598463961.670 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2020-08-26T17:46:01.670Z,1598463961.670 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2020-08-26T17:46:01.814Z,1598463961.814 [BuoyancyServo] Loaded 2020-08-26T17:46:01.814Z,1598463961.814 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2020-08-26T17:46:01.842Z,1598463961.842 [ElevatorServo] Loaded 2020-08-26T17:46:01.842Z,1598463961.842 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2020-08-26T17:46:01.870Z,1598463961.870 [MassServo] Loaded 2020-08-26T17:46:01.870Z,1598463961.870 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2020-08-26T17:46:01.897Z,1598463961.897 [RudderServo] Loaded 2020-08-26T17:46:01.897Z,1598463961.897 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2020-08-26T17:46:01.924Z,1598463961.924 [ThrusterServo] Loaded 2020-08-26T17:46:01.924Z,1598463961.924 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2020-08-26T17:46:01.925Z,1598463961.925 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2020-08-26T17:46:01.925Z,1598463961.925 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2020-08-26T17:46:01.955Z,1598463961.955 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2020-08-26T17:46:01.955Z,1598463961.955 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2020-08-26T17:46:02.275Z,1598463962.275 [BackSeatDriver] Loaded 2020-08-26T17:46:02.276Z,1598463962.276 [ComponentRegistry](DEBUG): Component "BackSeatDriver" handled in its own thread. 2020-08-26T17:46:02.277Z,1598463962.277 [BackSeatDriver ThreadHandler](DEBUG): Created PCaller Thread at 40B034E0 2020-08-26T17:46:02.277Z,1598463962.277 [BackSeatDriver ThreadHandler](INFO): Protected caller Thread ID is 2765 2020-08-26T17:46:02.305Z,1598463962.305 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2020-08-26T17:46:02.311Z,1598463962.311 [CTD_Seabird](INFO): created writer for : sea_water_density 2020-08-26T17:46:02.311Z,1598463962.311 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2020-08-26T17:46:02.316Z,1598463962.316 [CTD_Seabird](INFO): created writer for : depth 2020-08-26T17:46:02.316Z,1598463962.316 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2020-08-26T17:46:02.322Z,1598463962.322 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2020-08-26T17:46:02.323Z,1598463962.323 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2020-08-26T17:46:02.328Z,1598463962.328 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2020-08-26T17:46:02.329Z,1598463962.329 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2020-08-26T17:46:02.334Z,1598463962.334 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2020-08-26T17:46:02.334Z,1598463962.334 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2020-08-26T17:46:02.340Z,1598463962.340 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2020-08-26T17:46:02.340Z,1598463962.340 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2020-08-26T17:46:02.345Z,1598463962.345 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2020-08-26T17:46:02.373Z,1598463962.373 [CTD_Seabird] Loaded 2020-08-26T17:46:02.373Z,1598463962.373 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2020-08-26T17:46:02.374Z,1598463962.374 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B334E0 2020-08-26T17:46:02.375Z,1598463962.375 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 2766 2020-08-26T17:46:02.397Z,1598463962.397 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470 2020-08-26T17:46:02.397Z,1598463962.397 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470 2020-08-26T17:46:02.401Z,1598463962.401 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650 2020-08-26T17:46:02.401Z,1598463962.401 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650 2020-08-26T17:46:02.405Z,1598463962.405 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl 2020-08-26T17:46:02.406Z,1598463962.406 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl 2020-08-26T17:46:02.410Z,1598463962.410 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm 2020-08-26T17:46:02.410Z,1598463962.410 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm 2020-08-26T17:46:02.414Z,1598463962.414 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm 2020-08-26T17:46:02.414Z,1598463962.414 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm 2020-08-26T17:46:02.419Z,1598463962.419 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm 2020-08-26T17:46:02.419Z,1598463962.419 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm 2020-08-26T17:46:02.423Z,1598463962.423 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm 2020-08-26T17:46:02.423Z,1598463962.423 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm 2020-08-26T17:46:02.428Z,1598463962.428 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.432Z,1598463962.432 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.433Z,1598463962.433 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.433Z,1598463962.433 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.437Z,1598463962.437 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.437Z,1598463962.437 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.441Z,1598463962.441 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.441Z,1598463962.441 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-08-26T17:46:02.446Z,1598463962.446 [WetLabsBB2FL] Loaded 2020-08-26T17:46:02.446Z,1598463962.446 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2020-08-26T17:46:02.447Z,1598463962.447 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B634E0 2020-08-26T17:46:02.447Z,1598463962.447 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2767 2020-08-26T17:46:02.448Z,1598463962.448 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2020-08-26T17:46:02.452Z,1598463962.452 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2020-08-26T17:46:02.453Z,1598463962.453 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2020-08-26T17:46:02.459Z,1598463962.459 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2020-08-26T17:46:02.460Z,1598463962.460 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B934E0 2020-08-26T17:46:02.461Z,1598463962.461 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2768 2020-08-26T17:46:02.465Z,1598463962.465 [Supervisor](INFO): Main Thread ID is 2080 2020-08-26T17:46:02.465Z,1598463962.465 [Supervisor](DEBUG): Running supervisor. 2020-08-26T17:46:02.466Z,1598463962.466 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2769 2020-08-26T17:46:02.468Z,1598463962.468 [controlThread ThreadHandler](INFO): Handler Thread ID is 2770 2020-08-26T17:46:02.469Z,1598463962.469 [controlThread](DEBUG): Initializing ControlThread 2020-08-26T17:46:02.470Z,1598463962.470 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2020-08-26T17:46:02.471Z,1598463962.471 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2020-08-26T17:46:02.472Z,1598463962.472 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2020-08-26T17:46:02.473Z,1598463962.473 [LoopControl](DEBUG): Initialize LoopControlComponent. 2020-08-26T17:46:02.473Z,1598463962.473 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2020-08-26T17:46:02.473Z,1598463962.473 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2020-08-26T17:46:02.474Z,1598463962.474 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2020-08-26T17:46:02.474Z,1598463962.474 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2020-08-26T17:46:02.474Z,1598463962.474 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2020-08-26T17:46:02.475Z,1598463962.475 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2020-08-26T17:46:02.480Z,1598463962.480 [NavChart](DEBUG): Initialize NavChart Navigation. 2020-08-26T17:46:02.480Z,1598463962.480 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2020-08-26T17:46:02.481Z,1598463962.481 [SBIT](INFO): Initialize SBIT Component. 2020-08-26T17:46:02.481Z,1598463962.481 [SBIT](IMPORTANT): git: 2020-08-18a-28-g0d8891e 2020-08-26T17:46:02.481Z,1598463962.481 [SBIT](INFO): git hash: 0d8891e4c136abd7dd8b76b3c91e52f720a234d8 2020-08-26T17:46:02.481Z,1598463962.481 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2020-08-26T17:46:02.483Z,1598463962.483 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 Kernel Reported: #1 PREEMPT Thu Aug 6 12:04:53 PDT 2020 2020-08-26T17:46:02.484Z,1598463962.484 [SBIT](INFO): Beginning SBIT in 65.000000 seconds. 2020-08-26T17:46:02.484Z,1598463962.484 [IBIT](INFO): Initialize IBIT Component. 2020-08-26T17:46:02.485Z,1598463962.485 [CBIT](DEBUG): Initialize CBIT Component. 2020-08-26T17:46:02.486Z,1598463962.486 [logger ThreadHandler](INFO): Handler Thread ID is 2771 2020-08-26T17:46:02.498Z,1598463962.498 [CBIT](DEBUG): Initialized mux pins. 2020-08-26T17:46:02.499Z,1598463962.499 [CBIT](DEBUG): Initializing the watchdog timer. 2020-08-26T17:46:02.503Z,1598463962.503 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2772 2020-08-26T17:46:02.504Z,1598463962.504 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2020-08-26T17:46:02.511Z,1598463962.511 [Onboard ThreadHandler](INFO): Handler Thread ID is 2773 2020-08-26T17:46:02.523Z,1598463962.523 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2020-08-26T17:46:02.523Z,1598463962.523 [CBIT](DEBUG): Initializing heartbeat. 2020-08-26T17:46:02.533Z,1598463962.533 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2774 2020-08-26T17:46:02.542Z,1598463962.542 [BackSeatDriver ThreadHandler](INFO): Handler Thread ID is 2775 2020-08-26T17:46:02.552Z,1598463962.552 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 2776 2020-08-26T17:46:02.552Z,1598463962.552 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2020-08-26T17:46:02.556Z,1598463962.556 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2778 2020-08-26T17:46:02.557Z,1598463962.557 [WetLabsBB2FL](INFO): Powering down 2020-08-26T17:46:02.583Z,1598463962.583 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2779 2020-08-26T17:46:02.589Z,1598463962.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2020-08-26T17:46:02.589Z,1598463962.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2020-08-26T17:46:02.589Z,1598463962.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2020-08-26T17:46:02.589Z,1598463962.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2020-08-26T17:46:02.589Z,1598463962.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2020-08-26T17:46:02.589Z,1598463962.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2020-08-26T17:46:02.590Z,1598463962.590 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2020-08-26T17:46:02.590Z,1598463962.590 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2020-08-26T17:46:02.590Z,1598463962.590 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2020-08-26T17:46:02.590Z,1598463962.590 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2020-08-26T17:46:02.590Z,1598463962.590 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2020-08-26T17:46:02.591Z,1598463962.591 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2020-08-26T17:46:02.591Z,1598463962.591 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2020-08-26T17:46:02.591Z,1598463962.591 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2020-08-26T17:46:02.591Z,1598463962.591 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2020-08-26T17:46:02.591Z,1598463962.591 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2020-08-26T17:46:02.594Z,1598463962.594 [CBIT](DEBUG): Deactivating GF circuits. 2020-08-26T17:46:02.594Z,1598463962.594 [CBIT](DEBUG): Deactivating emergency mode. 2020-08-26T17:46:02.630Z,1598463962.630 [CBIT](DEBUG): Backplane powered. 2020-08-26T17:46:02.632Z,1598463962.632 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2020-08-26T17:46:02.644Z,1598463962.644 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2020-08-26T17:46:02.668Z,1598463962.668 [MissionManager](DEBUG): 2020-08-26T17:46:02.669Z,1598463962.669 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2020-08-26T17:46:02.739Z,1598463962.739 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2020-08-26T17:46:02.741Z,1598463962.741 [Default:A.Wait](DEBUG): Construct Wait. 2020-08-26T17:46:02.742Z,1598463962.742 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2020-08-26T17:46:02.781Z,1598463962.781 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2020-08-26T17:46:02.795Z,1598463962.795 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2020-08-26T17:46:02.801Z,1598463962.801 [Default:E.Execute](DEBUG): Construct Execute. 2020-08-26T17:46:02.820Z,1598463962.820 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2020-08-26T17:46:02.824Z,1598463962.824 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,NAL9602,DAT,BPC1,AMEcho,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2020-08-26T17:46:02.850Z,1598463962.850 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2020-08-26T17:46:02.907Z,1598463962.907 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar 2020-08-26T17:46:02.910Z,1598463962.910 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2020-08-26T17:46:02.910Z,1598463962.910 [DAT](INFO): Powering up 2020-08-26T17:46:02.910Z,1598463962.910 [DAT](DEBUG): Initializing DAT. 2020-08-26T17:46:02.955Z,1598463962.955 [Radio_Surface](INFO): Powering up 2020-08-26T17:46:02.959Z,1598463962.959 [AMEcho](INFO): Powering up 2020-08-26T17:46:02.967Z,1598463962.967 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2020-08-26T17:46:02.980Z,1598463962.980 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-08-26T17:46:03.019Z,1598463963.019 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2020-08-26T17:46:03.031Z,1598463963.031 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2020-08-26T17:46:03.032Z,1598463963.032 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-08-26T17:46:03.043Z,1598463963.043 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-08-26T17:46:03.044Z,1598463963.044 [MassServo](DEBUG): Initializing EZServoServo. 2020-08-26T17:46:03.055Z,1598463963.055 [MassServo](DEBUG): Initializing MassServo. 2020-08-26T17:46:03.056Z,1598463963.056 [RudderServo](DEBUG): Initializing EZServoServo. 2020-08-26T17:46:03.067Z,1598463963.067 [RudderServo](DEBUG): Initializing RudderServo. 2020-08-26T17:46:03.068Z,1598463963.068 [ThrusterServo](DEBUG): Initializing EZServoServo. 2020-08-26T17:46:03.079Z,1598463963.079 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2020-08-26T17:46:03.443Z,1598463963.443 [AMEcho](INFO): Powering down 2020-08-26T17:46:03.455Z,1598463963.455 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-08-26T17:46:03.643Z,1598463963.643 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-08-26T17:46:03.962Z,1598463963.962 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2020-08-26T17:46:03.963Z,1598463963.963 [RudderServo](FAULT): Rudder failed to initialize 2020-08-26T17:46:03.963Z,1598463963.963 [RudderServo] Communications Fault, FailCount= 1 2020-08-26T17:46:03.963Z,1598463963.963 [RudderServo](ERROR): Communications Fault 2020-08-26T17:46:04.074Z,1598463964.074 [CBIT](ERROR): Communications Fault in component: RudderServo 2020-08-26T17:46:04.235Z,1598463964.235 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2020-08-26T17:46:04.236Z,1598463964.236 [RudderServo](INFO): Powering down 2020-08-26T17:46:04.903Z,1598463964.903 [RudderServo](DEBUG): Initializing EZServoServo. 2020-08-26T17:46:05.214Z,1598463965.214 [RudderServo](DEBUG): Initializing RudderServo. 2020-08-26T17:46:05.218Z,1598463965.218 [CBIT](INFO): Clearing failed state for component RudderServo 2020-08-26T17:46:05.218Z,1598463965.218 [RudderServo] No Fault, FailCount= 1 2020-08-26T17:46:13.380Z,1598463973.380 [DAT](INFO): DAT read: 2020-08-26T17:46:13.382Z,1598463973.382 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2020-08-26T17:46:14.592Z,1598463974.592 [DAT](INFO): DAT read: MF Frequency Band 2020-08-26T17:46:14.593Z,1598463974.593 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.12.21 2020-08-26T17:46:14.594Z,1598463974.594 [DAT](INFO): DAT read: Aug 26 2020 17:45:51 2020-08-26T17:46:15.400Z,1598463975.400 [DAT](INFO): DAT read: Features enabled [Bearing] 2020-08-26T17:46:15.402Z,1598463975.402 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-26T17:46:15.402Z,1598463975.402 [DAT](INFO): commRate: 800 2020-08-26T17:46:15.402Z,1598463975.402 [DAT](INFO): commRate: 800 2020-08-26T17:46:15.804Z,1598463975.804 [DAT](INFO): entering command mode 2020-08-26T17:46:16.208Z,1598463976.208 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:16.612Z,1598463976.612 [DAT](INFO): DAT read: 2020-08-26T17:46:16.612Z,1598463976.612 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:17.016Z,1598463977.016 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:17.420Z,1598463977.420 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:17.824Z,1598463977.824 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:18.228Z,1598463978.228 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:18.632Z,1598463978.632 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:19.036Z,1598463979.036 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:19.440Z,1598463979.440 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:19.844Z,1598463979.844 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:20.248Z,1598463980.248 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:20.652Z,1598463980.652 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:21.056Z,1598463981.056 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:21.460Z,1598463981.460 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:21.864Z,1598463981.864 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:22.268Z,1598463982.268 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:22.672Z,1598463982.672 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:23.076Z,1598463983.076 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:23.480Z,1598463983.480 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:23.884Z,1598463983.884 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:24.288Z,1598463984.288 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:24.692Z,1598463984.692 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:25.097Z,1598463985.097 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:25.500Z,1598463985.500 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:25.904Z,1598463985.904 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:26.308Z,1598463986.308 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:26.712Z,1598463986.712 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:27.116Z,1598463987.116 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:27.516Z,1598463987.516 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:27.924Z,1598463987.924 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:28.334Z,1598463988.334 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:28.733Z,1598463988.733 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:29.141Z,1598463989.141 [NAL9602](INFO): Powering up NAL9602 2020-08-26T17:46:29.143Z,1598463989.143 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:29.544Z,1598463989.544 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:29.944Z,1598463989.944 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:30.348Z,1598463990.348 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:30.752Z,1598463990.752 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:31.152Z,1598463991.152 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-26T17:46:31.152Z,1598463991.152 [DAT](FAULT): failed to enter command mode 2020-08-26T17:46:31.560Z,1598463991.560 [DAT](INFO): entering command mode 2020-08-26T17:46:31.976Z,1598463991.976 [DAT](INFO): DAT read: user:1> 2020-08-26T17:46:31.977Z,1598463991.977 [DAT](INFO): DAT read: Command '+++' not found 2020-08-26T17:46:31.977Z,1598463991.977 [DAT](INFO): DAT read: Error 2020-08-26T17:46:31.978Z,1598463991.978 [DAT](INFO): setting verbose to 3 2020-08-26T17:46:32.364Z,1598463992.364 [DAT](INFO): DAT read: user:2> 2020-08-26T17:46:32.365Z,1598463992.365 [DAT](INFO): DAT read: Verbose | 3 2020-08-26T17:46:32.365Z,1598463992.365 [DAT](INFO): set verbose to 3 2020-08-26T17:46:32.366Z,1598463992.366 [DAT](INFO): setting DatVerbose to 27440 2020-08-26T17:46:32.772Z,1598463992.772 [DAT](INFO): DAT read: user:3> 2020-08-26T17:46:32.773Z,1598463992.773 [DAT](INFO): DAT read: DatVerbose | 27440 2020-08-26T17:46:32.773Z,1598463992.773 [DAT](INFO): set DatVerbose to 27440 2020-08-26T17:46:32.774Z,1598463992.774 [DAT](INFO): setting transmit power to 8 2020-08-26T17:46:33.176Z,1598463993.176 [DAT](INFO): DAT read: user:4> 2020-08-26T17:46:33.177Z,1598463993.177 [DAT](INFO): DAT read: TxPower | 8 (Max) 2020-08-26T17:46:33.177Z,1598463993.177 [DAT](INFO): set transmit power to 8 2020-08-26T17:46:33.177Z,1598463993.177 [DAT](INFO): setting local address to 9 2020-08-26T17:46:33.576Z,1598463993.576 [DAT](INFO): DAT read: user:5> 2020-08-26T17:46:33.577Z,1598463993.577 [DAT](INFO): DAT read: LocalAddr | 9 2020-08-26T17:46:33.577Z,1598463993.577 [DAT](INFO): set local address to 9 2020-08-26T17:46:40.048Z,1598464000.048 [NAL9602](INFO): NAL9602 initialized 2020-08-26T17:47:07.937Z,1598464027.937 [SBIT](IMPORTANT): Beginning Startup BIT 2020-08-26T17:47:07.957Z,1598464027.957 [CBIT](IMPORTANT): Beginning ground fault scan 2020-08-26T17:47:18.950Z,1598464038.950 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.011236 CHAN A1 (24V): -0.000984 CHAN A2 (12V): -0.007223 CHAN A3 (5V): -0.002225 CHAN B0 (3.3V): 0.000346 CHAN B1 (3.15aV): -0.000135 CHAN B2 (3.15bV): -0.000357 CHAN B3 (GND): 0.002187 OPEN: 0.005844 Full Scale Calc: 4.765 mA, -1.589 mA 2020-08-26T17:48:01.704Z,1598464081.704 [SBIT](IMPORTANT): SBIT PASSED 2020-08-26T17:48:01.705Z,1598464081.705 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2020-08-26T17:48:01.705Z,1598464081.705 [SBIT](IMPORTANT): BackSeatDriver.loadAtStartup=1 bool; 2020-08-26T17:48:01.706Z,1598464081.706 [SBIT](IMPORTANT): CBIT.gf24Offset=145 microampere; 2020-08-26T17:48:01.706Z,1598464081.706 [SBIT](IMPORTANT): DAT.sbdAddress=6 enum; 2020-08-26T17:48:01.706Z,1598464081.706 [SBIT](IMPORTANT): DAT.surfaceThreshold=-1 meter; 2020-08-26T17:48:01.706Z,1598464081.706 [SBIT](IMPORTANT): DAT.verbosity=3 count; 2020-08-26T17:48:01.726Z,1598464081.726 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2020-08-26T17:48:01.727Z,1598464081.727 [SBIT](IMPORTANT): Express none ThrusterServo.component_avgCurrent; 2020-08-26T17:48:01.727Z,1598464081.727 [SBIT](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 1.000000 liter_per_second; 2020-08-26T17:48:01.727Z,1598464081.727 [SBIT](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter; 2020-08-26T17:48:01.727Z,1598464081.727 [SBIT](IMPORTANT): RDI_Pathfinder.loadAtStartup=0 bool; 2020-08-26T17:48:01.727Z,1598464081.727 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=344.685708 cubic_centimeter; 2020-08-26T17:48:01.727Z,1598464081.727 [SBIT](IMPORTANT): VerticalControl.massDefault=11.293600 millimeter; 2020-08-26T17:48:01.727Z,1598464081.727 [SBIT](IMPORTANT): WetLabsUBAT.loadAtStartup=0 bool; 2020-08-26T17:48:02.095Z,1598464082.095 [MissionManager](IMPORTANT): Started mission Startup 2020-08-26T17:48:02.095Z,1598464082.095 [Startup] Running Loop=1 2020-08-26T17:48:02.095Z,1598464082.095 [Startup](DEBUG): Aggregate::initialize Startup 2020-08-26T17:48:02.096Z,1598464082.096 [Startup:A.GoToSurface] Running Loop=1 2020-08-26T17:48:02.096Z,1598464082.096 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-26T17:48:02.096Z,1598464082.096 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-26T17:48:02.097Z,1598464082.097 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-26T17:48:02.097Z,1598464082.097 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-26T17:48:02.097Z,1598464082.097 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-26T17:48:02.098Z,1598464082.098 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-26T17:48:02.099Z,1598464082.099 [Startup:StartupSatComms] Running Loop=1 2020-08-26T17:48:02.099Z,1598464082.099 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2020-08-26T17:48:02.099Z,1598464082.099 [Startup:StartupSatComms:A] Running Loop=1 2020-08-26T17:48:02.488Z,1598464082.488 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2020-08-26T17:48:02.877Z,1598464082.877 [AMEcho](INFO): Powering up 2020-08-26T17:48:32.862Z,1598464112.862 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005846 2020-08-26T17:49:02.280Z,1598464142.280 [Startup:StartupSatComms:A](INFO): Timed out from 2020-08-26T17:48:02.1Z 2020-08-26T17:49:02.280Z,1598464142.280 [Startup:StartupSatComms:A] Stopped 2020-08-26T17:49:02.280Z,1598464142.280 [Startup:StartupSatComms:B] Running Loop=1 2020-08-26T17:49:02.694Z,1598464142.694 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2020-08-26T17:49:02.694Z,1598464142.694 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T17:49:02.700Z,1598464142.700 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-08-26T17:49:02.752Z,1598464142.752 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T17:49:03.373Z,1598464143.373 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T17:49:03.373Z,1598464143.373 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2020-08-26T17:49:04.428Z,1598464144.428 [DAT](INFO): DAT read: user:6>Rx Time:17:48:09.6404 2020-08-26T17:49:04.429Z,1598464144.429 [DAT](INFO): DAT read: 2020-08-26T17:49:04.429Z,1598464144.429 [DAT](INFO): DAT read: $Packet for address 0 2020-08-26T17:49:04.430Z,1598464144.430 [DAT](INFO): received a packet notification 2020-08-26T17:49:05.918Z,1598464145.918 [DAT](INFO): #Outgoing data=1 2020-08-26T17:49:05.919Z,1598464145.919 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-26T17:49:06.043Z,1598464146.043 [DAT](INFO): setting remote address to 6 2020-08-26T17:49:06.093Z,1598464146.093 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20200826T162253/Courier0025.lzma 2020-08-26T17:49:06.423Z,1598464146.423 [DAT](INFO): DAT read: 2020-08-26T17:49:06.424Z,1598464146.424 [DAT](INFO): DAT read: RemoteAddr | 6 2020-08-26T17:49:06.425Z,1598464146.425 [DAT](INFO): set remote address to 6 2020-08-26T17:49:06.425Z,1598464146.425 [DAT](INFO): entering online mode 2020-08-26T17:49:06.813Z,1598464146.813 [DAT](INFO): DAT read: user:7> 2020-08-26T17:49:06.813Z,1598464146.813 [DAT](INFO): DAT read: 2020-08-26T17:49:06.815Z,1598464146.815 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-26T17:49:06.815Z,1598464146.815 [DAT](INFO): commRate: 800 2020-08-26T17:49:06.815Z,1598464146.815 [DAT](INFO): online mode acknowledged 2020-08-26T17:49:06.816Z,1598464146.816 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-26T17:49:07.108Z,1598464147.108 [DataOverHttps](INFO): Moved sent file to Logs/20200826T162253/Courier0025.lzma.bak 2020-08-26T17:49:07.108Z,1598464147.108 [DataOverHttps](INFO): SBD MOMSN=12620763 2020-08-26T17:49:10.060Z,1598464150.060 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:48:50.3371 2020-08-26T17:49:10.060Z,1598464150.060 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-26T17:49:22.434Z,1598464162.434 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20200826T174551/Courier0000.lzma 2020-08-26T17:49:23.436Z,1598464163.436 [DataOverHttps](INFO): Moved sent file to Logs/20200826T174551/Courier0000.lzma.bak 2020-08-26T17:49:23.436Z,1598464163.436 [DataOverHttps](INFO): SBD MOMSN=12620771 2020-08-26T17:49:27.016Z,1598464167.016 [DAT](FAULT): Ack receipt timeout failure. 2020-08-26T17:49:27.016Z,1598464167.016 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-26T17:49:28.445Z,1598464168.445 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-26T17:49:28.589Z,1598464168.589 [Startup:StartupSatComms:B] Stopped 2020-08-26T17:49:28.589Z,1598464168.589 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2020-08-26T17:49:28.589Z,1598464168.589 [Startup:StartupSatComms] Stopped 2020-08-26T17:49:28.590Z,1598464168.590 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2020-08-26T17:49:28.595Z,1598464168.595 [Startup](INFO): Completed Startup 2020-08-26T17:49:28.595Z,1598464168.595 [MissionManager](INFO): Startup is completed. 2020-08-26T17:49:28.595Z,1598464168.595 [MissionManager](INFO): Uninitializing Mission Startup 2020-08-26T17:49:28.595Z,1598464168.595 [Startup] Stopped 2020-08-26T17:49:28.595Z,1598464168.595 [Startup](DEBUG): Aggregate::uninitialize Startup 2020-08-26T17:49:28.595Z,1598464168.595 [Startup:A.GoToSurface] Stopped 2020-08-26T17:49:28.595Z,1598464168.595 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-26T17:49:28.731Z,1598464168.731 [MissionManager](IMPORTANT): Started mission Default 2020-08-26T17:49:28.731Z,1598464168.731 [Default] Running Loop=1 2020-08-26T17:49:28.731Z,1598464168.731 [Default](DEBUG): Aggregate::initialize Default 2020-08-26T17:49:28.732Z,1598464168.732 [Default:B.GoToSurface] Running Loop=1 2020-08-26T17:49:28.732Z,1598464168.732 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-26T17:49:28.732Z,1598464168.732 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-26T17:49:28.732Z,1598464168.732 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-26T17:49:28.732Z,1598464168.732 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-26T17:49:28.733Z,1598464168.733 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-26T17:49:28.733Z,1598464168.733 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-26T17:49:28.733Z,1598464168.733 [Default:A.Wait] Running Loop=1 2020-08-26T17:49:28.733Z,1598464168.733 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-26T17:49:29.294Z,1598464169.294 [AMEcho](INFO): Powering down 2020-08-26T17:49:30.279Z,1598464170.279 [AMEcho](INFO): Powering up 2020-08-26T17:49:40.888Z,1598464180.888 [DataOverHttps](INFO): Sending 271 bytes from file Logs/20200826T162253/Express0014.lzma 2020-08-26T17:49:41.888Z,1598464181.888 [DataOverHttps](INFO): Moved sent file to Logs/20200826T162253/Express0014.lzma.bak 2020-08-26T17:49:41.889Z,1598464181.889 [DataOverHttps](INFO): SBD MOMSN=12620774 2020-08-26T17:49:42.066Z,1598464182.066 [Default:A.Wait](INFO): Done Waiting. 2020-08-26T17:49:42.066Z,1598464182.066 [Default:A.Wait] Stopped 2020-08-26T17:49:42.067Z,1598464182.067 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-26T17:49:42.400Z,1598464182.400 [Default:CheckIn] Running Loop=1 2020-08-26T17:49:42.400Z,1598464182.400 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-26T17:49:42.400Z,1598464182.400 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-26T17:49:42.790Z,1598464182.790 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2020-08-26T17:51:43.156Z,1598464303.156 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-08-26T17:51:45.711Z,1598464305.711 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-26T17:52:03.770Z,1598464323.770 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2020-08-26T17:52:03.770Z,1598464323.770 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T17:52:03.780Z,1598464323.780 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T17:52:04.203Z,1598464324.203 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T17:52:04.203Z,1598464324.203 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2020-08-26T17:52:32.123Z,1598464352.123 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2020-08-26T17:52:39.381Z,1598464359.381 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2020-08-26T17:54:18.324Z,1598464458.324 [CommandLine](IMPORTANT): got command get DAT.surfaceThreshold 2020-08-26T17:54:18.325Z,1598464458.325 [CommandLine](IMPORTANT): DAT.surfaceThreshold -1.000000 m 2020-08-26T17:54:20.573Z,1598464460.573 [CommandLine](IMPORTANT): got command get depth 2020-08-26T17:54:20.573Z,1598464460.573 [CommandLine](IMPORTANT): depth -0.233698 m 2020-08-26T17:54:27.029Z,1598464467.029 [CommandLine](IMPORTANT): got command get DAT.verbosity 2020-08-26T17:54:27.030Z,1598464467.030 [CommandLine](IMPORTANT): DAT.verbosity 3 count 2020-08-26T17:54:35.676Z,1598464475.676 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2020-08-26T17:54:35.679Z,1598464475.679 [BPC1](INFO): Received data from all battery sticks. 2020-08-26T17:54:42.540Z,1598464482.540 [Default:CheckIn:Read_GPS](INFO): Timed out from 2020-08-26T17:49:42.4Z 2020-08-26T17:54:42.541Z,1598464482.541 [Default:CheckIn:Read_GPS] Stopped 2020-08-26T17:54:42.541Z,1598464482.541 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-26T17:54:42.992Z,1598464482.992 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-08-26T17:54:44.553Z,1598464484.553 [DAT](INFO): DAT read: Rx Time:17:53:19.4949 2020-08-26T17:54:44.553Z,1598464484.553 [DAT](INFO): received an acoustic signal 2020-08-26T17:54:44.554Z,1598464484.554 [DAT](INFO): DAT read: 2020-08-26T17:54:44.621Z,1598464484.621 [DAT](INFO): DAT read: $Packet for address 0 2020-08-26T17:54:44.621Z,1598464484.621 [DAT](INFO): received a packet notification 2020-08-26T17:54:44.637Z,1598464484.637 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-26T17:54:48.200Z,1598464488.200 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:54:28.1850 2020-08-26T17:54:48.200Z,1598464488.200 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-26T17:54:50.254Z,1598464490.254 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20200826T174551/Courier0004.lzma 2020-08-26T17:54:51.256Z,1598464491.256 [DataOverHttps](INFO): Moved sent file to Logs/20200826T174551/Courier0004.lzma.bak 2020-08-26T17:54:51.256Z,1598464491.256 [DataOverHttps](INFO): SBD MOMSN=12620787 2020-08-26T17:55:04.771Z,1598464504.771 [DAT](FAULT): Ack receipt timeout failure. 2020-08-26T17:55:04.771Z,1598464504.771 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-26T17:55:04.778Z,1598464504.778 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2020-08-26T17:55:04.779Z,1598464504.779 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T17:55:04.793Z,1598464504.793 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T17:55:06.626Z,1598464506.626 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-26T17:55:06.646Z,1598464506.646 [Default:CheckIn:Read_Iridium] Stopped 2020-08-26T17:55:06.646Z,1598464506.646 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-26T17:55:06.646Z,1598464506.646 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-26T17:55:06.666Z,1598464506.666 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T17:55:06.666Z,1598464506.666 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2020-08-26T17:55:08.995Z,1598464508.995 [DataOverHttps](INFO): Sending 267 bytes from file Logs/20200826T162253/Express0017.lzma 2020-08-26T17:55:09.996Z,1598464509.996 [DataOverHttps](INFO): Moved sent file to Logs/20200826T162253/Express0017.lzma.bak 2020-08-26T17:55:09.996Z,1598464509.996 [DataOverHttps](INFO): SBD MOMSN=12620792 2020-08-26T17:56:41.232Z,1598464601.232 [NAL9602](FAULT): GPS failed to acquire within timeout. 2020-08-26T17:56:41.232Z,1598464601.232 [NAL9602] Data Fault, FailCount= 1 2020-08-26T17:56:41.232Z,1598464601.232 [NAL9602](ERROR): Data Fault 2020-08-26T17:56:41.247Z,1598464601.247 [CBIT](ERROR): Data Fault in component: NAL9602 2020-08-26T17:56:41.632Z,1598464601.632 [NAL9602](INFO): Powering down 2020-08-26T17:56:42.114Z,1598464602.114 [CommandLine](IMPORTANT): got command strobe off 2020-08-26T17:56:42.114Z,1598464602.114 [CommandLine](IMPORTANT): Deactivating strobe 2020-08-26T17:56:42.447Z,1598464602.447 [CBIT](INFO): Clearing failed state for component NAL9602 2020-08-26T17:56:42.447Z,1598464602.447 [NAL9602] No Fault, FailCount= 1 2020-08-26T17:57:11.932Z,1598464631.932 [NAL9602](INFO): Powering up NAL9602 2020-08-26T17:57:22.840Z,1598464642.840 [NAL9602](INFO): NAL9602 initialized 2020-08-26T17:58:06.887Z,1598464686.887 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2020-08-26T17:58:06.887Z,1598464686.887 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T17:58:06.901Z,1598464686.901 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T17:58:07.291Z,1598464687.291 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T17:58:07.291Z,1598464687.291 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2020-08-26T18:00:06.883Z,1598464806.883 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-08-26T18:00:06.883Z,1598464806.883 [Default:CheckIn:C.Wait] Stopped 2020-08-26T18:00:06.883Z,1598464806.883 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-26T18:00:06.883Z,1598464806.883 [Default:CheckIn:D] Running Loop=1 2020-08-26T18:00:07.299Z,1598464807.299 [Default:CheckIn:D] Stopped 2020-08-26T18:00:07.299Z,1598464807.299 [Default:CheckIn:E] Running Loop=1 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.642800 min 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn:E] Stopped 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn] Stopped 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn](INFO): Running loop #2 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn] Running Loop=2 2020-08-26T18:00:07.704Z,1598464807.704 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-26T18:00:07.705Z,1598464807.705 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-26T18:01:07.898Z,1598464867.898 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2020-08-26T18:01:07.899Z,1598464867.899 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T18:01:07.917Z,1598464867.917 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T18:01:08.304Z,1598464868.304 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T18:01:08.304Z,1598464868.304 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2020-08-26T18:04:08.887Z,1598465048.887 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6 2020-08-26T18:04:08.887Z,1598465048.887 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T18:04:08.897Z,1598465048.897 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T18:04:09.307Z,1598465049.307 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T18:04:09.307Z,1598465049.307 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6 2020-08-26T18:05:07.864Z,1598465107.864 [Default:CheckIn:Read_GPS](INFO): Timed out from 2020-08-26T18:00:07.7Z 2020-08-26T18:05:07.864Z,1598465107.864 [Default:CheckIn:Read_GPS] Stopped 2020-08-26T18:05:07.864Z,1598465107.864 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-26T18:05:09.880Z,1598465109.880 [DAT](INFO): DAT read: Rx Time:17:55:02.0964 2020-08-26T18:05:09.881Z,1598465109.881 [DAT](INFO): received an acoustic signal 2020-08-26T18:05:09.881Z,1598465109.881 [DAT](INFO): DAT read: 2020-08-26T18:05:09.882Z,1598465109.882 [DAT](INFO): DAT read: $Packet for address 0 2020-08-26T18:05:09.883Z,1598465109.883 [DAT](INFO): received a packet notification 2020-08-26T18:05:09.895Z,1598465109.895 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-26T18:05:13.119Z,1598465113.119 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:04:53.4308 2020-08-26T18:05:13.119Z,1598465113.119 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-26T18:05:14.766Z,1598465114.766 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20200826T174551/Courier0007.lzma 2020-08-26T18:05:15.768Z,1598465115.768 [DataOverHttps](INFO): Moved sent file to Logs/20200826T174551/Courier0007.lzma.bak 2020-08-26T18:05:15.768Z,1598465115.768 [DataOverHttps](INFO): SBD MOMSN=12621015 2020-08-26T18:05:30.064Z,1598465130.064 [DAT](FAULT): Ack receipt timeout failure. 2020-08-26T18:05:30.064Z,1598465130.064 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-26T18:05:31.916Z,1598465131.916 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-26T18:05:31.937Z,1598465131.937 [Default:CheckIn:Read_Iridium] Stopped 2020-08-26T18:05:31.937Z,1598465131.937 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-26T18:05:31.938Z,1598465131.938 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-26T18:05:33.308Z,1598465133.308 [DataOverHttps](INFO): Sending 177 bytes from file Logs/20200826T162253/Express0020.lzma 2020-08-26T18:05:34.308Z,1598465134.308 [DataOverHttps](INFO): Moved sent file to Logs/20200826T162253/Express0020.lzma.bak 2020-08-26T18:05:34.308Z,1598465134.308 [DataOverHttps](INFO): SBD MOMSN=12621017 2020-08-26T18:07:09.762Z,1598465229.762 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7 2020-08-26T18:07:09.762Z,1598465229.762 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T18:07:09.773Z,1598465229.773 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T18:07:10.183Z,1598465230.183 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T18:07:10.183Z,1598465230.183 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7 2020-08-26T18:07:24.692Z,1598465244.692 [NAL9602](FAULT): GPS failed to acquire within timeout. 2020-08-26T18:07:24.692Z,1598465244.692 [NAL9602] Data Fault, FailCount= 2 2020-08-26T18:07:24.692Z,1598465244.692 [NAL9602](ERROR): Data Fault 2020-08-26T18:07:24.720Z,1598465244.720 [CBIT](ERROR): Data Fault in component: NAL9602 2020-08-26T18:07:25.091Z,1598465245.091 [NAL9602](INFO): Powering down 2020-08-26T18:07:25.915Z,1598465245.915 [CBIT](INFO): Clearing failed state for component NAL9602 2020-08-26T18:07:25.915Z,1598465245.915 [NAL9602] No Fault, FailCount= 2 2020-08-26T18:07:55.392Z,1598465275.392 [NAL9602](INFO): Powering up NAL9602 2020-08-26T18:08:06.300Z,1598465286.300 [NAL9602](INFO): NAL9602 initialized 2020-08-26T18:10:10.741Z,1598465410.741 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8 2020-08-26T18:10:10.741Z,1598465410.741 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-26T18:10:10.754Z,1598465410.754 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-26T18:10:11.163Z,1598465411.163 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-26T18:10:11.163Z,1598465411.163 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8 2020-08-26T18:10:32.185Z,1598465432.185 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-08-26T18:10:32.185Z,1598465432.185 [Default:CheckIn:C.Wait] Stopped 2020-08-26T18:10:32.185Z,1598465432.185 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-26T18:10:32.186Z,1598465432.186 [Default:CheckIn:D] Running Loop=1 2020-08-26T18:10:32.608Z,1598465432.608 [Default:CheckIn:D] Stopped 2020-08-26T18:10:32.608Z,1598465432.608 [Default:CheckIn:E] Running Loop=1 2020-08-26T18:10:33.016Z,1598465433.016 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.064612 min 2020-08-26T18:10:33.016Z,1598465433.016 [Default:CheckIn:E] Stopped 2020-08-26T18:10:33.016Z,1598465433.016 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-08-26T18:10:33.016Z,1598465433.016 [Default:CheckIn] Stopped 2020-08-26T18:10:33.017Z,1598465433.017 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-26T18:10:33.017Z,1598465433.017 [Default:CheckIn](INFO): Running loop #3 2020-08-26T18:10:33.017Z,1598465433.017 [Default:CheckIn] Running Loop=3 2020-08-26T18:10:33.017Z,1598465433.017 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-26T18:10:33.017Z,1598465433.017 [Default:CheckIn:Read_GPS] Running Loop=1