2020-08-25T17:35:44.837Z,1598376944.837 [Supervisor](DEBUG): Initializing supervisor. 2020-08-25T17:35:44.840Z,1598376944.840 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2020-08-25T17:35:44.840Z,1598376944.840 [SyncHandler](INFO): Protected caller Thread ID is 2203 2020-08-25T17:35:44.840Z,1598376944.840 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2020-08-25T17:35:44.841Z,1598376944.841 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2020-08-25T17:35:44.842Z,1598376944.842 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2204 2020-08-25T17:35:44.845Z,1598376944.845 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2020-08-25T17:35:44.859Z,1598376944.859 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2020-08-25T17:35:44.859Z,1598376944.859 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2020-08-25T17:35:44.860Z,1598376944.860 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2205 2020-08-25T17:35:44.860Z,1598376944.860 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2020-08-25T17:35:44.861Z,1598376944.861 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2020-08-25T17:35:44.862Z,1598376944.862 [logger ThreadHandler](INFO): Protected caller Thread ID is 2206 2020-08-25T17:35:44.864Z,1598376944.864 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2020-08-25T17:35:44.864Z,1598376944.864 [Supervisor](INFO): Looking for Config files in directory: Config/ 2020-08-25T17:35:44.866Z,1598376944.866 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2020-08-25T17:35:45.031Z,1598376945.031 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2020-08-25T17:35:45.032Z,1598376945.032 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2020-08-25T17:35:45.622Z,1598376945.622 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2020-08-25T17:35:45.623Z,1598376945.623 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2020-08-25T17:35:45.817Z,1598376945.817 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2020-08-25T17:35:45.817Z,1598376945.817 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2020-08-25T17:35:45.920Z,1598376945.920 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2020-08-25T17:35:45.921Z,1598376945.921 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2020-08-25T17:35:46.026Z,1598376946.026 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2020-08-25T17:35:46.027Z,1598376946.027 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2020-08-25T17:35:46.112Z,1598376946.112 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2020-08-25T17:35:46.252Z,1598376946.252 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2020-08-25T17:35:46.252Z,1598376946.252 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2020-08-25T17:35:46.540Z,1598376946.540 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2020-08-25T17:35:46.540Z,1598376946.540 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2020-08-25T17:35:46.990Z,1598376946.990 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2020-08-25T17:35:46.991Z,1598376946.991 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2020-08-25T17:35:47.137Z,1598376947.137 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2020-08-25T17:35:47.138Z,1598376947.138 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2020-08-25T17:35:47.332Z,1598376947.332 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2020-08-25T17:35:47.332Z,1598376947.332 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2020-08-25T17:35:47.796Z,1598376947.796 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2020-08-25T17:35:47.796Z,1598376947.796 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2020-08-25T17:35:48.013Z,1598376948.013 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2020-08-25T17:35:48.014Z,1598376948.014 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2020-08-25T17:35:48.218Z,1598376948.218 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2020-08-25T17:35:48.218Z,1598376948.218 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2020-08-25T17:35:48.627Z,1598376948.627 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2020-08-25T17:35:48.627Z,1598376948.627 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2020-08-25T17:35:49.422Z,1598376949.422 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2020-08-25T17:35:49.424Z,1598376949.424 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/ 2020-08-25T17:35:49.425Z,1598376949.425 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg 2020-08-25T17:35:49.515Z,1598376949.515 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg 2020-08-25T17:35:49.680Z,1598376949.680 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg 2020-08-25T17:35:49.790Z,1598376949.790 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg 2020-08-25T17:35:49.880Z,1598376949.880 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg 2020-08-25T17:35:49.977Z,1598376949.977 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg 2020-08-25T17:35:50.180Z,1598376950.180 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg 2020-08-25T17:35:50.413Z,1598376950.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2020-08-25T17:35:50.414Z,1598376950.414 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg 2020-08-25T17:35:50.512Z,1598376950.512 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg 2020-08-25T17:35:50.613Z,1598376950.613 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg 2020-08-25T17:35:50.747Z,1598376950.747 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg 2020-08-25T17:35:50.850Z,1598376950.850 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2020-08-25T17:35:50.863Z,1598376950.863 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2020-08-25T17:35:50.958Z,1598376950.958 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2020-08-25T17:35:50.958Z,1598376950.958 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2020-08-25T17:35:51.020Z,1598376951.020 [VerticalControl](DEBUG): Construct VerticalControl. 2020-08-25T17:35:51.129Z,1598376951.129 [VerticalControl] Loaded 2020-08-25T17:35:51.129Z,1598376951.129 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2020-08-25T17:35:51.130Z,1598376951.130 [HorizontalControl](DEBUG): Construct HorizontalControl. 2020-08-25T17:35:51.207Z,1598376951.207 [HorizontalControl] Loaded 2020-08-25T17:35:51.207Z,1598376951.207 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2020-08-25T17:35:51.208Z,1598376951.208 [SpeedControl](DEBUG): Construct SpeedControl. 2020-08-25T17:35:51.213Z,1598376951.213 [SpeedControl] Loaded 2020-08-25T17:35:51.213Z,1598376951.213 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2020-08-25T17:35:51.214Z,1598376951.214 [LoopControl](DEBUG): Construct LoopControl. 2020-08-25T17:35:51.214Z,1598376951.214 [LoopControl] Loaded 2020-08-25T17:35:51.215Z,1598376951.215 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2020-08-25T17:35:51.215Z,1598376951.215 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2020-08-25T17:35:51.216Z,1598376951.216 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2020-08-25T17:35:51.270Z,1598376951.270 [DepthRateCalculator] Loaded 2020-08-25T17:35:51.270Z,1598376951.270 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2020-08-25T17:35:51.275Z,1598376951.275 [PitchRateCalculator] Loaded 2020-08-25T17:35:51.275Z,1598376951.275 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2020-08-25T17:35:51.290Z,1598376951.290 [SpeedCalculator] Loaded 2020-08-25T17:35:51.291Z,1598376951.291 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2020-08-25T17:35:51.311Z,1598376951.311 [TempGradientCalculator] Loaded 2020-08-25T17:35:51.311Z,1598376951.311 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2020-08-25T17:35:51.316Z,1598376951.316 [YawRateCalculator] Loaded 2020-08-25T17:35:51.316Z,1598376951.316 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2020-08-25T17:35:51.345Z,1598376951.345 [ElevatorOffsetCalculator] Loaded 2020-08-25T17:35:51.345Z,1598376951.345 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2020-08-25T17:35:51.345Z,1598376951.345 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2020-08-25T17:35:51.346Z,1598376951.346 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2020-08-25T17:35:51.386Z,1598376951.386 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2020-08-25T17:35:51.386Z,1598376951.386 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2020-08-25T17:35:51.513Z,1598376951.513 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2020-08-25T17:35:51.513Z,1598376951.513 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2020-08-25T17:35:51.840Z,1598376951.840 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2020-08-25T17:35:51.841Z,1598376951.841 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2020-08-25T17:35:51.964Z,1598376951.964 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2020-08-25T17:35:51.964Z,1598376951.964 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2020-08-25T17:35:52.413Z,1598376952.413 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2020-08-25T17:35:52.418Z,1598376952.418 [AHRS_M2](INFO): created writer for : platform_orientation 2020-08-25T17:35:52.420Z,1598376952.420 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2020-08-25T17:35:52.425Z,1598376952.425 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2020-08-25T17:35:52.426Z,1598376952.426 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2020-08-25T17:35:52.430Z,1598376952.430 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2020-08-25T17:35:52.431Z,1598376952.431 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2020-08-25T17:35:52.436Z,1598376952.436 [AHRS_M2](INFO): created writer for : platform_roll_angle 2020-08-25T17:35:52.506Z,1598376952.506 [AHRS_M2] Loaded 2020-08-25T17:35:52.506Z,1598376952.506 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2020-08-25T17:35:52.581Z,1598376952.581 [DataOverHttps] Loaded 2020-08-25T17:35:52.582Z,1598376952.582 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2020-08-25T17:35:52.583Z,1598376952.583 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4090A4E0 2020-08-25T17:35:52.583Z,1598376952.583 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2288 2020-08-25T17:35:52.613Z,1598376952.613 [Depth_Keller] Loaded 2020-08-25T17:35:52.613Z,1598376952.613 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2020-08-25T17:35:52.724Z,1598376952.724 [NAL9602] Loaded 2020-08-25T17:35:52.724Z,1598376952.724 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2020-08-25T17:35:52.771Z,1598376952.771 [Onboard] Loaded 2020-08-25T17:35:52.772Z,1598376952.772 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2020-08-25T17:35:52.773Z,1598376952.773 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4093A4E0 2020-08-25T17:35:52.773Z,1598376952.773 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 2289 2020-08-25T17:35:52.792Z,1598376952.792 [Radio_Surface] Loaded 2020-08-25T17:35:52.792Z,1598376952.792 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2020-08-25T17:35:52.793Z,1598376952.793 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4096A4E0 2020-08-25T17:35:52.793Z,1598376952.793 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2290 2020-08-25T17:35:52.941Z,1598376952.941 [DAT] Loaded 2020-08-25T17:35:52.941Z,1598376952.941 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2020-08-25T17:35:54.859Z,1598376954.859 [BPC1] Loaded 2020-08-25T17:35:54.859Z,1598376954.859 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2020-08-25T17:35:54.860Z,1598376954.860 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2020-08-25T17:35:54.860Z,1598376954.860 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2020-08-25T17:35:54.993Z,1598376954.993 [DeadReckonUsingMultipleVelocitySources] Loaded 2020-08-25T17:35:54.994Z,1598376954.994 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2020-08-25T17:35:55.014Z,1598376955.014 [NavChart] Loaded 2020-08-25T17:35:55.014Z,1598376955.014 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2020-08-25T17:35:55.018Z,1598376955.018 [UniversalFixResidualReporter] Loaded 2020-08-25T17:35:55.018Z,1598376955.018 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2020-08-25T17:35:55.018Z,1598376955.018 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2020-08-25T17:35:55.019Z,1598376955.019 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2020-08-25T17:35:55.174Z,1598376955.174 [SBIT](DEBUG): Construct Startup Built In Test. 2020-08-25T17:35:55.185Z,1598376955.185 [SBIT] Loaded 2020-08-25T17:35:55.185Z,1598376955.185 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2020-08-25T17:35:55.186Z,1598376955.186 [IBIT](DEBUG): Construct Initiated Built In Test. 2020-08-25T17:35:55.198Z,1598376955.198 [IBIT] Loaded 2020-08-25T17:35:55.198Z,1598376955.198 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2020-08-25T17:35:55.201Z,1598376955.201 [CBIT](DEBUG): Construct Continuous Built In Test. 2020-08-25T17:35:55.336Z,1598376955.336 [CBIT] Loaded 2020-08-25T17:35:55.336Z,1598376955.336 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2020-08-25T17:35:55.336Z,1598376955.336 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2020-08-25T17:35:55.337Z,1598376955.337 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2020-08-25T17:35:55.478Z,1598376955.478 [BuoyancyServo] Loaded 2020-08-25T17:35:55.479Z,1598376955.479 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2020-08-25T17:35:55.507Z,1598376955.507 [ElevatorServo] Loaded 2020-08-25T17:35:55.507Z,1598376955.507 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2020-08-25T17:35:55.534Z,1598376955.534 [MassServo] Loaded 2020-08-25T17:35:55.534Z,1598376955.534 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2020-08-25T17:35:55.561Z,1598376955.561 [RudderServo] Loaded 2020-08-25T17:35:55.561Z,1598376955.561 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2020-08-25T17:35:55.587Z,1598376955.587 [ThrusterServo] Loaded 2020-08-25T17:35:55.588Z,1598376955.588 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2020-08-25T17:35:55.588Z,1598376955.588 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2020-08-25T17:35:55.589Z,1598376955.589 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2020-08-25T17:35:55.617Z,1598376955.617 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2020-08-25T17:35:55.618Z,1598376955.618 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2020-08-25T17:35:55.933Z,1598376955.933 [BackSeatDriver] Loaded 2020-08-25T17:35:55.933Z,1598376955.933 [ComponentRegistry](DEBUG): Component "BackSeatDriver" handled in its own thread. 2020-08-25T17:35:55.934Z,1598376955.934 [BackSeatDriver ThreadHandler](DEBUG): Created PCaller Thread at 40B004E0 2020-08-25T17:35:55.935Z,1598376955.935 [BackSeatDriver ThreadHandler](INFO): Protected caller Thread ID is 2291 2020-08-25T17:35:55.962Z,1598376955.962 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2020-08-25T17:35:55.967Z,1598376955.967 [CTD_Seabird](INFO): created writer for : sea_water_density 2020-08-25T17:35:55.968Z,1598376955.968 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2020-08-25T17:35:55.973Z,1598376955.973 [CTD_Seabird](INFO): created writer for : depth 2020-08-25T17:35:55.973Z,1598376955.973 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2020-08-25T17:35:55.978Z,1598376955.978 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2020-08-25T17:35:55.978Z,1598376955.978 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2020-08-25T17:35:55.984Z,1598376955.984 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2020-08-25T17:35:55.984Z,1598376955.984 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2020-08-25T17:35:55.989Z,1598376955.989 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2020-08-25T17:35:55.990Z,1598376955.990 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2020-08-25T17:35:55.995Z,1598376955.995 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2020-08-25T17:35:55.996Z,1598376955.996 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2020-08-25T17:35:56.001Z,1598376956.001 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2020-08-25T17:35:56.028Z,1598376956.028 [CTD_Seabird] Loaded 2020-08-25T17:35:56.029Z,1598376956.029 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2020-08-25T17:35:56.030Z,1598376956.030 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B304E0 2020-08-25T17:35:56.030Z,1598376956.030 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 2292 2020-08-25T17:35:56.052Z,1598376956.052 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470 2020-08-25T17:35:56.052Z,1598376956.052 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470 2020-08-25T17:35:56.056Z,1598376956.056 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650 2020-08-25T17:35:56.057Z,1598376956.057 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650 2020-08-25T17:35:56.061Z,1598376956.061 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl 2020-08-25T17:35:56.061Z,1598376956.061 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl 2020-08-25T17:35:56.065Z,1598376956.065 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm 2020-08-25T17:35:56.065Z,1598376956.065 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm 2020-08-25T17:35:56.069Z,1598376956.069 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm 2020-08-25T17:35:56.069Z,1598376956.069 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm 2020-08-25T17:35:56.074Z,1598376956.074 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm 2020-08-25T17:35:56.074Z,1598376956.074 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm 2020-08-25T17:35:56.078Z,1598376956.078 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm 2020-08-25T17:35:56.078Z,1598376956.078 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm 2020-08-25T17:35:56.082Z,1598376956.082 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.086Z,1598376956.086 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.087Z,1598376956.087 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.087Z,1598376956.087 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.091Z,1598376956.091 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.091Z,1598376956.091 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.095Z,1598376956.095 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.096Z,1598376956.096 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2020-08-25T17:35:56.100Z,1598376956.100 [WetLabsBB2FL] Loaded 2020-08-25T17:35:56.100Z,1598376956.100 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2020-08-25T17:35:56.101Z,1598376956.101 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B604E0 2020-08-25T17:35:56.101Z,1598376956.101 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2293 2020-08-25T17:35:56.102Z,1598376956.102 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2020-08-25T17:35:56.106Z,1598376956.106 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2020-08-25T17:35:56.107Z,1598376956.107 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2020-08-25T17:35:56.114Z,1598376956.114 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2020-08-25T17:35:56.115Z,1598376956.115 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B904E0 2020-08-25T17:35:56.115Z,1598376956.115 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2294 2020-08-25T17:35:56.120Z,1598376956.120 [Supervisor](INFO): Main Thread ID is 715 2020-08-25T17:35:56.120Z,1598376956.120 [Supervisor](DEBUG): Running supervisor. 2020-08-25T17:35:56.120Z,1598376956.120 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2295 2020-08-25T17:35:56.123Z,1598376956.123 [controlThread ThreadHandler](INFO): Handler Thread ID is 2296 2020-08-25T17:35:56.123Z,1598376956.123 [controlThread](DEBUG): Initializing ControlThread 2020-08-25T17:35:56.124Z,1598376956.124 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2020-08-25T17:35:56.126Z,1598376956.126 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2020-08-25T17:35:56.126Z,1598376956.126 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2020-08-25T17:35:56.127Z,1598376956.127 [LoopControl](DEBUG): Initialize LoopControlComponent. 2020-08-25T17:35:56.127Z,1598376956.127 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2020-08-25T17:35:56.128Z,1598376956.128 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2020-08-25T17:35:56.128Z,1598376956.128 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2020-08-25T17:35:56.128Z,1598376956.128 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2020-08-25T17:35:56.129Z,1598376956.129 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2020-08-25T17:35:56.129Z,1598376956.129 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2020-08-25T17:35:56.136Z,1598376956.136 [NavChart](DEBUG): Initialize NavChart Navigation. 2020-08-25T17:35:56.136Z,1598376956.136 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2020-08-25T17:35:56.136Z,1598376956.136 [SBIT](INFO): Initialize SBIT Component. 2020-08-25T17:35:56.137Z,1598376956.137 [SBIT](IMPORTANT): git: 2020-08-18a-28-g0d8891e 2020-08-25T17:35:56.137Z,1598376956.137 [SBIT](INFO): git hash: 0d8891e4c136abd7dd8b76b3c91e52f720a234d8 2020-08-25T17:35:56.137Z,1598376956.137 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2020-08-25T17:35:56.138Z,1598376956.138 [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-25T17:35:56.140Z,1598376956.140 [SBIT](INFO): Beginning SBIT in 65.000000 seconds. 2020-08-25T17:35:56.140Z,1598376956.140 [IBIT](INFO): Initialize IBIT Component. 2020-08-25T17:35:56.141Z,1598376956.141 [CBIT](DEBUG): Initialize CBIT Component. 2020-08-25T17:35:56.142Z,1598376956.142 [logger ThreadHandler](INFO): Handler Thread ID is 2297 2020-08-25T17:35:56.154Z,1598376956.154 [CBIT](DEBUG): Initialized mux pins. 2020-08-25T17:35:56.155Z,1598376956.155 [CBIT](DEBUG): Initializing the watchdog timer. 2020-08-25T17:35:56.159Z,1598376956.159 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2298 2020-08-25T17:35:56.160Z,1598376956.160 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2020-08-25T17:35:56.167Z,1598376956.167 [Onboard ThreadHandler](INFO): Handler Thread ID is 2299 2020-08-25T17:35:56.178Z,1598376956.178 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2020-08-25T17:35:56.178Z,1598376956.178 [CBIT](DEBUG): Initializing heartbeat. 2020-08-25T17:35:56.184Z,1598376956.184 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2300 2020-08-25T17:35:56.203Z,1598376956.203 [BackSeatDriver ThreadHandler](INFO): Handler Thread ID is 2301 2020-08-25T17:35:56.215Z,1598376956.215 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 2302 2020-08-25T17:35:56.215Z,1598376956.215 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2020-08-25T17:35:56.220Z,1598376956.220 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2304 2020-08-25T17:35:56.221Z,1598376956.221 [WetLabsBB2FL](INFO): Powering down 2020-08-25T17:35:56.247Z,1598376956.247 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2305 2020-08-25T17:35:56.250Z,1598376956.250 [CBIT](DEBUG): Deactivating GF circuits. 2020-08-25T17:35:56.250Z,1598376956.250 [CBIT](DEBUG): Deactivating emergency mode. 2020-08-25T17:35:56.255Z,1598376956.255 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2020-08-25T17:35:56.255Z,1598376956.255 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2020-08-25T17:35:56.255Z,1598376956.255 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2020-08-25T17:35:56.255Z,1598376956.255 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2020-08-25T17:35:56.255Z,1598376956.255 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2020-08-25T17:35:56.256Z,1598376956.256 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2020-08-25T17:35:56.256Z,1598376956.256 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2020-08-25T17:35:56.256Z,1598376956.256 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2020-08-25T17:35:56.256Z,1598376956.256 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2020-08-25T17:35:56.256Z,1598376956.256 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2020-08-25T17:35:56.256Z,1598376956.256 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2020-08-25T17:35:56.256Z,1598376956.256 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2020-08-25T17:35:56.257Z,1598376956.257 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2020-08-25T17:35:56.257Z,1598376956.257 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2020-08-25T17:35:56.257Z,1598376956.257 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2020-08-25T17:35:56.257Z,1598376956.257 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2020-08-25T17:35:56.286Z,1598376956.286 [CBIT](DEBUG): Backplane powered. 2020-08-25T17:35:56.288Z,1598376956.288 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2020-08-25T17:35:56.308Z,1598376956.308 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2020-08-25T17:35:56.319Z,1598376956.319 [MissionManager](DEBUG): 2020-08-25T17:35:56.320Z,1598376956.320 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2020-08-25T17:35:56.396Z,1598376956.396 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2020-08-25T17:35:56.397Z,1598376956.397 [Default:A.Wait](DEBUG): Construct Wait. 2020-08-25T17:35:56.415Z,1598376956.415 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2020-08-25T17:35:56.426Z,1598376956.426 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2020-08-25T17:35:56.445Z,1598376956.445 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2020-08-25T17:35:56.478Z,1598376956.478 [Default:E.Execute](DEBUG): Construct Execute. 2020-08-25T17:35:56.481Z,1598376956.481 [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-25T17:35:56.485Z,1598376956.485 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,NAL9602,DAT,BPC1,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-25T17:35:56.502Z,1598376956.502 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2020-08-25T17:35:56.537Z,1598376956.537 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar 2020-08-25T17:35:56.540Z,1598376956.540 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2020-08-25T17:35:56.540Z,1598376956.540 [DAT](INFO): Powering up 2020-08-25T17:35:56.540Z,1598376956.540 [DAT](DEBUG): Initializing DAT. 2020-08-25T17:35:56.591Z,1598376956.591 [DepthRateCalculator](ERROR): Depth measurement is not active 2020-08-25T17:35:56.607Z,1598376956.607 [Radio_Surface](INFO): Powering up 2020-08-25T17:35:56.612Z,1598376956.612 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2020-08-25T17:35:56.619Z,1598376956.619 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2020-08-25T17:35:56.643Z,1598376956.643 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2020-08-25T17:35:56.644Z,1598376956.644 [ElevatorServo](DEBUG): Initializing EZServoServo. 2020-08-25T17:35:56.655Z,1598376956.655 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2020-08-25T17:35:56.656Z,1598376956.656 [MassServo](DEBUG): Initializing EZServoServo. 2020-08-25T17:35:56.667Z,1598376956.667 [MassServo](DEBUG): Initializing MassServo. 2020-08-25T17:35:56.668Z,1598376956.668 [RudderServo](DEBUG): Initializing EZServoServo. 2020-08-25T17:35:56.679Z,1598376956.679 [RudderServo](DEBUG): Initializing RudderServo. 2020-08-25T17:35:56.680Z,1598376956.680 [ThrusterServo](DEBUG): Initializing EZServoServo. 2020-08-25T17:35:56.691Z,1598376956.691 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2020-08-25T17:35:57.658Z,1598376957.658 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2020-08-25T17:35:57.659Z,1598376957.659 [RudderServo](FAULT): Rudder failed to initialize 2020-08-25T17:35:57.659Z,1598376957.659 [RudderServo] Communications Fault, FailCount= 1 2020-08-25T17:35:57.659Z,1598376957.659 [RudderServo](ERROR): Communications Fault 2020-08-25T17:35:57.770Z,1598376957.770 [CBIT](ERROR): Communications Fault in component: RudderServo 2020-08-25T17:35:57.935Z,1598376957.935 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2020-08-25T17:35:57.935Z,1598376957.935 [RudderServo](INFO): Powering down 2020-08-25T17:35:58.597Z,1598376958.597 [RudderServo](DEBUG): Initializing EZServoServo. 2020-08-25T17:35:58.715Z,1598376958.715 [RudderServo](DEBUG): Initializing RudderServo. 2020-08-25T17:35:58.719Z,1598376958.719 [CBIT](INFO): Clearing failed state for component RudderServo 2020-08-25T17:35:58.719Z,1598376958.719 [RudderServo] No Fault, FailCount= 1 2020-08-25T17:36:03.247Z,1598376963.247 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit. 2020-08-25T17:36:07.076Z,1598376967.076 [DAT](INFO): DAT read: 2020-08-25T17:36:07.078Z,1598376967.078 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2020-08-25T17:36:08.288Z,1598376968.288 [DAT](INFO): DAT read: MF Frequency Band 2020-08-25T17:36:08.289Z,1598376968.289 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.12.21 2020-08-25T17:36:08.290Z,1598376968.290 [DAT](INFO): DAT read: Aug 25 2020 17:35:44 2020-08-25T17:36:09.096Z,1598376969.096 [DAT](INFO): DAT read: Features enabled [Bearing] 2020-08-25T17:36:09.098Z,1598376969.098 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-25T17:36:09.098Z,1598376969.098 [DAT](INFO): commRate: 800 2020-08-25T17:36:09.098Z,1598376969.098 [DAT](INFO): commRate: 800 2020-08-25T17:36:09.500Z,1598376969.500 [DAT](INFO): entering command mode 2020-08-25T17:36:09.904Z,1598376969.904 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:10.308Z,1598376970.308 [DAT](INFO): DAT read: 2020-08-25T17:36:10.308Z,1598376970.308 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:10.712Z,1598376970.712 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:11.116Z,1598376971.116 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:11.520Z,1598376971.520 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:11.924Z,1598376971.924 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:12.328Z,1598376972.328 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:12.732Z,1598376972.732 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:13.136Z,1598376973.136 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:13.540Z,1598376973.540 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:13.948Z,1598376973.948 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:14.348Z,1598376974.348 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:14.752Z,1598376974.752 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:15.156Z,1598376975.156 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:15.560Z,1598376975.560 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:15.964Z,1598376975.964 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:16.368Z,1598376976.368 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:16.772Z,1598376976.772 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:17.176Z,1598376977.176 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:17.588Z,1598376977.588 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:17.990Z,1598376977.990 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:18.388Z,1598376978.388 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:18.792Z,1598376978.792 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:19.196Z,1598376979.196 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:19.604Z,1598376979.604 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:19.000Z,1598376980.000 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:20.408Z,1598376980.408 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:20.812Z,1598376980.812 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:21.220Z,1598376981.220 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:21.620Z,1598376981.620 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:22.024Z,1598376982.024 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:22.432Z,1598376982.432 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:22.836Z,1598376982.836 [NAL9602](INFO): Powering up NAL9602 2020-08-25T17:36:22.837Z,1598376982.837 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:23.236Z,1598376983.236 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:23.640Z,1598376983.640 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:24.044Z,1598376984.044 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:24.452Z,1598376984.452 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:24.852Z,1598376984.852 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T17:36:24.852Z,1598376984.852 [DAT](FAULT): failed to enter command mode 2020-08-25T17:36:25.256Z,1598376985.256 [DAT](INFO): entering command mode 2020-08-25T17:36:25.660Z,1598376985.660 [DAT](INFO): DAT read: user:1> 2020-08-25T17:36:25.661Z,1598376985.661 [DAT](INFO): DAT read: Command '+++' not found 2020-08-25T17:36:25.661Z,1598376985.661 [DAT](INFO): DAT read: Error 2020-08-25T17:36:25.662Z,1598376985.662 [DAT](INFO): setting verbose to 3 2020-08-25T17:36:26.065Z,1598376986.065 [DAT](INFO): DAT read: user:2> 2020-08-25T17:36:26.066Z,1598376986.066 [DAT](INFO): DAT read: Verbose | 3 2020-08-25T17:36:26.067Z,1598376986.067 [DAT](INFO): set verbose to 3 2020-08-25T17:36:26.067Z,1598376986.067 [DAT](INFO): setting DatVerbose to 27440 2020-08-25T17:36:26.468Z,1598376986.468 [DAT](INFO): DAT read: user:3> 2020-08-25T17:36:26.469Z,1598376986.469 [DAT](INFO): DAT read: DatVerbose | 27440 2020-08-25T17:36:26.469Z,1598376986.469 [DAT](INFO): set DatVerbose to 27440 2020-08-25T17:36:26.470Z,1598376986.470 [DAT](INFO): setting transmit power to 8 2020-08-25T17:36:26.872Z,1598376986.872 [DAT](INFO): DAT read: user:4> 2020-08-25T17:36:26.873Z,1598376986.873 [DAT](INFO): DAT read: TxPower | 8 (Max) 2020-08-25T17:36:26.873Z,1598376986.873 [DAT](INFO): set transmit power to 8 2020-08-25T17:36:26.874Z,1598376986.874 [DAT](INFO): setting local address to 9 2020-08-25T17:36:27.276Z,1598376987.276 [DAT](INFO): DAT read: user:5> 2020-08-25T17:36:27.277Z,1598376987.277 [DAT](INFO): DAT read: LocalAddr | 9 2020-08-25T17:36:27.277Z,1598376987.277 [DAT](INFO): set local address to 9 2020-08-25T17:36:33.740Z,1598376993.740 [NAL9602](INFO): NAL9602 initialized 2020-08-25T17:37:01.640Z,1598377021.640 [SBIT](IMPORTANT): Beginning Startup BIT 2020-08-25T17:37:01.645Z,1598377021.645 [CBIT](IMPORTANT): Beginning ground fault scan 2020-08-25T17:37:12.646Z,1598377032.646 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.009834 CHAN A1 (24V): -0.001167 CHAN A2 (12V): -0.007395 CHAN A3 (5V): -0.002346 CHAN B0 (3.3V): -0.000304 CHAN B1 (3.15aV): 0.000227 CHAN B2 (3.15bV): 0.000281 CHAN B3 (GND): 0.002513 OPEN: 0.005967 Full Scale Calc: 4.765 mA, -1.589 mA 2020-08-25T17:37:55.375Z,1598377075.375 [SBIT](IMPORTANT): SBIT PASSED 2020-08-25T17:37:55.375Z,1598377075.375 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2020-08-25T17:37:55.376Z,1598377075.376 [SBIT](IMPORTANT): BackSeatDriver.loadAtStartup=1 bool; 2020-08-25T17:37:55.376Z,1598377075.376 [SBIT](IMPORTANT): CBIT.gf24Offset=145 microampere; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): DAT.verbosity=3 count; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): Express none ThrusterServo.component_avgCurrent; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 1.000000 liter_per_second; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): RDI_Pathfinder.loadAtStartup=0 bool; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=344.685708 cubic_centimeter; 2020-08-25T17:37:55.377Z,1598377075.377 [SBIT](IMPORTANT): VerticalControl.massDefault=11.293600 millimeter; 2020-08-25T17:37:55.378Z,1598377075.378 [SBIT](IMPORTANT): WetLabsUBAT.loadAtStartup=0 bool; 2020-08-25T17:37:55.779Z,1598377075.779 [MissionManager](IMPORTANT): Started mission Startup 2020-08-25T17:37:55.779Z,1598377075.779 [Startup] Running Loop=1 2020-08-25T17:37:55.780Z,1598377075.780 [Startup](DEBUG): Aggregate::initialize Startup 2020-08-25T17:37:55.780Z,1598377075.780 [Startup:A.GoToSurface] Running Loop=1 2020-08-25T17:37:55.780Z,1598377075.780 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-25T17:37:55.780Z,1598377075.780 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-25T17:37:55.781Z,1598377075.781 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-25T17:37:55.781Z,1598377075.781 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-25T17:37:55.781Z,1598377075.781 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-25T17:37:55.782Z,1598377075.782 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-25T17:37:55.783Z,1598377075.783 [Startup:StartupSatComms] Running Loop=1 2020-08-25T17:37:55.783Z,1598377075.783 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2020-08-25T17:37:55.783Z,1598377075.783 [Startup:StartupSatComms:A] Running Loop=1 2020-08-25T17:37:56.184Z,1598377076.184 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2020-08-25T17:38:55.964Z,1598377135.964 [Startup:StartupSatComms:A](INFO): Timed out from 2020-08-25T17:37:55.8Z 2020-08-25T17:38:55.964Z,1598377135.964 [Startup:StartupSatComms:A] Stopped 2020-08-25T17:38:55.964Z,1598377135.964 [Startup:StartupSatComms:B] Running Loop=1 2020-08-25T17:38:56.374Z,1598377136.374 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2020-08-25T17:38:56.375Z,1598377136.375 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2020-08-25T17:38:56.376Z,1598377136.376 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-08-25T17:38:56.390Z,1598377136.390 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2020-08-25T17:38:56.792Z,1598377136.792 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2020-08-25T17:38:56.792Z,1598377136.792 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2020-08-25T17:39:19.229Z,1598377159.229 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004903 2020-08-25T17:39:26.334Z,1598377166.334 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20200825T153601/Courier0064.lzma 2020-08-25T17:39:27.337Z,1598377167.337 [DataOverHttps](INFO): Moved sent file to Logs/20200825T153601/Courier0064.lzma.bak 2020-08-25T17:39:27.337Z,1598377167.337 [DataOverHttps](INFO): SBD MOMSN=12615230 2020-08-25T17:39:42.834Z,1598377182.834 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20200825T173544/Courier0000.lzma 2020-08-25T17:39:43.836Z,1598377183.836 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0000.lzma.bak 2020-08-25T17:39:43.836Z,1598377183.836 [DataOverHttps](INFO): SBD MOMSN=12615232 2020-08-25T17:39:56.184Z,1598377196.184 [Startup:StartupSatComms:B](INFO): Timed out from 2020-08-25T17:38:55.0Z 2020-08-25T17:39:56.184Z,1598377196.184 [Startup:StartupSatComms:B] Stopped 2020-08-25T17:39:56.184Z,1598377196.184 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2020-08-25T17:39:56.184Z,1598377196.184 [Startup:StartupSatComms] Stopped 2020-08-25T17:39:56.184Z,1598377196.184 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2020-08-25T17:39:56.185Z,1598377196.185 [Startup](INFO): Completed Startup 2020-08-25T17:39:56.185Z,1598377196.185 [MissionManager](INFO): Startup is completed. 2020-08-25T17:39:56.185Z,1598377196.185 [MissionManager](INFO): Uninitializing Mission Startup 2020-08-25T17:39:56.185Z,1598377196.185 [Startup] Stopped 2020-08-25T17:39:56.185Z,1598377196.185 [Startup](DEBUG): Aggregate::uninitialize Startup 2020-08-25T17:39:56.185Z,1598377196.185 [Startup:A.GoToSurface] Stopped 2020-08-25T17:39:56.186Z,1598377196.186 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-25T17:39:56.575Z,1598377196.575 [MissionManager](IMPORTANT): Started mission Default 2020-08-25T17:39:56.576Z,1598377196.576 [Default] Running Loop=1 2020-08-25T17:39:56.576Z,1598377196.576 [Default](DEBUG): Aggregate::initialize Default 2020-08-25T17:39:56.576Z,1598377196.576 [Default:B.GoToSurface] Running Loop=1 2020-08-25T17:39:56.576Z,1598377196.576 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-25T17:39:56.576Z,1598377196.576 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-25T17:39:56.576Z,1598377196.576 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-25T17:39:56.577Z,1598377196.577 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-25T17:39:56.577Z,1598377196.577 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-25T17:39:56.577Z,1598377196.577 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-25T17:39:56.578Z,1598377196.578 [Default:A.Wait] Running Loop=1 2020-08-25T17:39:56.578Z,1598377196.578 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-25T17:40:00.938Z,1598377200.938 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20200825T153601/Express0065.lzma 2020-08-25T17:40:01.940Z,1598377201.940 [DataOverHttps](INFO): Moved sent file to Logs/20200825T153601/Express0065.lzma.bak 2020-08-25T17:40:01.940Z,1598377201.940 [DataOverHttps](INFO): SBD MOMSN=12615237 2020-08-25T17:40:09.896Z,1598377209.896 [Default:A.Wait](INFO): Done Waiting. 2020-08-25T17:40:09.896Z,1598377209.896 [Default:A.Wait] Stopped 2020-08-25T17:40:09.896Z,1598377209.896 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T17:40:10.304Z,1598377210.304 [Default:CheckIn] Running Loop=1 2020-08-25T17:40:10.304Z,1598377210.304 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T17:40:10.304Z,1598377210.304 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T17:40:10.785Z,1598377210.785 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2020-08-25T17:41:36.740Z,1598377296.740 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-08-25T17:41:40.790Z,1598377300.790 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174139.00,A,3648.16262,N,12147.27707,W,0.156,304.38,250820,,,A*7A 2020-08-25T17:41:40.793Z,1598377300.793 [NAL9602](INFO): GPS fix at 20200825T174139: (36.802710, -121.787951) 2020-08-25T17:41:40.818Z,1598377300.818 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T17:41:40.818Z,1598377300.818 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-25T17:41:41.215Z,1598377301.215 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2020-08-25T17:41:50.774Z,1598377310.774 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20200825T173544/Courier0004.lzma 2020-08-25T17:41:51.776Z,1598377311.776 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0004.lzma.bak 2020-08-25T17:41:51.776Z,1598377311.776 [DataOverHttps](INFO): SBD MOMSN=12615282 2020-08-25T17:42:09.772Z,1598377329.772 [DataOverHttps](INFO): Sending 1005 bytes from file Logs/20200825T173544/Express0001.lzma 2020-08-25T17:42:10.773Z,1598377330.773 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0001.lzma.bak 2020-08-25T17:42:10.773Z,1598377330.773 [DataOverHttps](INFO): SBD MOMSN=12615285 2020-08-25T17:42:13.111Z,1598377333.111 [NAL9602](INFO): Not Powering down - fast GPS 2020-08-25T17:42:33.166Z,1598377353.166 [DataOverHttps](INFO): Sending 311 bytes from file Logs/20200825T173544/Express0005.lzma 2020-08-25T17:42:34.168Z,1598377354.168 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0005.lzma.bak 2020-08-25T17:42:34.168Z,1598377354.168 [DataOverHttps](INFO): SBD MOMSN=12615310 2020-08-25T17:42:37.105Z,1598377357.105 [Default:CheckIn:Read_Iridium] Stopped 2020-08-25T17:42:37.105Z,1598377357.105 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-25T17:42:37.105Z,1598377357.105 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-25T17:42:39.947Z,1598377359.947 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2020-08-25T17:43:26.011Z,1598377406.011 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2020-08-25T17:43:26.014Z,1598377406.014 [BPC1](INFO): Received data from all battery sticks. 2020-08-25T17:47:37.676Z,1598377657.676 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-08-25T17:47:37.677Z,1598377657.677 [Default:CheckIn:C.Wait] Stopped 2020-08-25T17:47:37.677Z,1598377657.677 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T17:47:37.677Z,1598377657.677 [Default:CheckIn:D] Running Loop=1 2020-08-25T17:47:38.082Z,1598377658.082 [Default:CheckIn:D] Stopped 2020-08-25T17:47:38.086Z,1598377658.086 [Default:CheckIn:E] Running Loop=1 2020-08-25T17:47:38.487Z,1598377658.487 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.691774 min 2020-08-25T17:47:38.487Z,1598377658.487 [Default:CheckIn:E] Stopped 2020-08-25T17:47:38.487Z,1598377658.487 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-08-25T17:47:38.488Z,1598377658.488 [Default:CheckIn] Stopped 2020-08-25T17:47:38.488Z,1598377658.488 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T17:47:38.488Z,1598377658.488 [Default:CheckIn](INFO): Running loop #2 2020-08-25T17:47:38.488Z,1598377658.488 [Default:CheckIn] Running Loop=2 2020-08-25T17:47:38.488Z,1598377658.488 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T17:47:38.488Z,1598377658.488 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T17:47:40.501Z,1598377660.501 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174740.00,A,3648.16726,N,12147.28080,W,0.214,304.38,250820,,,A*75 2020-08-25T17:47:40.504Z,1598377660.504 [NAL9602](INFO): GPS fix at 20200825T174740: (36.802788, -121.788013) 2020-08-25T17:47:40.512Z,1598377660.512 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T17:47:40.512Z,1598377660.512 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-25T17:47:49.222Z,1598377669.222 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20200825T173544/Courier0007.lzma 2020-08-25T17:47:50.240Z,1598377670.240 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0007.lzma.bak 2020-08-25T17:47:50.241Z,1598377670.241 [DataOverHttps](INFO): SBD MOMSN=12615350 2020-08-25T17:48:07.466Z,1598377687.466 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20200825T173544/Express0008.lzma 2020-08-25T17:48:08.468Z,1598377688.468 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0008.lzma.bak 2020-08-25T17:48:08.468Z,1598377688.468 [DataOverHttps](INFO): SBD MOMSN=12615353 2020-08-25T17:48:11.216Z,1598377691.216 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2020-08-25T17:48:11.298Z,1598377691.298 [NAL9602](FAULT): received: +CSQ:0 OK 2020-08-25T17:48:11.298Z,1598377691.298 [NAL9602] Data Fault, FailCount= 1 2020-08-25T17:48:11.299Z,1598377691.299 [NAL9602](ERROR): Data Fault 2020-08-25T17:48:11.337Z,1598377691.337 [Default:CheckIn:Read_Iridium] Stopped 2020-08-25T17:48:11.337Z,1598377691.337 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-25T17:48:11.337Z,1598377691.337 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-25T17:48:11.351Z,1598377691.351 [CBIT](ERROR): Data Fault in component: NAL9602 2020-08-25T17:48:11.607Z,1598377691.607 [NAL9602](INFO): Powering down 2020-08-25T17:48:12.456Z,1598377692.456 [CBIT](INFO): Clearing failed state for component NAL9602 2020-08-25T17:48:12.456Z,1598377692.456 [NAL9602] No Fault, FailCount= 1 2020-08-25T17:48:41.906Z,1598377721.906 [NAL9602](INFO): Powering up NAL9602 2020-08-25T17:48:52.816Z,1598377732.816 [NAL9602](INFO): NAL9602 initialized 2020-08-25T17:49:23.929Z,1598377763.929 [NAL9602](INFO): Not Powering down - fast GPS 2020-08-25T17:53:11.789Z,1598377991.789 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-08-25T17:53:11.789Z,1598377991.789 [Default:CheckIn:C.Wait] Stopped 2020-08-25T17:53:11.789Z,1598377991.789 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T17:53:11.789Z,1598377991.789 [Default:CheckIn:D] Running Loop=1 2020-08-25T17:53:12.193Z,1598377992.193 [Default:CheckIn:D] Stopped 2020-08-25T17:53:12.193Z,1598377992.193 [Default:CheckIn:E] Running Loop=1 2020-08-25T17:53:12.595Z,1598377992.595 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.260295 min 2020-08-25T17:53:12.595Z,1598377992.595 [Default:CheckIn:E] Stopped 2020-08-25T17:53:12.595Z,1598377992.595 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-08-25T17:53:12.595Z,1598377992.595 [Default:CheckIn] Stopped 2020-08-25T17:53:12.595Z,1598377992.595 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T17:53:12.595Z,1598377992.595 [Default:CheckIn](INFO): Running loop #3 2020-08-25T17:53:12.596Z,1598377992.596 [Default:CheckIn] Running Loop=3 2020-08-25T17:53:12.596Z,1598377992.596 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T17:53:12.596Z,1598377992.596 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T17:53:14.613Z,1598377994.613 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175313.00,A,3648.15544,N,12147.27777,W,0.525,167.66,250820,,,A*7A 2020-08-25T17:53:14.615Z,1598377994.615 [NAL9602](INFO): GPS fix at 20200825T175313: (36.802591, -121.787963) 2020-08-25T17:53:14.624Z,1598377994.624 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T17:53:14.624Z,1598377994.624 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-25T17:53:16.635Z,1598377996.635 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-08-25T17:53:22.726Z,1598378002.726 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200825T173544/Courier0010.lzma 2020-08-25T17:53:23.728Z,1598378003.728 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0010.lzma.bak 2020-08-25T17:53:23.728Z,1598378003.728 [DataOverHttps](INFO): SBD MOMSN=12615365 2020-08-25T17:53:40.774Z,1598378020.774 [DataOverHttps](INFO): Sending 160 bytes from file Logs/20200825T173544/Express0011.lzma 2020-08-25T17:53:41.776Z,1598378021.776 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0011.lzma.bak 2020-08-25T17:53:41.776Z,1598378021.776 [DataOverHttps](INFO): SBD MOMSN=12615368 2020-08-25T17:53:45.328Z,1598378025.328 [Default:CheckIn:Read_Iridium] Stopped 2020-08-25T17:53:45.328Z,1598378025.328 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-25T17:53:45.328Z,1598378025.328 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-25T17:53:47.330Z,1598378027.330 [NAL9602](INFO): Not Powering down - fast GPS 2020-08-25T17:58:45.924Z,1598378325.924 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-08-25T17:58:45.924Z,1598378325.924 [Default:CheckIn:C.Wait] Stopped 2020-08-25T17:58:45.924Z,1598378325.924 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T17:58:45.924Z,1598378325.924 [Default:CheckIn:D] Running Loop=1 2020-08-25T17:58:46.340Z,1598378326.341 [Default:CheckIn:D] Stopped 2020-08-25T17:58:46.341Z,1598378326.341 [Default:CheckIn:E] Running Loop=1 2020-08-25T17:58:46.735Z,1598378326.735 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.829415 min 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn:E] Stopped 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn] Stopped 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn](INFO): Running loop #4 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn] Running Loop=4 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T17:58:46.736Z,1598378326.736 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T17:58:48.749Z,1598378328.749 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175848.00,A,3648.16392,N,12147.28382,W,0.214,300.04,250820,,,A*72 2020-08-25T17:58:48.751Z,1598378328.751 [NAL9602](INFO): GPS fix at 20200825T175848: (36.802732, -121.788064) 2020-08-25T17:58:48.760Z,1598378328.760 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T17:58:48.760Z,1598378328.760 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-25T17:58:56.410Z,1598378336.410 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200825T173544/Courier0013.lzma 2020-08-25T17:58:57.412Z,1598378337.412 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0013.lzma.bak 2020-08-25T17:58:57.412Z,1598378337.412 [DataOverHttps](INFO): SBD MOMSN=12615405 2020-08-25T17:59:15.410Z,1598378355.410 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20200825T173544/Express0014.lzma 2020-08-25T17:59:16.412Z,1598378356.412 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0014.lzma.bak 2020-08-25T17:59:16.412Z,1598378356.412 [DataOverHttps](INFO): SBD MOMSN=12615408 2020-08-25T17:59:19.084Z,1598378359.084 [Default:CheckIn:Read_Iridium] Stopped 2020-08-25T17:59:19.084Z,1598378359.084 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-25T17:59:19.084Z,1598378359.084 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-25T18:02:25.767Z,1598378545.767 [CommandLine](IMPORTANT): got command failComponent 2020-08-25T18:02:25.767Z,1598378545.767 [CommandLine](IMPORTANT): Failed components: 2020-08-25T18:02:25.768Z,1598378545.768 [CommandLine](IMPORTANT): No failed Components. 2020-08-25T18:02:40.657Z,1598378560.657 [NAL9602](INFO): SBD MO Status=2, MOMSN=8113, MT Status=2, MTMSN=0 2020-08-25T18:02:40.657Z,1598378560.657 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-08-25T18:02:54.387Z,1598378574.387 [NAL9602](INFO): SBD MO Status=2, MOMSN=8113, MT Status=2, MTMSN=0 2020-08-25T18:02:54.387Z,1598378574.387 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-08-25T18:03:10.957Z,1598378590.957 [NAL9602](INFO): SBD MO Status=2, MOMSN=8113, MT Status=2, MTMSN=0 2020-08-25T18:03:10.957Z,1598378590.957 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-08-25T18:03:48.125Z,1598378628.125 [NAL9602](INFO): SBD MO Status=0, MOMSN=8113, MT Status=0, MTMSN=0 2020-08-25T18:03:48.125Z,1598378628.125 [NAL9602](INFO): No messages in MT queue 2020-08-25T18:04:18.823Z,1598378658.823 [NAL9602](INFO): Not Powering down - fast GPS 2020-08-25T18:04:19.643Z,1598378659.643 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2020-08-25T18:04:19.643Z,1598378659.643 [Default:CheckIn:C.Wait] Stopped 2020-08-25T18:04:19.643Z,1598378659.643 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T18:04:19.643Z,1598378659.643 [Default:CheckIn:D] Running Loop=1 2020-08-25T18:04:20.041Z,1598378660.041 [Default:CheckIn:D] Stopped 2020-08-25T18:04:20.041Z,1598378660.041 [Default:CheckIn:E] Running Loop=1 2020-08-25T18:04:20.450Z,1598378660.450 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.391093 min 2020-08-25T18:04:20.450Z,1598378660.450 [Default:CheckIn:E] Stopped 2020-08-25T18:04:20.450Z,1598378660.450 [Default:CheckIn](INFO): Completed Default:CheckIn 2020-08-25T18:04:20.450Z,1598378660.450 [Default:CheckIn] Stopped 2020-08-25T18:04:20.450Z,1598378660.450 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T18:04:20.450Z,1598378660.450 [Default:CheckIn](INFO): Running loop #5 2020-08-25T18:04:20.450Z,1598378660.450 [Default:CheckIn] Running Loop=5 2020-08-25T18:04:20.451Z,1598378660.451 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T18:04:20.451Z,1598378660.451 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T18:04:22.465Z,1598378662.465 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180422.00,A,3648.16249,N,12147.28038,W,0.136,298.64,250820,,,A*78 2020-08-25T18:04:22.467Z,1598378662.467 [NAL9602](INFO): GPS fix at 20200825T180422: (36.802708, -121.788006) 2020-08-25T18:04:22.476Z,1598378662.476 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T18:04:22.476Z,1598378662.476 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-25T18:04:32.630Z,1598378672.630 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200825T173544/Courier0016.lzma 2020-08-25T18:04:33.632Z,1598378673.632 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0016.lzma.bak 2020-08-25T18:04:33.632Z,1598378673.632 [DataOverHttps](INFO): SBD MOMSN=12615421 2020-08-25T18:04:43.497Z,1598378683.497 [NAL9602](INFO): SBD MO Status=2, MOMSN=8114, MT Status=2, MTMSN=0 2020-08-25T18:04:43.497Z,1598378683.497 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-08-25T18:04:44.552Z,1598378684.552 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:04:44.553Z,1598378684.553 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:04:44.584Z,1598378684.584 [MissionManager](DEBUG): 2020-08-25T18:04:44.735Z,1598378684.735 [Default] Stopped 2020-08-25T18:04:44.735Z,1598378684.735 [Default](DEBUG): Aggregate::uninitialize Default 2020-08-25T18:04:44.735Z,1598378684.735 [Default:B.GoToSurface] Stopped 2020-08-25T18:04:44.736Z,1598378684.736 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-25T18:04:44.736Z,1598378684.736 [Default:CheckIn] Stopped 2020-08-25T18:04:44.736Z,1598378684.736 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T18:04:44.736Z,1598378684.736 [Default:CheckIn:Read_Iridium] Stopped 2020-08-25T18:04:44.737Z,1598378684.737 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2020-08-25T18:04:44.738Z,1598378684.738 [senddata_direct_test] Running Loop=1 2020-08-25T18:04:44.750Z,1598378684.750 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2020-08-25T18:04:44.750Z,1598378684.750 [senddata_direct_test:A] Running Loop=1 2020-08-25T18:04:44.751Z,1598378684.751 [senddata_direct_test:A] Stopped 2020-08-25T18:04:44.751Z,1598378684.751 [senddata_direct_test:B] Running Loop=1 2020-08-25T18:04:45.112Z,1598378685.112 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:04:45.126Z,1598378685.126 [senddata_direct_test:B] Stopped 2020-08-25T18:04:45.126Z,1598378685.126 [senddata_direct_test:C] Running Loop=1 2020-08-25T18:04:45.541Z,1598378685.541 [senddata_direct_test:C] Stopped 2020-08-25T18:04:45.541Z,1598378685.541 [senddata_direct_test](INFO): Completed senddata_direct_test 2020-08-25T18:04:45.541Z,1598378685.541 [MissionManager](INFO): senddata_direct_test is completed. 2020-08-25T18:04:45.542Z,1598378685.542 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2020-08-25T18:04:45.542Z,1598378685.542 [senddata_direct_test] Stopped 2020-08-25T18:04:45.542Z,1598378685.542 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2020-08-25T18:04:45.931Z,1598378685.931 [MissionManager](IMPORTANT): Started mission Default 2020-08-25T18:04:45.932Z,1598378685.932 [Default] Running Loop=1 2020-08-25T18:04:45.932Z,1598378685.932 [Default](DEBUG): Aggregate::initialize Default 2020-08-25T18:04:45.932Z,1598378685.932 [Default:B.GoToSurface] Running Loop=1 2020-08-25T18:04:45.932Z,1598378685.932 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-25T18:04:45.932Z,1598378685.932 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-25T18:04:45.932Z,1598378685.932 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-25T18:04:45.933Z,1598378685.933 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-25T18:04:45.933Z,1598378685.933 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-25T18:04:45.933Z,1598378685.933 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-25T18:04:45.934Z,1598378685.934 [Default:A.Wait] Running Loop=1 2020-08-25T18:04:45.934Z,1598378685.934 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-25T18:04:53.946Z,1598378693.946 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20200825T173544/Express0017.lzma 2020-08-25T18:04:54.948Z,1598378694.948 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0017.lzma.bak 2020-08-25T18:04:54.948Z,1598378694.948 [DataOverHttps](INFO): SBD MOMSN=12615424 2020-08-25T18:04:59.259Z,1598378699.259 [Default:A.Wait](INFO): Done Waiting. 2020-08-25T18:04:59.259Z,1598378699.259 [Default:A.Wait] Stopped 2020-08-25T18:04:59.259Z,1598378699.259 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T18:04:59.670Z,1598378699.670 [Default:CheckIn] Running Loop=1 2020-08-25T18:04:59.670Z,1598378699.670 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T18:04:59.670Z,1598378699.670 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T18:05:00.464Z,1598378700.464 [NAL9602](INFO): SBD MO Status=2, MOMSN=8114, MT Status=2, MTMSN=0 2020-08-25T18:05:00.465Z,1598378700.465 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-08-25T18:05:17.842Z,1598378717.842 [NAL9602](INFO): SBD MO Status=2, MOMSN=8114, MT Status=2, MTMSN=0 2020-08-25T18:05:17.842Z,1598378717.842 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-08-25T18:05:43.700Z,1598378743.700 [NAL9602](INFO): SBD MO Status=2, MOMSN=8114, MT Status=2, MTMSN=0 2020-08-25T18:05:43.701Z,1598378743.701 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2020-08-25T18:06:07.074Z,1598378767.074 [CommandLine](IMPORTANT): got command show variable benthos 2020-08-25T18:06:07.094Z,1598378767.094 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup (bool) 2020-08-25T18:06:07.095Z,1598378767.095 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.simulateHardware (bool) 2020-08-25T18:06:07.095Z,1598378767.095 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.txPower (enum) 2020-08-25T18:06:07.095Z,1598378767.095 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.localAddress (count) 2020-08-25T18:06:07.096Z,1598378767.096 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.sbdAddress (enum) 2020-08-25T18:06:07.096Z,1598378767.096 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.transponderAddress (enum) 2020-08-25T18:06:07.096Z,1598378767.096 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.sendExpress (bool) 2020-08-25T18:06:07.097Z,1598378767.097 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.surfaceThreshold (meter) 2020-08-25T18:06:07.097Z,1598378767.097 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.verbosity (count) 2020-08-25T18:06:07.202Z,1598378767.202 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadControl (none) 2020-08-25T18:06:07.203Z,1598378767.203 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.uart (none) 2020-08-25T18:06:07.203Z,1598378767.203 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.baud (bit_per_second) 2020-08-25T18:06:07.203Z,1598378767.203 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadControl2 (none) 2020-08-25T18:06:14.654Z,1598378774.654 [CommandLine](IMPORTANT): got command get AcousticModem_Benthos_ATM900.loadAtStartup 2020-08-25T18:06:14.655Z,1598378774.655 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup 0 bool 2020-08-25T18:06:18.792Z,1598378778.792 [CommandLine](IMPORTANT): got command get DAT.loadAtStartup 2020-08-25T18:06:18.793Z,1598378778.793 [CommandLine](IMPORTANT): DAT.loadAtStartup 1 bool 2020-08-25T18:06:28.248Z,1598378788.248 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:06:28.249Z,1598378788.249 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:06:28.261Z,1598378788.261 [MissionManager](DEBUG): 2020-08-25T18:06:28.263Z,1598378788.263 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:06:28.576Z,1598378788.576 [Default] Stopped 2020-08-25T18:06:28.576Z,1598378788.576 [Default](DEBUG): Aggregate::uninitialize Default 2020-08-25T18:06:28.576Z,1598378788.576 [Default:B.GoToSurface] Stopped 2020-08-25T18:06:28.576Z,1598378788.576 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-25T18:06:28.576Z,1598378788.576 [Default:CheckIn] Stopped 2020-08-25T18:06:28.576Z,1598378788.576 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T18:06:28.576Z,1598378788.576 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T18:06:28.576Z,1598378788.576 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2020-08-25T18:06:28.577Z,1598378788.577 [senddata_direct_test] Running Loop=1 2020-08-25T18:06:28.577Z,1598378788.577 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2020-08-25T18:06:28.577Z,1598378788.577 [senddata_direct_test:A] Running Loop=1 2020-08-25T18:06:28.577Z,1598378788.577 [senddata_direct_test:A] Stopped 2020-08-25T18:06:28.577Z,1598378788.577 [senddata_direct_test:B] Running Loop=1 2020-08-25T18:06:28.963Z,1598378788.963 [senddata_direct_test:B] Stopped 2020-08-25T18:06:28.964Z,1598378788.964 [senddata_direct_test:C] Running Loop=1 2020-08-25T18:06:29.402Z,1598378789.402 [senddata_direct_test:C] Stopped 2020-08-25T18:06:29.403Z,1598378789.403 [senddata_direct_test](INFO): Completed senddata_direct_test 2020-08-25T18:06:29.403Z,1598378789.403 [MissionManager](INFO): senddata_direct_test is completed. 2020-08-25T18:06:29.403Z,1598378789.403 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2020-08-25T18:06:29.403Z,1598378789.403 [senddata_direct_test] Stopped 2020-08-25T18:06:29.403Z,1598378789.403 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2020-08-25T18:06:29.794Z,1598378789.794 [MissionManager](IMPORTANT): Started mission Default 2020-08-25T18:06:29.794Z,1598378789.794 [Default] Running Loop=1 2020-08-25T18:06:29.794Z,1598378789.794 [Default](DEBUG): Aggregate::initialize Default 2020-08-25T18:06:29.794Z,1598378789.794 [Default:B.GoToSurface] Running Loop=1 2020-08-25T18:06:29.794Z,1598378789.794 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-25T18:06:29.799Z,1598378789.799 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-25T18:06:29.799Z,1598378789.799 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-25T18:06:29.799Z,1598378789.799 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-25T18:06:29.800Z,1598378789.800 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-25T18:06:29.800Z,1598378789.800 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-25T18:06:29.800Z,1598378789.800 [Default:A.Wait] Running Loop=1 2020-08-25T18:06:29.800Z,1598378789.800 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-25T18:06:43.126Z,1598378803.126 [Default:A.Wait](INFO): Done Waiting. 2020-08-25T18:06:43.126Z,1598378803.126 [Default:A.Wait] Stopped 2020-08-25T18:06:43.126Z,1598378803.126 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T18:06:43.513Z,1598378803.513 [Default:CheckIn] Running Loop=1 2020-08-25T18:06:43.514Z,1598378803.514 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T18:06:43.514Z,1598378803.514 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T18:06:54.598Z,1598378814.598 [CommandLine](IMPORTANT): got command configSet DAT.surfaceThreshold 0.000000 meter persist 2020-08-25T18:06:55.737Z,1598378815.737 [CommandLine](IMPORTANT): got command get depth 2020-08-25T18:06:55.738Z,1598378815.738 [CommandLine](IMPORTANT): depth -0.042599 m 2020-08-25T18:07:04.105Z,1598378824.105 [CommandLine](IMPORTANT): got command configSet DAT.surfaceThreshold -1.000000 meter persist 2020-08-25T18:07:07.080Z,1598378827.080 [CommandLine](IMPORTANT): got command failComponent hardware DAT 2020-08-25T18:07:07.080Z,1598378827.080 [DAT] Hardware Fault, FailCount= 1 2020-08-25T18:07:07.080Z,1598378827.080 [DAT](ERROR): Hardware Fault 2020-08-25T18:07:07.081Z,1598378827.081 [CommandLine](IMPORTANT): DAT failureMode is Hardware Fault 2020-08-25T18:07:07.332Z,1598378827.332 [DAT](INFO): Powering down 2020-08-25T18:07:07.474Z,1598378827.474 [CBIT](ERROR): Hardware Fault in component: DAT 2020-08-25T18:07:08.190Z,1598378828.190 [CBIT](INFO): Clearing failed state for component DAT 2020-08-25T18:07:08.190Z,1598378828.190 [DAT] No Fault, FailCount= 1 2020-08-25T18:07:10.575Z,1598378830.575 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2020-08-25T18:07:10.575Z,1598378830.575 [DAT](INFO): Powering up 2020-08-25T18:07:10.575Z,1598378830.575 [DAT](DEBUG): Initializing DAT. 2020-08-25T18:07:10.606Z,1598378830.606 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2020-08-25T18:07:21.068Z,1598378841.068 [DAT](INFO): DAT read: 2020-08-25T18:07:21.069Z,1598378841.069 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2020-08-25T18:07:22.281Z,1598378842.281 [DAT](INFO): DAT read: MF Frequency Band 2020-08-25T18:07:22.282Z,1598378842.282 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.12.21 2020-08-25T18:07:22.283Z,1598378842.283 [DAT](INFO): DAT read: Aug 25 2020 18:06:58 2020-08-25T18:07:23.097Z,1598378843.097 [DAT](INFO): DAT read: Features enabled [Bearing] 2020-08-25T18:07:23.098Z,1598378843.098 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-25T18:07:23.098Z,1598378843.098 [DAT](INFO): commRate: 800 2020-08-25T18:07:23.099Z,1598378843.099 [DAT](INFO): commRate: 800 2020-08-25T18:07:23.503Z,1598378843.503 [DAT](INFO): entering command mode 2020-08-25T18:07:23.919Z,1598378843.919 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:24.319Z,1598378844.319 [DAT](INFO): DAT read: 2020-08-25T18:07:24.319Z,1598378844.319 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:24.717Z,1598378844.717 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:25.107Z,1598378845.107 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:25.512Z,1598378845.512 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:25.920Z,1598378845.920 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:26.324Z,1598378846.324 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:26.724Z,1598378846.724 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:27.129Z,1598378847.129 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:27.536Z,1598378847.536 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:27.936Z,1598378847.936 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:28.338Z,1598378848.338 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:28.759Z,1598378848.759 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:29.167Z,1598378849.167 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:29.565Z,1598378849.565 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:29.971Z,1598378849.971 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:30.364Z,1598378850.364 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:30.764Z,1598378850.764 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:31.168Z,1598378851.168 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:31.576Z,1598378851.576 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:31.974Z,1598378851.974 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:32.384Z,1598378852.384 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:32.805Z,1598378852.805 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:33.187Z,1598378853.187 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:33.596Z,1598378853.596 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:34.015Z,1598378854.015 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:34.413Z,1598378854.413 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:34.819Z,1598378854.819 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:35.223Z,1598378855.223 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:35.612Z,1598378855.612 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:36.025Z,1598378856.025 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:36.420Z,1598378856.420 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:36.822Z,1598378856.822 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:37.236Z,1598378857.236 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:37.632Z,1598378857.632 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:38.034Z,1598378858.034 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:38.440Z,1598378858.440 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:38.853Z,1598378858.853 [DAT](DEBUG): checking for command mode acknowledgment 2020-08-25T18:07:38.853Z,1598378858.853 [DAT](FAULT): failed to enter command mode 2020-08-25T18:07:39.266Z,1598378859.266 [DAT](INFO): entering command mode 2020-08-25T18:07:39.663Z,1598378859.663 [DAT](INFO): DAT read: user:1> 2020-08-25T18:07:39.664Z,1598378859.664 [DAT](INFO): DAT read: Command '+++' not found 2020-08-25T18:07:39.664Z,1598378859.664 [DAT](INFO): DAT read: Error 2020-08-25T18:07:39.665Z,1598378859.665 [DAT](INFO): setting verbose to 3 2020-08-25T18:07:40.071Z,1598378860.071 [DAT](INFO): DAT read: user:2> 2020-08-25T18:07:40.072Z,1598378860.072 [DAT](INFO): DAT read: Verbose | 3 2020-08-25T18:07:40.072Z,1598378860.072 [DAT](INFO): set verbose to 3 2020-08-25T18:07:40.072Z,1598378860.072 [DAT](INFO): setting DatVerbose to 27440 2020-08-25T18:07:40.471Z,1598378860.471 [DAT](INFO): DAT read: user:3> 2020-08-25T18:07:40.472Z,1598378860.472 [DAT](INFO): DAT read: DatVerbose | 27440 2020-08-25T18:07:40.472Z,1598378860.472 [DAT](INFO): set DatVerbose to 27440 2020-08-25T18:07:40.473Z,1598378860.473 [DAT](INFO): setting transmit power to 8 2020-08-25T18:07:40.864Z,1598378860.864 [DAT](INFO): DAT read: user:4> 2020-08-25T18:07:40.865Z,1598378860.865 [DAT](INFO): DAT read: TxPower | 8 (Max) 2020-08-25T18:07:40.865Z,1598378860.865 [DAT](INFO): set transmit power to 8 2020-08-25T18:07:40.866Z,1598378860.866 [DAT](INFO): setting local address to 9 2020-08-25T18:07:41.274Z,1598378861.274 [DAT](INFO): DAT read: user:5> 2020-08-25T18:07:41.275Z,1598378861.275 [DAT](INFO): DAT read: LocalAddr | 9 2020-08-25T18:07:41.276Z,1598378861.276 [DAT](INFO): set local address to 9 2020-08-25T18:07:41.277Z,1598378861.277 [DAT](INFO): modem://6: set _.pressure 0.506848 atmosphere 2020-08-25T18:07:41.278Z,1598378861.278 [DAT](INFO): #Outgoing data=1 2020-08-25T18:07:41.278Z,1598378861.278 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:07:41.672Z,1598378861.672 [DAT](INFO): setting remote address to 6 2020-08-25T18:07:42.076Z,1598378862.076 [DAT](INFO): DAT read: user:6> 2020-08-25T18:07:42.077Z,1598378862.077 [DAT](INFO): DAT read: RemoteAddr | 6 2020-08-25T18:07:42.077Z,1598378862.077 [DAT](INFO): set remote address to 6 2020-08-25T18:07:42.079Z,1598378862.079 [DAT](INFO): entering online mode 2020-08-25T18:07:42.480Z,1598378862.480 [DAT](INFO): DAT read: user:7> 2020-08-25T18:07:42.481Z,1598378862.481 [DAT](INFO): DAT read: 2020-08-25T18:07:42.482Z,1598378862.482 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2020-08-25T18:07:42.482Z,1598378862.482 [DAT](INFO): commRate: 800 2020-08-25T18:07:42.483Z,1598378862.483 [DAT](INFO): online mode acknowledged 2020-08-25T18:07:42.483Z,1598378862.483 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:07:45.726Z,1598378865.726 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:07:25.9884 2020-08-25T18:07:45.726Z,1598378865.726 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:08:02.684Z,1598378882.684 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:08:02.684Z,1598378882.684 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:08:03.089Z,1598378883.089 [DAT](INFO): modem://6: set _.temperature 21.358820 celsius 2020-08-25T18:08:03.089Z,1598378883.089 [DAT](INFO): #Outgoing data=1 2020-08-25T18:08:03.089Z,1598378883.089 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:08:03.495Z,1598378883.495 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:08:06.732Z,1598378886.732 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:07:46.9884 2020-08-25T18:08:06.732Z,1598378886.732 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:08:21.479Z,1598378901.479 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:08:21.479Z,1598378901.479 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:08:21.492Z,1598378901.492 [MissionManager](DEBUG): 2020-08-25T18:08:21.494Z,1598378901.494 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:08:21.697Z,1598378901.697 [Default] Stopped 2020-08-25T18:08:21.697Z,1598378901.697 [Default](DEBUG): Aggregate::uninitialize Default 2020-08-25T18:08:21.697Z,1598378901.697 [Default:B.GoToSurface] Stopped 2020-08-25T18:08:21.697Z,1598378901.697 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-25T18:08:21.697Z,1598378901.697 [Default:CheckIn] Stopped 2020-08-25T18:08:21.697Z,1598378901.697 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T18:08:21.697Z,1598378901.697 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T18:08:21.698Z,1598378901.698 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2020-08-25T18:08:21.698Z,1598378901.698 [senddata_direct_test] Running Loop=1 2020-08-25T18:08:21.698Z,1598378901.698 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2020-08-25T18:08:21.698Z,1598378901.698 [senddata_direct_test:A] Running Loop=1 2020-08-25T18:08:21.699Z,1598378901.699 [senddata_direct_test:A] Stopped 2020-08-25T18:08:21.699Z,1598378901.699 [senddata_direct_test:B] Running Loop=1 2020-08-25T18:08:22.116Z,1598378902.116 [senddata_direct_test:B] Stopped 2020-08-25T18:08:22.116Z,1598378902.116 [senddata_direct_test:C] Running Loop=1 2020-08-25T18:08:22.502Z,1598378902.502 [senddata_direct_test:C] Stopped 2020-08-25T18:08:22.502Z,1598378902.502 [senddata_direct_test](INFO): Completed senddata_direct_test 2020-08-25T18:08:22.502Z,1598378902.502 [MissionManager](INFO): senddata_direct_test is completed. 2020-08-25T18:08:22.506Z,1598378902.506 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2020-08-25T18:08:22.506Z,1598378902.506 [senddata_direct_test] Stopped 2020-08-25T18:08:22.507Z,1598378902.507 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2020-08-25T18:08:22.897Z,1598378902.897 [MissionManager](IMPORTANT): Started mission Default 2020-08-25T18:08:22.898Z,1598378902.898 [Default] Running Loop=1 2020-08-25T18:08:22.898Z,1598378902.898 [Default](DEBUG): Aggregate::initialize Default 2020-08-25T18:08:22.898Z,1598378902.898 [Default:B.GoToSurface] Running Loop=1 2020-08-25T18:08:22.898Z,1598378902.898 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-25T18:08:22.902Z,1598378902.902 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-25T18:08:22.903Z,1598378902.903 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-25T18:08:22.903Z,1598378902.903 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-25T18:08:22.903Z,1598378902.903 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-25T18:08:22.904Z,1598378902.904 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-25T18:08:22.904Z,1598378902.904 [Default:A.Wait] Running Loop=1 2020-08-25T18:08:22.904Z,1598378902.904 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-25T18:08:23.688Z,1598378903.688 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:08:23.688Z,1598378903.688 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:08:24.093Z,1598378904.093 [DAT](INFO): modem://6: set _.humidity 24.380417 percent 2020-08-25T18:08:24.093Z,1598378904.093 [DAT](INFO): #Outgoing data=2 2020-08-25T18:08:24.093Z,1598378904.093 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:08:24.496Z,1598378904.496 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:08:27.740Z,1598378907.740 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:08:07.9886 2020-08-25T18:08:27.740Z,1598378907.740 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:08:36.220Z,1598378916.220 [Default:A.Wait](INFO): Done Waiting. 2020-08-25T18:08:36.220Z,1598378916.220 [Default:A.Wait] Stopped 2020-08-25T18:08:36.220Z,1598378916.220 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T18:08:36.630Z,1598378916.630 [Default:CheckIn] Running Loop=1 2020-08-25T18:08:36.630Z,1598378916.630 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T18:08:36.630Z,1598378916.630 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T18:08:44.696Z,1598378924.696 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:08:44.696Z,1598378924.696 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:08:45.101Z,1598378925.101 [DAT](INFO): modem://6: set _.pressure 0.509473 atmosphere 2020-08-25T18:08:45.101Z,1598378925.101 [DAT](INFO): #Outgoing data=3 2020-08-25T18:08:45.101Z,1598378925.101 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:08:45.509Z,1598378925.509 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:08:48.752Z,1598378928.752 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:08:29.0383 2020-08-25T18:08:48.752Z,1598378928.752 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:09:05.716Z,1598378945.716 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:09:05.716Z,1598378945.716 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:09:06.106Z,1598378946.106 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:09:06.517Z,1598378946.517 [DAT](INFO): modem://6: set _.temperature 21.358820 celsius 2020-08-25T18:09:06.517Z,1598378946.517 [DAT](INFO): #Outgoing data=4 2020-08-25T18:09:06.517Z,1598378946.517 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:09:06.921Z,1598378946.921 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:09:10.153Z,1598378950.153 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:08:50.4383 2020-08-25T18:09:10.153Z,1598378950.153 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:09:25.100Z,1598378965.100 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2020-08-25T18:09:26.309Z,1598378966.309 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180925.00,A,3648.16532,N,12147.28223,W,0.525,298.64,250820,,,A*77 2020-08-25T18:09:26.311Z,1598378966.311 [NAL9602](INFO): GPS fix at 20200825T180925: (36.802755, -121.788037) 2020-08-25T18:09:26.320Z,1598378966.320 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T18:09:26.320Z,1598378966.320 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-25T18:09:27.116Z,1598378967.116 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:09:27.116Z,1598378967.116 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:09:27.528Z,1598378967.528 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:09:27.929Z,1598378967.929 [DAT](INFO): modem://6: set _.humidity 24.356001 percent 2020-08-25T18:09:27.929Z,1598378967.929 [DAT](INFO): #Outgoing data=4 2020-08-25T18:09:27.929Z,1598378967.929 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:09:28.329Z,1598378968.329 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:09:31.560Z,1598378971.560 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:09:11.8383 2020-08-25T18:09:31.561Z,1598378971.561 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:09:34.562Z,1598378974.562 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200825T173544/Courier0019.lzma 2020-08-25T18:09:35.564Z,1598378975.564 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0019.lzma.bak 2020-08-25T18:09:35.564Z,1598378975.564 [DataOverHttps](INFO): SBD MOMSN=12615460 2020-08-25T18:09:48.528Z,1598378988.528 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:09:48.528Z,1598378988.528 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:09:48.932Z,1598378988.932 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:09:49.336Z,1598378989.336 [DAT](INFO): modem://6: set _.pressure 0.505434 atmosphere 2020-08-25T18:09:49.337Z,1598378989.337 [DAT](INFO): #Outgoing data=4 2020-08-25T18:09:49.337Z,1598378989.337 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:09:49.740Z,1598378989.740 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:09:52.811Z,1598378992.811 [DataOverHttps](INFO): Sending 794 bytes from file Logs/20200825T173544/Express0020.lzma 2020-08-25T18:09:52.973Z,1598378992.973 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:09:33.2383 2020-08-25T18:09:52.973Z,1598378992.973 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:09:53.824Z,1598378993.824 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0020.lzma.bak 2020-08-25T18:09:53.824Z,1598378993.824 [DataOverHttps](INFO): SBD MOMSN=12615463 2020-08-25T18:09:56.641Z,1598378996.641 [Default:CheckIn:Read_Iridium] Stopped 2020-08-25T18:09:56.642Z,1598378996.642 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-25T18:09:56.642Z,1598378996.642 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-25T18:09:58.223Z,1598378998.223 [NAL9602](INFO): Not Powering down - fast GPS 2020-08-25T18:10:09.940Z,1598379009.940 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:10:09.940Z,1598379009.940 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:10:10.344Z,1598379010.344 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:10:10.748Z,1598379010.748 [DAT](INFO): modem://6: set _.temperature 21.439386 celsius 2020-08-25T18:10:10.749Z,1598379010.749 [DAT](INFO): #Outgoing data=4 2020-08-25T18:10:10.749Z,1598379010.749 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:10:11.152Z,1598379011.152 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:10:14.389Z,1598379014.389 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:09:54.6395 2020-08-25T18:10:14.389Z,1598379014.389 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:10:31.357Z,1598379031.357 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:10:31.357Z,1598379031.357 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:10:31.758Z,1598379031.758 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:10:32.169Z,1598379032.169 [DAT](INFO): modem://6: set _.humidity 24.356001 percent 2020-08-25T18:10:32.170Z,1598379032.170 [DAT](INFO): #Outgoing data=4 2020-08-25T18:10:32.170Z,1598379032.170 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:11:17.639Z,1598379077.639 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:11:17.639Z,1598379077.639 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:11:17.671Z,1598379077.671 [MissionManager](DEBUG): 2020-08-25T18:11:17.672Z,1598379077.672 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2020-08-25T18:11:17.829Z,1598379077.829 [Default] Stopped 2020-08-25T18:11:17.829Z,1598379077.829 [Default](DEBUG): Aggregate::uninitialize Default 2020-08-25T18:11:17.829Z,1598379077.829 [Default:B.GoToSurface] Stopped 2020-08-25T18:11:17.830Z,1598379077.830 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2020-08-25T18:11:17.830Z,1598379077.830 [Default:CheckIn] Stopped 2020-08-25T18:11:17.830Z,1598379077.830 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2020-08-25T18:11:17.830Z,1598379077.830 [Default:CheckIn:C.Wait] Stopped 2020-08-25T18:11:17.830Z,1598379077.830 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T18:11:17.830Z,1598379077.830 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2020-08-25T18:11:17.830Z,1598379077.830 [senddata_direct_test] Running Loop=1 2020-08-25T18:11:17.831Z,1598379077.831 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2020-08-25T18:11:17.831Z,1598379077.831 [senddata_direct_test:A] Running Loop=1 2020-08-25T18:11:17.831Z,1598379077.831 [senddata_direct_test:A] Stopped 2020-08-25T18:11:17.831Z,1598379077.831 [senddata_direct_test:B] Running Loop=1 2020-08-25T18:11:18.244Z,1598379078.244 [senddata_direct_test:B] Stopped 2020-08-25T18:11:18.245Z,1598379078.245 [senddata_direct_test:C] Running Loop=1 2020-08-25T18:11:18.636Z,1598379078.636 [senddata_direct_test:C] Stopped 2020-08-25T18:11:18.636Z,1598379078.636 [senddata_direct_test](INFO): Completed senddata_direct_test 2020-08-25T18:11:18.636Z,1598379078.636 [MissionManager](INFO): senddata_direct_test is completed. 2020-08-25T18:11:18.636Z,1598379078.636 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2020-08-25T18:11:18.636Z,1598379078.636 [senddata_direct_test] Stopped 2020-08-25T18:11:18.636Z,1598379078.636 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2020-08-25T18:11:19.045Z,1598379079.045 [MissionManager](IMPORTANT): Started mission Default 2020-08-25T18:11:19.045Z,1598379079.045 [Default] Running Loop=1 2020-08-25T18:11:19.045Z,1598379079.045 [Default](DEBUG): Aggregate::initialize Default 2020-08-25T18:11:19.046Z,1598379079.046 [Default:B.GoToSurface] Running Loop=1 2020-08-25T18:11:19.046Z,1598379079.046 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2020-08-25T18:11:19.046Z,1598379079.046 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2020-08-25T18:11:19.046Z,1598379079.046 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2020-08-25T18:11:19.047Z,1598379079.047 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2020-08-25T18:11:19.047Z,1598379079.047 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2020-08-25T18:11:19.047Z,1598379079.047 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2020-08-25T18:11:19.047Z,1598379079.047 [Default:A.Wait] Running Loop=1 2020-08-25T18:11:19.048Z,1598379079.048 [Default:A.Wait](DEBUG): Initialize Wait Component. 2020-08-25T18:11:19.428Z,1598379079.428 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:11:22.664Z,1598379082.664 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:11:02.9383 2020-08-25T18:11:22.665Z,1598379082.665 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:11:32.363Z,1598379092.363 [Default:A.Wait](INFO): Done Waiting. 2020-08-25T18:11:32.363Z,1598379092.363 [Default:A.Wait] Stopped 2020-08-25T18:11:32.363Z,1598379092.363 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2020-08-25T18:11:32.776Z,1598379092.776 [Default:CheckIn] Running Loop=1 2020-08-25T18:11:32.776Z,1598379092.776 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2020-08-25T18:11:32.776Z,1598379092.776 [Default:CheckIn:Read_GPS] Running Loop=1 2020-08-25T18:11:34.790Z,1598379094.790 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181134.00,A,3648.16663,N,12147.28251,W,0.117,309.13,250820,,,D*75 2020-08-25T18:11:34.792Z,1598379094.792 [NAL9602](INFO): GPS fix at 20200825T181134: (36.802777, -121.788042) 2020-08-25T18:11:34.802Z,1598379094.802 [Default:CheckIn:Read_GPS] Stopped 2020-08-25T18:11:34.802Z,1598379094.802 [Default:CheckIn:Read_Iridium] Running Loop=1 2020-08-25T18:11:39.628Z,1598379099.628 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:11:39.628Z,1598379099.628 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:11:40.032Z,1598379100.032 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:11:40.437Z,1598379100.437 [DAT](INFO): modem://6: set _.pressure 0.506037 atmosphere 2020-08-25T18:11:40.437Z,1598379100.437 [DAT](INFO): #Outgoing data=4 2020-08-25T18:11:40.437Z,1598379100.437 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:11:40.843Z,1598379100.843 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:11:43.218Z,1598379103.218 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200825T173544/Courier0022.lzma 2020-08-25T18:11:44.072Z,1598379104.072 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:11:24.3383 2020-08-25T18:11:44.073Z,1598379104.073 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:11:44.220Z,1598379104.220 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Courier0022.lzma.bak 2020-08-25T18:11:44.220Z,1598379104.220 [DataOverHttps](INFO): SBD MOMSN=12615508 2020-08-25T18:12:01.038Z,1598379121.038 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:12:01.038Z,1598379121.038 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:12:01.443Z,1598379121.443 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:12:01.502Z,1598379121.502 [DataOverHttps](INFO): Sending 227 bytes from file Logs/20200825T173544/Express0023.lzma 2020-08-25T18:12:01.849Z,1598379121.849 [DAT](INFO): modem://6: set _.temperature 21.439386 celsius 2020-08-25T18:12:01.849Z,1598379121.849 [DAT](INFO): #Outgoing data=4 2020-08-25T18:12:01.849Z,1598379121.849 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:12:02.251Z,1598379122.251 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2020-08-25T18:12:02.504Z,1598379122.504 [DataOverHttps](INFO): Moved sent file to Logs/20200825T173544/Express0023.lzma.bak 2020-08-25T18:12:02.504Z,1598379122.504 [DataOverHttps](INFO): SBD MOMSN=12615514 2020-08-25T18:12:05.483Z,1598379125.483 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2020-08-25T18:12:05.566Z,1598379125.566 [NAL9602](FAULT): received: +CSQ:0 OK14, 2, 0, 0, 0 OK 2020-08-25T18:12:05.566Z,1598379125.566 [NAL9602] Data Fault, FailCount= 1 2020-08-25T18:12:05.567Z,1598379125.566 [NAL9602](ERROR): Data Fault 2020-08-25T18:12:05.568Z,1598379125.568 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:11:45.7384 2020-08-25T18:12:05.569Z,1598379125.569 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2020-08-25T18:12:05.577Z,1598379125.577 [Default:CheckIn:Read_Iridium] Stopped 2020-08-25T18:12:05.578Z,1598379125.578 [Default:CheckIn:C.Wait] Running Loop=1 2020-08-25T18:12:05.578Z,1598379125.578 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2020-08-25T18:12:05.587Z,1598379125.587 [CBIT](ERROR): Data Fault in component: NAL9602 2020-08-25T18:12:05.887Z,1598379125.887 [NAL9602](INFO): Powering down 2020-08-25T18:12:06.751Z,1598379126.751 [CBIT](INFO): Clearing failed state for component NAL9602 2020-08-25T18:12:06.751Z,1598379126.751 [NAL9602] No Fault, FailCount= 1 2020-08-25T18:12:14.370Z,1598379134.370 [DAT](INFO): DAT read: Rx Time:18:11:53.8291 2020-08-25T18:12:14.371Z,1598379134.371 [DAT](INFO): received an acoustic signal 2020-08-25T18:12:15.184Z,1598379135.184 [DAT](INFO): DAT read: 18:11:53.8291 LVL= 32752, 26673, 22898, 32755, AGC= 74, IDX= 487,-0.09, 1.029, 2.139, 2.568, 0.728, PHS= 0.336, 1.441, 1.912, RAW= 253.1, -42.9, CAL= 251.6, -42.1, ROT= 243.4, 42.1 2020-08-25T18:12:15.186Z,1598379135.186 [DAT](INFO): got valid direction response: 18:11:53.8291 LVL= 32752, 26673, 22898, 32755, AGC= 74, IDX= 487,-0.09, 1.029, 2.139, 2.568, 0.728, PHS= 0.336, 1.441, 1.912, RAW= 253.1, -42.9, CAL= 251.6, -42.1, ROT= 243.4, 42.1 2020-08-25T18:12:15.219Z,1598379135.219 [DAT](INFO): DAT read: 2020-08-25T18:12:15.220Z,1598379135.220 [DAT](INFO): DAT read: $Packet for address 0 2020-08-25T18:12:15.220Z,1598379135.220 [DAT](INFO): received a packet notification 2020-08-25T18:12:15.231Z,1598379135.231 [DAT](INFO): Read direction message, but no range. 2020-08-25T18:12:22.459Z,1598379142.459 [DAT](FAULT): Ack receipt timeout failure. 2020-08-25T18:12:22.460Z,1598379142.460 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2020-08-25T18:12:22.860Z,1598379142.860 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2020-08-25T18:12:23.264Z,1598379143.264 [DAT](INFO): modem://6: set _.humidity 24.356001 percent 2020-08-25T18:12:23.265Z,1598379143.265 [DAT](INFO): #Outgoing data=4 2020-08-25T18:12:23.265Z,1598379143.265 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2020-08-25T18:12:36.185Z,1598379156.185 [NAL9602](INFO): Powering up NAL9602 2020-08-25T18:12:47.093Z,1598379167.093 [NAL9602](INFO): NAL9602 initialized 2020-08-25T18:13:18.201Z,1598379198.201 [NAL9602](INFO): Not Powering down - fast GPS