2019-12-10T17:19:04.858Z,1575998344.858 [Supervisor](DEBUG): Initializing supervisor. 2019-12-10T17:19:04.860Z,1575998344.860 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-12-10T17:19:04.861Z,1575998344.861 [SyncHandler](INFO): Protected caller Thread ID is 808 2019-12-10T17:19:04.861Z,1575998344.861 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-12-10T17:19:04.862Z,1575998344.862 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-12-10T17:19:04.862Z,1575998344.862 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 809 2019-12-10T17:19:04.865Z,1575998344.865 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-12-10T17:19:04.876Z,1575998344.876 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-12-10T17:19:04.877Z,1575998344.877 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-12-10T17:19:04.877Z,1575998344.877 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 810 2019-12-10T17:19:04.878Z,1575998344.878 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-12-10T17:19:04.879Z,1575998344.879 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-12-10T17:19:04.879Z,1575998344.879 [logger ThreadHandler](INFO): Protected caller Thread ID is 811 2019-12-10T17:19:04.881Z,1575998344.881 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-12-10T17:19:04.882Z,1575998344.882 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-12-10T17:19:04.885Z,1575998344.885 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-12-10T17:19:04.979Z,1575998344.979 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-12-10T17:19:04.981Z,1575998344.981 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-12-10T17:19:05.178Z,1575998345.178 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-12-10T17:19:05.179Z,1575998345.179 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-12-10T17:19:05.311Z,1575998345.311 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-12-10T17:19:05.313Z,1575998345.313 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-12-10T17:19:05.912Z,1575998345.912 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-12-10T17:19:05.914Z,1575998345.914 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-12-10T17:19:06.346Z,1575998346.346 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-12-10T17:19:06.348Z,1575998346.348 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-12-10T17:19:06.796Z,1575998346.796 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-12-10T17:19:06.796Z,1575998346.796 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-12-10T17:19:07.150Z,1575998347.150 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-12-10T17:19:07.152Z,1575998347.152 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-12-10T17:19:07.463Z,1575998347.463 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-12-10T17:19:07.465Z,1575998347.465 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-12-10T17:19:07.861Z,1575998347.861 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-12-10T17:19:07.862Z,1575998347.862 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-12-10T17:19:08.007Z,1575998348.007 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-12-10T17:19:08.008Z,1575998348.008 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-12-10T17:19:08.111Z,1575998348.111 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-12-10T17:19:08.112Z,1575998348.112 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-12-10T17:19:08.424Z,1575998348.424 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-12-10T17:19:08.625Z,1575998348.625 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-12-10T17:19:08.626Z,1575998348.626 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-12-10T17:19:08.811Z,1575998348.811 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-12-10T17:19:08.811Z,1575998348.811 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-12-10T17:19:09.017Z,1575998349.017 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-12-10T17:19:09.019Z,1575998349.019 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/ 2019-12-10T17:19:09.023Z,1575998349.023 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg 2019-12-10T17:19:09.105Z,1575998349.105 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg 2019-12-10T17:19:09.329Z,1575998349.329 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-12-10T17:19:09.331Z,1575998349.331 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg 2019-12-10T17:19:09.425Z,1575998349.425 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg 2019-12-10T17:19:09.589Z,1575998349.589 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg 2019-12-10T17:19:09.790Z,1575998349.790 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg 2019-12-10T17:19:09.875Z,1575998349.875 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg 2019-12-10T17:19:09.975Z,1575998349.975 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg 2019-12-10T17:19:10.066Z,1575998350.066 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg 2019-12-10T17:19:10.218Z,1575998350.218 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg 2019-12-10T17:19:10.322Z,1575998350.322 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg 2019-12-10T17:19:10.420Z,1575998350.420 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-12-10T17:19:10.424Z,1575998350.424 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-12-10T17:19:10.548Z,1575998350.548 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-12-10T17:19:10.550Z,1575998350.550 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-12-10T17:19:10.703Z,1575998350.703 [BuoyancyServo] Loaded 2019-12-10T17:19:10.703Z,1575998350.703 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-12-10T17:19:10.718Z,1575998350.718 [ElevatorServo] Loaded 2019-12-10T17:19:10.718Z,1575998350.718 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-12-10T17:19:10.732Z,1575998350.732 [MassServo] Loaded 2019-12-10T17:19:10.732Z,1575998350.732 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-12-10T17:19:10.747Z,1575998350.747 [RudderServo] Loaded 2019-12-10T17:19:10.748Z,1575998350.748 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-12-10T17:19:10.762Z,1575998350.762 [ThrusterServo] Loaded 2019-12-10T17:19:10.762Z,1575998350.762 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-12-10T17:19:10.762Z,1575998350.762 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-12-10T17:19:10.763Z,1575998350.763 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-12-10T17:19:10.919Z,1575998350.919 [SBIT](DEBUG): Construct Startup Built In Test. 2019-12-10T17:19:10.946Z,1575998350.946 [SBIT] Loaded 2019-12-10T17:19:10.947Z,1575998350.947 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-12-10T17:19:10.947Z,1575998350.947 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-12-10T17:19:10.976Z,1575998350.976 [IBIT] Loaded 2019-12-10T17:19:10.976Z,1575998350.976 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-12-10T17:19:10.979Z,1575998350.979 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-12-10T17:19:11.358Z,1575998351.358 [CBIT] Loaded 2019-12-10T17:19:11.358Z,1575998351.358 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-12-10T17:19:11.359Z,1575998351.359 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-12-10T17:19:11.359Z,1575998351.359 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-12-10T17:19:11.625Z,1575998351.625 [Aanderaa_O2] Loaded 2019-12-10T17:19:11.626Z,1575998351.626 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2019-12-10T17:19:11.635Z,1575998351.635 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2019-12-10T17:19:11.640Z,1575998351.640 [CTD_Seabird](INFO): created writer for : sea_water_density 2019-12-10T17:19:11.642Z,1575998351.642 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2019-12-10T17:19:11.647Z,1575998351.647 [CTD_Seabird](INFO): created writer for : depth 2019-12-10T17:19:11.647Z,1575998351.647 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2019-12-10T17:19:11.652Z,1575998351.652 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2019-12-10T17:19:11.653Z,1575998351.653 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2019-12-10T17:19:11.658Z,1575998351.658 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2019-12-10T17:19:11.659Z,1575998351.659 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2019-12-10T17:19:11.664Z,1575998351.664 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2019-12-10T17:19:11.665Z,1575998351.665 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2019-12-10T17:19:11.670Z,1575998351.670 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2019-12-10T17:19:11.670Z,1575998351.670 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2019-12-10T17:19:11.675Z,1575998351.675 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2019-12-10T17:19:11.701Z,1575998351.701 [CTD_Seabird] Loaded 2019-12-10T17:19:11.701Z,1575998351.701 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2019-12-10T17:19:11.702Z,1575998351.702 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066C4E0 2019-12-10T17:19:11.703Z,1575998351.703 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 891 2019-12-10T17:19:11.733Z,1575998351.733 [ESPComponent] Loaded 2019-12-10T17:19:11.733Z,1575998351.733 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2019-12-10T17:19:11.747Z,1575998351.747 [PAR_Licor] Loaded 2019-12-10T17:19:11.747Z,1575998351.747 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-12-10T17:19:11.753Z,1575998351.753 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470 2019-12-10T17:19:11.753Z,1575998351.753 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470 2019-12-10T17:19:11.757Z,1575998351.757 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650 2019-12-10T17:19:11.758Z,1575998351.758 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650 2019-12-10T17:19:11.762Z,1575998351.762 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl 2019-12-10T17:19:11.762Z,1575998351.762 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl 2019-12-10T17:19:11.766Z,1575998351.766 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm 2019-12-10T17:19:11.766Z,1575998351.766 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm 2019-12-10T17:19:11.770Z,1575998351.770 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm 2019-12-10T17:19:11.770Z,1575998351.770 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm 2019-12-10T17:19:11.775Z,1575998351.775 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm 2019-12-10T17:19:11.775Z,1575998351.775 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm 2019-12-10T17:19:11.779Z,1575998351.779 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm 2019-12-10T17:19:11.779Z,1575998351.779 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm 2019-12-10T17:19:11.783Z,1575998351.783 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.788Z,1575998351.788 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.788Z,1575998351.788 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.788Z,1575998351.788 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.792Z,1575998351.792 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.793Z,1575998351.793 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.797Z,1575998351.797 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.797Z,1575998351.797 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water 2019-12-10T17:19:11.801Z,1575998351.801 [WetLabsBB2FL] Loaded 2019-12-10T17:19:11.801Z,1575998351.801 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2019-12-10T17:19:11.802Z,1575998351.802 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069C4E0 2019-12-10T17:19:11.803Z,1575998351.803 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 892 2019-12-10T17:19:11.803Z,1575998351.803 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-12-10T17:19:11.805Z,1575998351.805 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-12-10T17:19:11.859Z,1575998351.859 [DepthRateCalculator] Loaded 2019-12-10T17:19:11.859Z,1575998351.859 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-12-10T17:19:11.864Z,1575998351.864 [PitchRateCalculator] Loaded 2019-12-10T17:19:11.865Z,1575998351.865 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-12-10T17:19:11.880Z,1575998351.880 [SpeedCalculator] Loaded 2019-12-10T17:19:11.880Z,1575998351.880 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-12-10T17:19:11.900Z,1575998351.900 [TempGradientCalculator] Loaded 2019-12-10T17:19:11.901Z,1575998351.901 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-12-10T17:19:11.906Z,1575998351.906 [YawRateCalculator] Loaded 2019-12-10T17:19:11.906Z,1575998351.906 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-12-10T17:19:11.938Z,1575998351.938 [ElevatorOffsetCalculator] Loaded 2019-12-10T17:19:11.938Z,1575998351.938 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-12-10T17:19:11.939Z,1575998351.939 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-12-10T17:19:11.939Z,1575998351.939 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-12-10T17:19:11.988Z,1575998351.988 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-12-10T17:19:11.989Z,1575998351.989 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-12-10T17:19:12.104Z,1575998352.104 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-12-10T17:19:12.105Z,1575998352.105 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-12-10T17:19:12.125Z,1575998352.125 [NavChart] Loaded 2019-12-10T17:19:12.125Z,1575998352.125 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-12-10T17:19:12.129Z,1575998352.129 [UniversalFixResidualReporter] Loaded 2019-12-10T17:19:12.129Z,1575998352.129 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-12-10T17:19:12.129Z,1575998352.129 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-12-10T17:19:12.130Z,1575998352.130 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-12-10T17:19:12.641Z,1575998352.641 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2019-12-10T17:19:12.646Z,1575998352.646 [AHRS_M2](INFO): created writer for : platform_orientation 2019-12-10T17:19:12.647Z,1575998352.647 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2019-12-10T17:19:12.652Z,1575998352.652 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2019-12-10T17:19:12.652Z,1575998352.652 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2019-12-10T17:19:12.657Z,1575998352.657 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2019-12-10T17:19:12.658Z,1575998352.658 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2019-12-10T17:19:12.663Z,1575998352.663 [AHRS_M2](INFO): created writer for : platform_roll_angle 2019-12-10T17:19:12.839Z,1575998352.839 [AHRS_M2] Loaded 2019-12-10T17:19:12.840Z,1575998352.840 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-12-10T17:19:12.991Z,1575998352.991 [DataOverHttps] Loaded 2019-12-10T17:19:12.991Z,1575998352.991 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-12-10T17:19:12.992Z,1575998352.992 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4098A4E0 2019-12-10T17:19:12.993Z,1575998352.993 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 893 2019-12-10T17:19:13.006Z,1575998353.006 [Depth_Keller] Loaded 2019-12-10T17:19:13.006Z,1575998353.006 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-12-10T17:19:13.011Z,1575998353.011 [DropWeight] Loaded 2019-12-10T17:19:13.011Z,1575998353.011 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-12-10T17:19:13.056Z,1575998353.056 [DVL_micro] Loaded 2019-12-10T17:19:13.057Z,1575998353.057 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2019-12-10T17:19:13.144Z,1575998353.144 [NAL9602] Loaded 2019-12-10T17:19:13.144Z,1575998353.144 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-12-10T17:19:13.171Z,1575998353.171 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/voltage_now 2019-12-10T17:19:13.172Z,1575998353.172 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/current_now 2019-12-10T17:19:13.172Z,1575998353.172 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_now 2019-12-10T17:19:13.173Z,1575998353.173 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_full 2019-12-10T17:19:13.173Z,1575998353.173 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/voltage_now 2019-12-10T17:19:13.174Z,1575998353.174 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/current_now 2019-12-10T17:19:13.174Z,1575998353.174 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_now 2019-12-10T17:19:13.175Z,1575998353.175 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_full 2019-12-10T17:19:13.175Z,1575998353.175 [Onboard] Loaded 2019-12-10T17:19:13.175Z,1575998353.175 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-12-10T17:19:13.178Z,1575998353.178 [Radio_Surface] Loaded 2019-12-10T17:19:13.179Z,1575998353.179 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-12-10T17:19:13.180Z,1575998353.180 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409BA4E0 2019-12-10T17:19:13.180Z,1575998353.180 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 894 2019-12-10T17:19:13.608Z,1575998353.608 [DAT] Loaded 2019-12-10T17:19:13.609Z,1575998353.609 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2019-12-10T17:19:15.017Z,1575998355.017 [BPC1] Loaded 2019-12-10T17:19:15.017Z,1575998355.017 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-12-10T17:19:15.017Z,1575998355.017 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-12-10T17:19:15.018Z,1575998355.018 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-12-10T17:19:15.139Z,1575998355.139 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-12-10T17:19:15.140Z,1575998355.140 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-12-10T17:19:15.202Z,1575998355.202 [VerticalControl](DEBUG): Construct VerticalControl. 2019-12-10T17:19:15.283Z,1575998355.283 [VerticalControl] Loaded 2019-12-10T17:19:15.283Z,1575998355.283 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-12-10T17:19:15.284Z,1575998355.284 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-12-10T17:19:15.351Z,1575998355.351 [HorizontalControl] Loaded 2019-12-10T17:19:15.352Z,1575998355.352 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-12-10T17:19:15.353Z,1575998355.353 [SpeedControl](DEBUG): Construct SpeedControl. 2019-12-10T17:19:15.354Z,1575998355.354 [SpeedControl] Loaded 2019-12-10T17:19:15.354Z,1575998355.354 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-12-10T17:19:15.355Z,1575998355.355 [LoopControl](DEBUG): Construct LoopControl. 2019-12-10T17:19:15.355Z,1575998355.355 [LoopControl] Loaded 2019-12-10T17:19:15.356Z,1575998355.356 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-12-10T17:19:15.356Z,1575998355.356 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-12-10T17:19:15.357Z,1575998355.357 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-12-10T17:19:15.381Z,1575998355.381 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-12-10T17:19:15.381Z,1575998355.381 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-12-10T17:19:15.735Z,1575998355.735 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-12-10T17:19:15.738Z,1575998355.738 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-12-10T17:19:15.739Z,1575998355.739 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-12-10T17:19:15.745Z,1575998355.745 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-12-10T17:19:15.746Z,1575998355.746 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AF94E0 2019-12-10T17:19:15.747Z,1575998355.747 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 896 2019-12-10T17:19:15.751Z,1575998355.751 [Supervisor](INFO): Main Thread ID is 804 2019-12-10T17:19:15.751Z,1575998355.751 [Supervisor](DEBUG): Running supervisor. 2019-12-10T17:19:15.752Z,1575998355.752 [CommandLine ThreadHandler](INFO): Handler Thread ID is 897 2019-12-10T17:19:15.754Z,1575998355.754 [controlThread ThreadHandler](INFO): Handler Thread ID is 898 2019-12-10T17:19:15.755Z,1575998355.755 [controlThread](DEBUG): Initializing ControlThread 2019-12-10T17:19:15.757Z,1575998355.757 [SBIT](INFO): Initialize SBIT Component. 2019-12-10T17:19:15.758Z,1575998355.758 [SBIT](IMPORTANT): git: 2019-12-10 2019-12-10T17:19:15.758Z,1575998355.758 [SBIT](INFO): git hash: 66d82f7afabd4173e737eff51d4a73f4137f1e60 2019-12-10T17:19:15.758Z,1575998355.758 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-12-10T17:19:15.759Z,1575998355.759 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 2019-12-10T17:19:15.761Z,1575998355.761 [SBIT](INFO): Beginning SBIT in 72.000000 seconds. 2019-12-10T17:19:15.761Z,1575998355.761 [IBIT](INFO): Initialize IBIT Component. 2019-12-10T17:19:15.762Z,1575998355.762 [CBIT](DEBUG): Initialize CBIT Component. 2019-12-10T17:19:15.763Z,1575998355.763 [logger ThreadHandler](INFO): Handler Thread ID is 899 2019-12-10T17:19:15.772Z,1575998355.772 [CBIT](DEBUG): Initialized mux pins. 2019-12-10T17:19:15.773Z,1575998355.773 [CBIT](DEBUG): Initializing the watchdog timer. 2019-12-10T17:19:15.781Z,1575998355.781 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 900 2019-12-10T17:19:15.781Z,1575998355.781 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2019-12-10T17:19:15.785Z,1575998355.785 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20 2019-12-10T17:19:15.786Z,1575998355.786 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 902 2019-12-10T17:19:15.787Z,1575998355.787 [WetLabsBB2FL](INFO): Powering down 2019-12-10T17:19:15.797Z,1575998355.797 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-12-10T17:19:15.797Z,1575998355.797 [CBIT](DEBUG): Initializing heartbeat. 2019-12-10T17:19:15.868Z,1575998355.868 [CBIT](DEBUG): Deactivating GF circuits. 2019-12-10T17:19:15.869Z,1575998355.869 [CBIT](DEBUG): Deactivating emergency mode. 2019-12-10T17:19:15.904Z,1575998355.904 [CBIT](DEBUG): Backplane powered. 2019-12-10T17:19:15.909Z,1575998355.909 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 903 2019-12-10T17:19:15.910Z,1575998355.910 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-12-10T17:19:15.917Z,1575998355.917 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 904 2019-12-10T17:19:15.926Z,1575998355.926 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-12-10T17:19:15.926Z,1575998355.926 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-12-10T17:19:15.926Z,1575998355.926 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-12-10T17:19:15.927Z,1575998355.927 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-12-10T17:19:15.927Z,1575998355.927 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-12-10T17:19:15.927Z,1575998355.927 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-12-10T17:19:15.929Z,1575998355.929 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-12-10T17:19:15.930Z,1575998355.930 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-12-10T17:19:15.950Z,1575998355.950 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-12-10T17:19:15.952Z,1575998355.952 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-12-10T17:19:15.953Z,1575998355.953 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-12-10T17:19:15.953Z,1575998355.953 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-12-10T17:19:15.954Z,1575998355.954 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-12-10T17:19:16.035Z,1575998356.035 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 905 2019-12-10T17:19:16.117Z,1575998356.117 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-12-10T17:19:16.117Z,1575998356.117 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-12-10T17:19:16.117Z,1575998356.117 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-12-10T17:19:16.117Z,1575998356.117 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-12-10T17:19:16.117Z,1575998356.117 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-12-10T17:19:16.118Z,1575998356.118 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-12-10T17:19:16.118Z,1575998356.118 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-12-10T17:19:16.118Z,1575998356.118 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-12-10T17:19:16.118Z,1575998356.118 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-12-10T17:19:16.118Z,1575998356.118 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-12-10T17:19:16.119Z,1575998356.119 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-12-10T17:19:16.119Z,1575998356.119 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-12-10T17:19:16.119Z,1575998356.119 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-12-10T17:19:16.119Z,1575998356.119 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-12-10T17:19:16.119Z,1575998356.119 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-12-10T17:19:16.119Z,1575998356.119 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-12-10T17:19:16.124Z,1575998356.124 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-12-10T17:19:16.217Z,1575998356.217 [MissionManager](DEBUG): 2019-12-10T17:19:16.217Z,1575998356.217 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-12-10T17:19:16.283Z,1575998356.283 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-12-10T17:19:16.284Z,1575998356.284 [Default:A.Wait](DEBUG): Construct Wait. 2019-12-10T17:19:16.306Z,1575998356.306 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-12-10T17:19:16.321Z,1575998356.321 [Radio_Surface](INFO): Powering up 2019-12-10T17:19:16.332Z,1575998356.332 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-12-10T17:19:16.335Z,1575998356.335 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-12-10T17:19:16.358Z,1575998356.358 [Default:E.Execute](DEBUG): Construct Execute. 2019-12-10T17:19:16.381Z,1575998356.381 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2019-12-10T17:19:16.386Z,1575998356.386 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,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, 2019-12-10T17:19:16.422Z,1575998356.422 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-12-10T17:19:16.536Z,1575998356.536 [Depth_Keller](ERROR): Pressure reading out of range: 1895.684326 decibar 2019-12-10T17:19:16.570Z,1575998356.570 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2019-12-10T17:19:16.570Z,1575998356.570 [DAT](INFO): Powering up 2019-12-10T17:19:16.571Z,1575998356.571 [DAT](DEBUG): Initializing DAT. 2019-12-10T17:19:16.633Z,1575998356.633 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-12-10T17:19:16.653Z,1575998356.653 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2019-12-10T17:19:16.717Z,1575998356.717 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-12-10T17:19:16.729Z,1575998356.729 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-12-10T17:19:16.730Z,1575998356.730 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-12-10T17:19:16.741Z,1575998356.741 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-12-10T17:19:16.742Z,1575998356.742 [MassServo](DEBUG): Initializing EZServoServo. 2019-12-10T17:19:16.753Z,1575998356.753 [MassServo](DEBUG): Initializing MassServo. 2019-12-10T17:19:16.754Z,1575998356.754 [RudderServo](DEBUG): Initializing EZServoServo. 2019-12-10T17:19:16.765Z,1575998356.765 [RudderServo](DEBUG): Initializing RudderServo. 2019-12-10T17:19:16.766Z,1575998356.766 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-12-10T17:19:16.781Z,1575998356.781 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-12-10T17:19:19.741Z,1575998359.741 [Aanderaa_O2](INFO): Powering down 2019-12-10T17:19:27.821Z,1575998367.821 [DAT](DEBUG): 2019-12-10T17:19:27.822Z,1575998367.822 [DAT](DEBUG): Teledyne Benthos DAT-900 Series 2019-12-10T17:19:29.031Z,1575998369.031 [DAT](DEBUG): MF Frequency Band 2019-12-10T17:19:29.033Z,1575998369.033 [DAT](DEBUG): Directional Acoustic Transponder version 8.12.21 2019-12-10T17:19:29.033Z,1575998369.033 [DAT](DEBUG): Aug 16 2000 08:04:09 2019-12-10T17:19:29.838Z,1575998369.838 [DAT](DEBUG): Features enabled [Bearing] 2019-12-10T17:19:29.839Z,1575998369.839 [DAT](DEBUG): WARNING: diag.rom image not found; POST not performed 2019-12-10T17:19:30.242Z,1575998370.242 [DAT](DEBUG): CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2019-12-10T17:19:30.242Z,1575998370.242 [DAT](INFO): commRate: 800 2019-12-10T17:19:30.646Z,1575998370.646 [DAT](INFO): entering command mode 2019-12-10T17:19:31.049Z,1575998371.049 [DAT](DEBUG): checking for command mode acknowledgment 2019-12-10T17:19:31.453Z,1575998371.453 [DAT](DEBUG): checking for command mode acknowledgment 2019-12-10T17:19:31.857Z,1575998371.857 [DAT](DEBUG): checking for command mode acknowledgment 2019-12-10T17:19:31.858Z,1575998371.858 [DAT](INFO): command mode acknowledged 2019-12-10T17:19:31.858Z,1575998371.858 [DAT](INFO): setting verbose to 3 2019-12-10T17:19:32.262Z,1575998372.262 [DAT](DEBUG): checking for verbose setting acknowledgment 2019-12-10T17:19:32.262Z,1575998372.262 [DAT](INFO): set verbose to 3 2019-12-10T17:19:32.665Z,1575998372.665 [DAT](INFO): setting transmit power to 8 2019-12-10T17:19:33.069Z,1575998373.069 [DAT](DEBUG): checking for transmit power setting acknowledgment 2019-12-10T17:19:33.473Z,1575998373.473 [DAT](DEBUG): checking for transmit power setting acknowledgment 2019-12-10T17:19:33.474Z,1575998373.474 [DAT](INFO): set transmit power to 8 2019-12-10T17:19:33.859Z,1575998373.859 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T17:19:33.859Z,1575998373.859 [DVL_micro] Communications Fault, FailCount= 1 2019-12-10T17:19:33.860Z,1575998373.860 [DVL_micro](ERROR): Communications Fault 2019-12-10T17:19:33.880Z,1575998373.880 [DAT](INFO): setting local address to 4 2019-12-10T17:19:33.953Z,1575998373.953 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T17:19:34.337Z,1575998374.337 [DVL_micro](INFO): Powering down 2019-12-10T17:19:34.354Z,1575998374.354 [DAT](DEBUG): checking for local address setting acknowledgment 2019-12-10T17:19:34.700Z,1575998374.700 [DAT](DEBUG): checking for local address setting acknowledgment 2019-12-10T17:19:34.701Z,1575998374.701 [DAT](INFO): set local address to 4 2019-12-10T17:19:35.161Z,1575998375.161 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T17:19:35.161Z,1575998375.161 [DVL_micro] No Fault, FailCount= 1 2019-12-10T17:19:43.158Z,1575998383.158 [NAL9602](INFO): Powering up NAL9602 2019-12-10T17:19:52.850Z,1575998392.850 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T17:19:52.850Z,1575998392.850 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T17:19:52.850Z,1575998392.850 [DVL_micro](ERROR): Communications Fault 2019-12-10T17:19:52.955Z,1575998392.955 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T17:19:53.325Z,1575998393.325 [DVL_micro](INFO): Powering down 2019-12-10T17:19:54.068Z,1575998394.068 [NAL9602](INFO): NAL9602 initialized 2019-12-10T17:19:54.143Z,1575998394.143 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T17:19:54.144Z,1575998394.144 [DVL_micro] No Fault, FailCount= 2 2019-12-10T17:20:11.839Z,1575998411.839 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T17:20:11.839Z,1575998411.839 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T17:20:11.839Z,1575998411.839 [DVL_micro](ERROR): Communications Fault 2019-12-10T17:20:11.897Z,1575998411.897 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T17:20:11.898Z,1575998411.898 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T17:20:12.313Z,1575998412.313 [DVL_micro](INFO): Powering down 2019-12-10T17:20:12.362Z,1575998412.362 [CommandLine](FAULT): Scheduling is paused 2019-12-10T17:20:12.362Z,1575998412.362 [CBIT](INFO): Critical error at 20191210T172011 2019-12-10T17:20:12.363Z,1575998412.363 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2019-12-10T17:20:28.438Z,1575998428.438 [SBIT](IMPORTANT): Beginning Startup BIT 2019-12-10T17:20:28.442Z,1575998428.442 [CBIT](IMPORTANT): Beginning ground fault scan 2019-12-10T17:20:39.527Z,1575998439.527 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): 0.016016 CHAN A1 (24V): 0.016139 CHAN A2 (12V): 0.005547 CHAN A3 (5V): -0.005847 CHAN B0 (3.3V): -0.004898 CHAN B1 (3.15aV): -0.004875 CHAN B2 (3.15bV): -0.004060 CHAN B3 (GND): -0.007732 OPEN: 0.007542 Full Scale Calc: 4.765 mA, -1.589 mA 2019-12-10T17:20:49.384Z,1575998449.384 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:20:49.384Z,1575998449.384 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:21:16.608Z,1575998476.608 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:21:16.609Z,1575998476.609 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:21:21.885Z,1575998481.885 [SBIT](IMPORTANT): SBIT PASSED 2019-12-10T17:21:21.928Z,1575998481.928 [CommandLine](IMPORTANT): got command configSet list 2019-12-10T17:21:21.928Z,1575998481.928 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-12-10T17:21:21.929Z,1575998481.929 [CommandLine](IMPORTANT): No configSet variables persisted 2019-12-10T17:21:22.282Z,1575998482.282 [MissionManager](IMPORTANT): Started mission Startup 2019-12-10T17:21:22.282Z,1575998482.282 [Startup] Running Loop=1 2019-12-10T17:21:22.282Z,1575998482.282 [Startup](DEBUG): Aggregate::initialize Startup 2019-12-10T17:21:22.282Z,1575998482.282 [Startup:A.GoToSurface] Running Loop=1 2019-12-10T17:21:22.282Z,1575998482.282 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-12-10T17:21:22.283Z,1575998482.283 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-12-10T17:21:22.283Z,1575998482.283 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-12-10T17:21:22.284Z,1575998482.284 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-12-10T17:21:22.284Z,1575998482.284 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-12-10T17:21:22.285Z,1575998482.285 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-12-10T17:21:22.286Z,1575998482.286 [Startup:StartupSatComms] Running Loop=1 2019-12-10T17:21:22.286Z,1575998482.286 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-12-10T17:21:22.286Z,1575998482.286 [Startup:StartupSatComms:A] Running Loop=1 2019-12-10T17:21:22.729Z,1575998482.729 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-12-10T17:21:36.812Z,1575998496.812 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:21:36.813Z,1575998496.813 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:21:48.733Z,1575998508.733 [CommandLine](IMPORTANT): got command failComponent 2019-12-10T17:21:48.733Z,1575998508.733 [CommandLine](IMPORTANT): Failed components: 2019-12-10T17:21:48.734Z,1575998508.734 [CommandLine](IMPORTANT): DVL_micro: Communications Fault 2019-12-10T17:21:54.180Z,1575998514.180 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:21:54.180Z,1575998514.180 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:21:55.080Z,1575998515.080 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005825 2019-12-10T17:22:01.746Z,1575998521.746 [CommandLine](IMPORTANT): got command failComponent hardware DVL_micro 2019-12-10T17:22:01.747Z,1575998521.747 [DVL_micro] Hardware Fault, FailCount= 3 2019-12-10T17:22:01.747Z,1575998521.747 [DVL_micro](ERROR): Hardware Fault 2019-12-10T17:22:01.747Z,1575998521.747 [CommandLine](IMPORTANT): DVL_micro failureMode is Hardware Fault 2019-12-10T17:22:11.617Z,1575998531.617 [CommandLine](IMPORTANT): got command failComponent none DVL_micro 2019-12-10T17:22:11.618Z,1575998531.618 [DVL_micro] No Fault, FailCount= 3 2019-12-10T17:22:11.618Z,1575998531.618 [CommandLine](IMPORTANT): DVL_micro failureMode is No Fault 2019-12-10T17:22:16.032Z,1575998536.032 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-12-10T17:22:16.032Z,1575998536.032 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-12-10T17:22:16.042Z,1575998536.042 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-12-10T17:22:16.449Z,1575998536.449 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-12-10T17:22:16.449Z,1575998536.449 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-12-10T17:22:22.494Z,1575998542.494 [Startup:StartupSatComms:A](INFO): Timed out from 2019-12-10T17:21:22.3Z 2019-12-10T17:22:22.494Z,1575998542.494 [Startup:StartupSatComms:A] Stopped 2019-12-10T17:22:22.494Z,1575998542.494 [Startup:StartupSatComms:B] Running Loop=1 2019-12-10T17:22:22.887Z,1575998542.887 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-12-10T17:22:24.482Z,1575998544.482 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T17:22:24.482Z,1575998544.482 [DVL_micro] Data Fault, FailCount= 4 2019-12-10T17:22:24.482Z,1575998544.482 [DVL_micro](ERROR): Data Fault 2019-12-10T17:22:24.551Z,1575998544.551 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T17:22:24.551Z,1575998544.551 [CBIT](CRITICAL): Data Fault in component: DVL_micro 2019-12-10T17:22:24.953Z,1575998544.953 [DVL_micro](INFO): Powering down 2019-12-10T17:22:24.989Z,1575998544.989 [CBIT](INFO): Critical error at 20191210T172224 2019-12-10T17:22:34.065Z,1575998554.065 [DataOverHttps](INFO): Sending 102 bytes from file Logs/20191210T171904/Courier0000.lzma 2019-12-10T17:22:36.070Z,1575998556.070 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0000.lzma.bak 2019-12-10T17:22:36.070Z,1575998556.070 [DataOverHttps](INFO): SBD MOMSN=12138466 2019-12-10T17:22:57.707Z,1575998577.707 [DataOverHttps](INFO): Sending 858 bytes from file Logs/20191210T170802/Express0005.lzma 2019-12-10T17:22:59.710Z,1575998579.710 [DataOverHttps](INFO): Moved sent file to Logs/20191210T170802/Express0005.lzma.bak 2019-12-10T17:22:59.710Z,1575998579.710 [DataOverHttps](INFO): SBD MOMSN=12138470 2019-12-10T17:23:19.813Z,1575998599.813 [DataOverHttps](INFO): Sending 1663 bytes from file Logs/20191210T171427/Express0001.lzma 2019-12-10T17:23:21.814Z,1575998601.814 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171427/Express0001.lzma.bak 2019-12-10T17:23:21.814Z,1575998601.814 [DataOverHttps](INFO): SBD MOMSN=12138530 2019-12-10T17:23:22.702Z,1575998602.702 [Startup:StartupSatComms:B](INFO): Timed out from 2019-12-10T17:22:22.5Z 2019-12-10T17:23:22.702Z,1575998602.702 [Startup:StartupSatComms:B] Stopped 2019-12-10T17:23:22.702Z,1575998602.702 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-12-10T17:23:22.702Z,1575998602.702 [Startup:StartupSatComms] Stopped 2019-12-10T17:23:22.702Z,1575998602.702 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-12-10T17:23:22.703Z,1575998602.703 [Startup](INFO): Completed Startup 2019-12-10T17:23:22.703Z,1575998602.703 [MissionManager](INFO): Startup is completed. 2019-12-10T17:23:22.703Z,1575998602.703 [MissionManager](INFO): Uninitializing Mission Startup 2019-12-10T17:23:22.703Z,1575998602.703 [Startup] Stopped 2019-12-10T17:23:22.704Z,1575998602.704 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-12-10T17:23:22.704Z,1575998602.704 [Startup:A.GoToSurface] Stopped 2019-12-10T17:23:22.704Z,1575998602.704 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-12-10T17:23:23.138Z,1575998603.138 [MissionManager](IMPORTANT): Started mission Default 2019-12-10T17:23:23.138Z,1575998603.138 [Default] Running Loop=1 2019-12-10T17:23:23.138Z,1575998603.138 [Default](DEBUG): Aggregate::initialize Default 2019-12-10T17:23:23.138Z,1575998603.138 [Default:B.GoToSurface] Running Loop=1 2019-12-10T17:23:23.138Z,1575998603.138 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-12-10T17:23:23.138Z,1575998603.138 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-12-10T17:23:23.139Z,1575998603.139 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-12-10T17:23:23.139Z,1575998603.139 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-12-10T17:23:23.139Z,1575998603.139 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-12-10T17:23:23.140Z,1575998603.140 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-12-10T17:23:23.140Z,1575998603.140 [Default:A.Wait] Running Loop=1 2019-12-10T17:23:23.140Z,1575998603.140 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-12-10T17:23:36.441Z,1575998616.441 [Default:A.Wait](INFO): Done Waiting. 2019-12-10T17:23:36.441Z,1575998616.441 [Default:A.Wait] Stopped 2019-12-10T17:23:36.441Z,1575998616.441 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T17:23:36.850Z,1575998616.850 [Default:CheckIn] Running Loop=1 2019-12-10T17:23:36.850Z,1575998616.850 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T17:23:36.850Z,1575998616.850 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T17:23:37.233Z,1575998617.233 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-12-10T17:23:57.429Z,1575998637.429 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:23:57.429Z,1575998637.429 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:24:49.530Z,1575998689.530 [CommandLine](IMPORTANT): got command failComponent none DVL_micro 2019-12-10T17:24:49.531Z,1575998689.531 [DVL_micro] No Fault, FailCount= 4 2019-12-10T17:24:49.531Z,1575998689.531 [CommandLine](IMPORTANT): DVL_micro failureMode is No Fault 2019-12-10T17:24:57.615Z,1575998697.615 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-12-10T17:24:58.021Z,1575998698.021 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:24:58.021Z,1575998698.021 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+17.8,0000.0,00 2019-12-10T17:25:17.041Z,1575998717.041 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2019-12-10T17:25:17.041Z,1575998717.041 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-12-10T17:25:17.050Z,1575998717.050 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-12-10T17:25:17.461Z,1575998717.461 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-12-10T17:25:17.462Z,1575998717.462 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2019-12-10T17:25:23.322Z,1575998723.322 [CommandLine](IMPORTANT): got command failComponent 2019-12-10T17:25:23.322Z,1575998723.322 [CommandLine](IMPORTANT): Failed components: 2019-12-10T17:25:23.322Z,1575998723.322 [CommandLine](IMPORTANT): No failed Components. 2019-12-10T17:25:53.774Z,1575998753.774 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 860 2019-12-10T17:25:53.777Z,1575998753.777 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-12-10T17:26:21.649Z,1575998781.649 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:26:21.649Z,1575998781.649 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0,+0.0,1489:WI,-0080,-01226, 2019-12-10T17:27:17.403Z,1575998837.403 [DVL_micro](ERROR): Failed to parse:00000000000,38,0000.0,14 2019-12-10T17:27:18.647Z,1575998838.647 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-12-10T17:27:18.648Z,1575998838.648 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-12-10T17:27:18.649Z,1575998838.649 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5. 2019-12-10T17:27:18.652Z,1575998838.652 [BPC1](INFO): Received data from all battery sticks. 2019-12-10T17:27:47.710Z,1575998867.710 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172746.00,A,3648.15262,N,12147.31062,W,0.641,0.00,101219,,,A*78 2019-12-10T17:27:47.714Z,1575998867.714 [NAL9602](INFO): GPS fix at 20191210T172746: (36.802544, -121.788510) 2019-12-10T17:27:47.761Z,1575998867.761 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T17:27:47.761Z,1575998867.761 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T17:27:48.155Z,1575998868.155 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-12-10T17:27:55.408Z,1575998875.408 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+17.9,0000.0,1489.0,000 2019-12-10T17:27:57.153Z,1575998877.153 [DataOverHttps](INFO): Sending 343 bytes from file Logs/20191210T171904/Courier0004.lzma 2019-12-10T17:27:59.158Z,1575998879.158 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0004.lzma.bak 2019-12-10T17:27:59.158Z,1575998879.158 [DataOverHttps](INFO): SBD MOMSN=12138634 2019-12-10T17:28:16.804Z,1575998896.804 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20191210T171427/Express0005.lzma 2019-12-10T17:28:18.810Z,1575998898.810 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171427/Express0005.lzma.bak 2019-12-10T17:28:18.810Z,1575998898.810 [DataOverHttps](INFO): SBD MOMSN=12138638 2019-12-10T17:28:20.044Z,1575998900.044 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T17:28:25.700Z,1575998905.700 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:28:25.700Z,1575998905.700 [DVL_micro](ERROR): Failed to parse: :TS,000000000000017.9,0000.0,1489.0,000 2019-12-10T17:28:35.821Z,1575998915.821 [DataOverHttps](INFO): Sending 742 bytes from file Logs/20191210T171904/Express0001.lzma 2019-12-10T17:28:37.826Z,1575998917.826 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0001.lzma.bak 2019-12-10T17:28:37.826Z,1575998917.826 [DataOverHttps](INFO): SBD MOMSN=12138641 2019-12-10T17:28:55.357Z,1575998935.357 [DataOverHttps](INFO): Sending 438 bytes from file Logs/20191210T171904/Express0005.lzma 2019-12-10T17:28:57.362Z,1575998937.362 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0005.lzma.bak 2019-12-10T17:28:57.362Z,1575998937.362 [DataOverHttps](INFO): SBD MOMSN=12138663 2019-12-10T17:28:58.478Z,1575998938.478 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T17:28:58.479Z,1575998938.479 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T17:28:58.479Z,1575998938.479 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T17:29:01.272Z,1575998941.272 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:29:01.272Z,1575998941.272 [DVL_micro](ERROR): Failed to parse: :TS,000000,35,0000.0,1489.0,000 2019-12-10T17:30:07.111Z,1575999007.111 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:30:07.111Z,1575999007.111 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+18.0,0000.,000 2019-12-10T17:31:12.974Z,1575999072.974 [DVL_micro](ERROR): only read 3 of 4 data items 2019-12-10T17:31:12.974Z,1575999072.974 [DVL_micro](ERROR): Failed to parse: :BI,-01007,-0477,+00000,I 2019-12-10T17:31:53.376Z,1575999113.376 [DVL_micro](ERROR): only read 3 of 4 data items 2019-12-10T17:31:53.377Z,1575999113.377 [DVL_micro](ERROR): Failed to parse: :BI,-0116,-01239,+00000,I 2019-12-10T17:33:59.058Z,1575999239.058 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T17:33:59.058Z,1575999239.058 [Default:CheckIn:C.Wait] Stopped 2019-12-10T17:33:59.058Z,1575999239.058 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T17:33:59.058Z,1575999239.058 [Default:CheckIn:D] Running Loop=1 2019-12-10T17:33:59.471Z,1575999239.471 [Default:CheckIn:D] Stopped 2019-12-10T17:33:59.471Z,1575999239.471 [Default:CheckIn:E] Running Loop=1 2019-12-10T17:33:59.892Z,1575999239.892 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.605550 min 2019-12-10T17:33:59.892Z,1575999239.892 [Default:CheckIn:E] Stopped 2019-12-10T17:33:59.896Z,1575999239.896 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T17:33:59.897Z,1575999239.897 [Default:CheckIn] Stopped 2019-12-10T17:33:59.897Z,1575999239.897 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T17:33:59.897Z,1575999239.897 [Default:CheckIn](INFO): Running loop #2 2019-12-10T17:33:59.897Z,1575999239.897 [Default:CheckIn] Running Loop=2 2019-12-10T17:33:59.897Z,1575999239.897 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T17:33:59.897Z,1575999239.897 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T17:34:01.866Z,1575999241.866 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173400.00,A,3648.15538,N,12147.27485,W,3.790,140.59,101219,,,A*7D 2019-12-10T17:34:01.868Z,1575999241.868 [NAL9602](INFO): GPS fix at 20191210T173400: (36.802590, -121.787914) 2019-12-10T17:34:01.917Z,1575999241.917 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T17:34:01.917Z,1575999241.917 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T17:34:12.072Z,1575999252.072 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191210T171904/Courier0007.lzma 2019-12-10T17:34:14.078Z,1575999254.078 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0007.lzma.bak 2019-12-10T17:34:14.078Z,1575999254.078 [DataOverHttps](INFO): SBD MOMSN=12138692 2019-12-10T17:34:25.339Z,1575999265.339 [DVL_micro](ERROR): Failed to parse: 9.99,+99999.99,+9999.99 2019-12-10T17:34:31.348Z,1575999271.348 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20191210T171904/Express0008.lzma 2019-12-10T17:34:32.603Z,1575999272.603 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-12-10T17:34:32.681Z,1575999272.681 [NAL9602](FAULT): received: +CSQ:0 OK188, 2, 0, 0, 0 OK 2019-12-10T17:34:32.681Z,1575999272.681 [NAL9602] Data Fault, FailCount= 1 2019-12-10T17:34:32.681Z,1575999272.681 [NAL9602](ERROR): Data Fault 2019-12-10T17:34:32.755Z,1575999272.755 [CBIT](ERROR): Data Fault in component: NAL9602 2019-12-10T17:34:33.020Z,1575999273.020 [NAL9602](INFO): Powering down 2019-12-10T17:34:33.354Z,1575999273.354 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0008.lzma.bak 2019-12-10T17:34:33.354Z,1575999273.354 [DataOverHttps](INFO): SBD MOMSN=12138695 2019-12-10T17:34:33.860Z,1575999273.860 [CBIT](INFO): Clearing failed state for component NAL9602 2019-12-10T17:34:33.860Z,1575999273.860 [NAL9602] No Fault, FailCount= 1 2019-12-10T17:34:34.646Z,1575999274.646 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T17:34:34.646Z,1575999274.646 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T17:34:34.646Z,1575999274.646 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T17:35:03.315Z,1575999303.315 [NAL9602](INFO): Powering up NAL9602 2019-12-10T17:35:14.213Z,1575999314.213 [NAL9602](INFO): NAL9602 initialized 2019-12-10T17:35:44.533Z,1575999344.533 [DataOverHttps](IMPORTANT): SBD MTMSN=20191210T173541 2019-12-10T17:35:45.321Z,1575999345.321 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T17:35:51.389Z,1575999351.389 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:35:51.389Z,1575999351.389 [DVL_micro](ERROR): Failed to parse: :TS,000000,.1,0000.0,00 2019-12-10T17:35:51.941Z,1575999351.941 [DataOverHttps](INFO): Received command:ibit 2019-12-10T17:35:52.033Z,1575999352.033 [CommandLine](IMPORTANT): got command ibit 2019-12-10T17:35:52.238Z,1575999352.238 [IBIT](IMPORTANT): Beginning Initiated BIT 2019-12-10T17:35:52.238Z,1575999352.238 [IBIT](IMPORTANT): Beginning control surface checks. 2019-12-10T17:35:52.241Z,1575999352.241 [CBIT](IMPORTANT): Beginning ground fault scan 2019-12-10T17:36:03.163Z,1575999363.163 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): 0.012344 CHAN A1 (24V): 0.011664 CHAN A2 (12V): 0.004626 CHAN A3 (5V): -0.005068 CHAN B0 (3.3V): -0.004950 CHAN B1 (3.15aV): -0.004231 CHAN B2 (3.15bV): -0.003877 CHAN B3 (GND): -0.008322 OPEN: 0.007334 Full Scale Calc: 4.765 mA, -1.589 mA 2019-12-10T17:36:12.802Z,1575999372.802 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:36:12.803Z,1575999372.803 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:36:19.668Z,1575999379.668 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:36:19.668Z,1575999379.668 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:36:28.566Z,1575999388.566 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:36:28.567Z,1575999388.567 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:36:46.336Z,1575999406.336 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:36:46.337Z,1575999406.337 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:36:53.602Z,1575999413.602 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:36:53.602Z,1575999413.602 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:02.117Z,1575999422.117 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:02.117Z,1575999422.117 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:09.777Z,1575999429.777 [DVL_micro](ERROR): Failed to parse: :WI,-00994,+00101,-01235,+00000,A 2019-12-10T17:37:11.389Z,1575999431.389 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:11.389Z,1575999431.389 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:19.546Z,1575999439.546 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:19.546Z,1575999439.546 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:27.947Z,1575999447.947 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:27.947Z,1575999447.947 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:32.791Z,1575999452.791 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:32.791Z,1575999452.791 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:40.088Z,1575999460.088 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:40.089Z,1575999460.089 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:43.341Z,1575999463.341 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired. 2019-12-10T17:37:43.742Z,1575999463.742 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 0.000000 Voltage: 0.000000 2019-12-10T17:37:43.742Z,1575999463.742 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah 2019-12-10T17:37:43.743Z,1575999463.743 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V 2019-12-10T17:37:44.163Z,1575999464.163 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2019-12-10T17:37:44.164Z,1575999464.164 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2019-12-10T17:37:44.164Z,1575999464.164 [IBIT](IMPORTANT): Pressure:9.838083 PSI 2019-12-10T17:37:44.165Z,1575999464.165 [IBIT](IMPORTANT): Humidity:31.168356 % 2019-12-10T17:37:44.557Z,1575999464.557 [IBIT](IMPORTANT): Vehicle Pitch:1.121959 degrees 2019-12-10T17:37:44.558Z,1575999464.558 [IBIT](IMPORTANT): Vehicle Roll:7.443010 degrees 2019-12-10T17:37:44.558Z,1575999464.558 [IBIT](IMPORTANT): Vehicle Heading:217.241974 degrees 2019-12-10T17:37:44.992Z,1575999464.992 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m 2019-12-10T17:37:44.993Z,1575999464.993 [IBIT](IMPORTANT): buoyancyNeutral: 209.000000 cc 2019-12-10T17:37:44.993Z,1575999464.993 [IBIT](IMPORTANT): massDefault: 1.300000 cm 2019-12-10T17:37:44.993Z,1575999464.993 [IBIT](IMPORTANT): stopDepth: 50.000000 m 2019-12-10T17:37:44.994Z,1575999464.994 [IBIT](IMPORTANT): abortDepth: 60.000000 m 2019-12-10T17:37:44.994Z,1575999464.994 [IBIT](IMPORTANT): IBIT FAILED 2019-12-10T17:37:48.554Z,1575999468.554 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:48.554Z,1575999468.554 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:37:57.038Z,1575999477.038 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:37:57.038Z,1575999477.038 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:38:05.918Z,1575999485.918 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:38:05.918Z,1575999485.918 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:38:14.403Z,1575999494.403 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:38:14.403Z,1575999494.403 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:38:18.043Z,1575999498.043 [DVL_micro](ERROR): only read 3 of 4 data items 2019-12-10T17:38:18.043Z,1575999498.043 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.99, 2019-12-10T17:38:23.306Z,1575999503.306 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:38:23.307Z,1575999503.307 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:38:28.140Z,1575999508.140 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+18.1,0000.0,1489.0,000 2019-12-10T17:38:32.183Z,1575999512.183 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:38:32.184Z,1575999512.184 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:38:40.677Z,1575999520.677 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:38:40.677Z,1575999520.677 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:38:45.523Z,1575999525.523 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:38:45.523Z,1575999525.523 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:38:54.007Z,1575999534.007 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:38:54.008Z,1575999534.008 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:39:02.503Z,1575999542.503 [NAL9602](INFO): SBD MO Status=2, MOMSN=36188, MT Status=2, MTMSN=0 2019-12-10T17:39:02.504Z,1575999542.504 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T17:39:04.521Z,1575999544.521 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-12-10T17:39:26.337Z,1575999566.337 [DVL_micro](ERROR): Failed to parse: :WI,-00902,+00010,-01225,+00000,A 2019-12-10T17:39:35.225Z,1575999575.225 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T17:39:35.249Z,1575999575.249 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T17:39:35.249Z,1575999575.249 [Default:CheckIn:C.Wait] Stopped 2019-12-10T17:39:35.249Z,1575999575.249 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T17:39:35.249Z,1575999575.249 [Default:CheckIn:D] Running Loop=1 2019-12-10T17:39:35.650Z,1575999575.650 [Default:CheckIn:D] Stopped 2019-12-10T17:39:35.650Z,1575999575.650 [Default:CheckIn:E] Running Loop=1 2019-12-10T17:39:36.074Z,1575999576.074 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.208529 min 2019-12-10T17:39:36.075Z,1575999576.075 [Default:CheckIn:E] Stopped 2019-12-10T17:39:36.075Z,1575999576.075 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T17:39:36.075Z,1575999576.075 [Default:CheckIn] Stopped 2019-12-10T17:39:36.075Z,1575999576.075 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T17:39:36.076Z,1575999576.076 [Default:CheckIn](INFO): Running loop #3 2019-12-10T17:39:36.076Z,1575999576.076 [Default:CheckIn] Running Loop=3 2019-12-10T17:39:36.076Z,1575999576.076 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T17:39:36.076Z,1575999576.076 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T17:39:38.054Z,1575999578.054 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173934.00,A,3648.16649,N,12147.21675,W,0.019,15.72,101219,,,A*47 2019-12-10T17:39:38.057Z,1575999578.057 [NAL9602](INFO): GPS fix at 20191210T173934: (36.802775, -121.786946) 2019-12-10T17:39:38.104Z,1575999578.104 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T17:39:38.104Z,1575999578.104 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T17:39:47.996Z,1575999587.996 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191210T171904/Courier0010.lzma 2019-12-10T17:39:50.002Z,1575999590.002 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0010.lzma.bak 2019-12-10T17:39:50.002Z,1575999590.002 [DataOverHttps](INFO): SBD MOMSN=12138713 2019-12-10T17:40:07.202Z,1575999607.202 [DataOverHttps](INFO): Sending 887 bytes from file Logs/20191210T171904/Express0011.lzma 2019-12-10T17:40:08.753Z,1575999608.753 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-12-10T17:40:08.833Z,1575999608.833 [NAL9602](FAULT): received: +SBDI: 2, 36188, 2, 0, 0, 0 OK 2019-12-10T17:40:08.833Z,1575999608.833 [NAL9602] Data Fault, FailCount= 1 2019-12-10T17:40:08.833Z,1575999608.833 [NAL9602](ERROR): Data Fault 2019-12-10T17:40:08.873Z,1575999608.873 [CBIT](ERROR): Data Fault in component: NAL9602 2019-12-10T17:40:09.166Z,1575999609.166 [NAL9602](INFO): Powering down 2019-12-10T17:40:09.206Z,1575999609.206 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0011.lzma.bak 2019-12-10T17:40:09.206Z,1575999609.206 [DataOverHttps](INFO): SBD MOMSN=12138717 2019-12-10T17:40:10.007Z,1575999610.007 [CBIT](INFO): Clearing failed state for component NAL9602 2019-12-10T17:40:10.007Z,1575999610.007 [NAL9602] No Fault, FailCount= 1 2019-12-10T17:40:26.192Z,1575999626.192 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191210T171904/Express0014.lzma 2019-12-10T17:40:28.198Z,1575999628.198 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0014.lzma.bak 2019-12-10T17:40:28.198Z,1575999628.198 [DataOverHttps](INFO): SBD MOMSN=12138745 2019-12-10T17:40:29.396Z,1575999629.396 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T17:40:29.396Z,1575999629.396 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T17:40:29.396Z,1575999629.396 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T17:40:39.475Z,1575999639.475 [NAL9602](INFO): Powering up NAL9602 2019-12-10T17:40:50.369Z,1575999650.369 [NAL9602](INFO): NAL9602 initialized 2019-12-10T17:41:08.538Z,1575999668.538 [DataOverHttps](IMPORTANT): SBD MTMSN=20191210T174104 2019-12-10T17:41:15.976Z,1575999675.976 [DataOverHttps](INFO): Received command:ibit 2019-12-10T17:41:16.025Z,1575999676.025 [CommandLine](IMPORTANT): got command ibit 2019-12-10T17:41:16.266Z,1575999676.266 [IBIT](IMPORTANT): Beginning Initiated BIT 2019-12-10T17:41:16.266Z,1575999676.266 [IBIT](IMPORTANT): Beginning control surface checks. 2019-12-10T17:41:16.269Z,1575999676.269 [CBIT](IMPORTANT): Beginning ground fault scan 2019-12-10T17:41:24.710Z,1575999684.710 [NAL9602](INFO): SBD MO Status=0, MOMSN=36188, MT Status=0, MTMSN=0 2019-12-10T17:41:24.710Z,1575999684.710 [NAL9602](INFO): No messages in MT queue 2019-12-10T17:41:27.183Z,1575999687.183 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): 0.015360 CHAN A1 (24V): 0.015352 CHAN A2 (12V): 0.005472 CHAN A3 (5V): -0.005482 CHAN B0 (3.3V): -0.005851 CHAN B1 (3.15aV): -0.005105 CHAN B2 (3.15bV): -0.004345 CHAN B3 (GND): -0.008331 OPEN: 0.007469 Full Scale Calc: 4.765 mA, -1.589 mA 2019-12-10T17:41:34.810Z,1575999694.810 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174131.00,A,3648.16846,N,12147.21536,W,0.603,287.43,101219,,,A*7E 2019-12-10T17:41:34.812Z,1575999694.812 [NAL9602](INFO): GPS fix at 20191210T174131: (36.802808, -121.786923) 2019-12-10T17:41:40.868Z,1575999700.868 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174137.00,A,3648.17229,N,12147.21406,W,0.292,205.32,101219,,,A*78 2019-12-10T17:41:40.870Z,1575999700.870 [NAL9602](INFO): GPS fix at 20191210T174137: (36.802872, -121.786901) 2019-12-10T17:41:43.698Z,1575999703.698 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174140.00,A,3648.16718,N,12147.21545,W,1.497,195.71,101219,,,A*77 2019-12-10T17:41:43.700Z,1575999703.700 [NAL9602](INFO): GPS fix at 20191210T174140: (36.802786, -121.786924) 2019-12-10T17:41:45.332Z,1575999705.332 [DVL_micro](ERROR): Failed to parse:99.99,+99999.99,+9999.99 2019-12-10T17:41:46.928Z,1575999706.928 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174143.00,A,3648.16949,N,12147.21541,W,0.972,250.95,101219,,,A*7D 2019-12-10T17:41:46.930Z,1575999706.930 [NAL9602](INFO): GPS fix at 20191210T174143: (36.802825, -121.786924) 2019-12-10T17:41:49.755Z,1575999709.755 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174146.00,A,3648.17365,N,12147.21380,W,0.875,250.95,101219,,,A*70 2019-12-10T17:41:49.757Z,1575999709.757 [NAL9602](INFO): GPS fix at 20191210T174146: (36.802894, -121.786897) 2019-12-10T17:41:55.814Z,1575999715.814 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174152.00,A,3648.17492,N,12147.21341,W,0.505,313.85,101219,,,A*7A 2019-12-10T17:41:55.829Z,1575999715.829 [NAL9602](INFO): GPS fix at 20191210T174152: (36.802915, -121.786890) 2019-12-10T17:41:58.648Z,1575999718.648 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174155.00,A,3648.16810,N,12147.21593,W,0.136,313.85,101219,,,A*77 2019-12-10T17:41:58.650Z,1575999718.650 [NAL9602](INFO): GPS fix at 20191210T174155: (36.802802, -121.786932) 2019-12-10T17:42:01.880Z,1575999721.880 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174158.00,A,3648.16777,N,12147.21657,W,0.214,313.85,101219,,,A*7C 2019-12-10T17:42:01.882Z,1575999721.882 [NAL9602](INFO): GPS fix at 20191210T174158: (36.802796, -121.786943) 2019-12-10T17:42:02.716Z,1575999722.716 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 5 Latitude: 36.802795 Longitude: -121.786942 2019-12-10T17:42:03.182Z,1575999723.182 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 0.000000 Voltage: 0.000000 2019-12-10T17:42:03.182Z,1575999723.182 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah 2019-12-10T17:42:03.183Z,1575999723.183 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V 2019-12-10T17:42:03.529Z,1575999723.529 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2019-12-10T17:42:03.529Z,1575999723.529 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2019-12-10T17:42:03.529Z,1575999723.529 [IBIT](IMPORTANT): Pressure:9.767176 PSI 2019-12-10T17:42:03.530Z,1575999723.530 [IBIT](IMPORTANT): Humidity:31.064583 % 2019-12-10T17:42:03.933Z,1575999723.933 [IBIT](IMPORTANT): Vehicle Pitch:1.630761 degrees 2019-12-10T17:42:03.933Z,1575999723.933 [IBIT](IMPORTANT): Vehicle Roll:6.185095 degrees 2019-12-10T17:42:03.933Z,1575999723.933 [IBIT](IMPORTANT): Vehicle Heading:195.434326 degrees 2019-12-10T17:42:04.339Z,1575999724.339 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m 2019-12-10T17:42:04.339Z,1575999724.339 [IBIT](IMPORTANT): buoyancyNeutral: 209.000000 cc 2019-12-10T17:42:04.339Z,1575999724.339 [IBIT](IMPORTANT): massDefault: 1.300000 cm 2019-12-10T17:42:04.340Z,1575999724.340 [IBIT](IMPORTANT): stopDepth: 50.000000 m 2019-12-10T17:42:04.340Z,1575999724.340 [IBIT](IMPORTANT): abortDepth: 60.000000 m 2019-12-10T17:42:04.340Z,1575999724.340 [IBIT](IMPORTANT): IBIT PASSED 2019-12-10T17:42:34.192Z,1575999754.192 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T17:43:39.256Z,1575999819.256 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:43:39.256Z,1575999819.256 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,.0,0000.0,1489.0,000 2019-12-10T17:45:29.980Z,1575999929.980 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T17:45:29.980Z,1575999929.980 [Default:CheckIn:C.Wait] Stopped 2019-12-10T17:45:29.980Z,1575999929.980 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T17:45:29.980Z,1575999929.980 [Default:CheckIn:D] Running Loop=1 2019-12-10T17:45:30.391Z,1575999930.391 [Default:CheckIn:D] Stopped 2019-12-10T17:45:30.391Z,1575999930.391 [Default:CheckIn:E] Running Loop=1 2019-12-10T17:45:30.792Z,1575999930.792 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.120886 min 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn:E] Stopped 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn] Stopped 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn](INFO): Running loop #4 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn] Running Loop=4 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T17:45:30.793Z,1575999930.793 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T17:45:32.795Z,1575999932.795 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174528.00,A,3648.16588,N,12147.21378,W,0.019,313.85,101219,,,A*7A 2019-12-10T17:45:32.819Z,1575999932.819 [NAL9602](INFO): GPS fix at 20191210T174528: (36.802765, -121.786896) 2019-12-10T17:45:32.842Z,1575999932.842 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T17:45:32.842Z,1575999932.842 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T17:45:40.528Z,1575999940.528 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191210T171904/Courier0016.lzma 2019-12-10T17:45:42.534Z,1575999942.534 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0016.lzma.bak 2019-12-10T17:45:42.534Z,1575999942.534 [DataOverHttps](INFO): SBD MOMSN=12138781 2019-12-10T17:45:44.096Z,1575999944.096 [NAL9602](INFO): SBD MO Status=0, MOMSN=36189, MT Status=0, MTMSN=0 2019-12-10T17:45:44.096Z,1575999944.096 [NAL9602](INFO): No messages in MT queue 2019-12-10T17:46:02.729Z,1575999962.729 [DataOverHttps](INFO): Sending 797 bytes from file Logs/20191210T171904/Express0017.lzma 2019-12-10T17:46:04.734Z,1575999964.734 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0017.lzma.bak 2019-12-10T17:46:04.734Z,1575999964.734 [DataOverHttps](INFO): SBD MOMSN=12138785 2019-12-10T17:46:05.919Z,1575999965.919 [DVL_micro](ERROR): Failed to parse: :WI,-01174,+00125,-01265,+00000,A 2019-12-10T17:46:14.800Z,1575999974.800 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T17:46:25.016Z,1575999985.016 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191210T171904/Express0020.lzma 2019-12-10T17:46:27.022Z,1575999987.022 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0020.lzma.bak 2019-12-10T17:46:27.022Z,1575999987.022 [DataOverHttps](INFO): SBD MOMSN=12138812 2019-12-10T17:46:28.177Z,1575999988.177 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T17:46:28.177Z,1575999988.177 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T17:46:28.177Z,1575999988.177 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T17:46:54.007Z,1576000014.007 [DVL_micro](ERROR): Failed to parse: :WI,-00804,-00100,-01180,+00000,A 2019-12-10T17:50:11.193Z,1576000211.193 [DataOverHttps](IMPORTANT): SBD MTMSN=20191210T175006 2019-12-10T17:50:22.784Z,1576000222.784 [DataOverHttps](INFO): Received command:Ibit 2019-12-10T17:50:22.857Z,1576000222.857 [CommandLine](IMPORTANT): got command ibit 2019-12-10T17:50:22.910Z,1576000222.910 [IBIT](IMPORTANT): Beginning Initiated BIT 2019-12-10T17:50:22.910Z,1576000222.910 [IBIT](IMPORTANT): Beginning control surface checks. 2019-12-10T17:50:22.929Z,1576000222.929 [CBIT](IMPORTANT): Beginning ground fault scan 2019-12-10T17:50:24.485Z,1576000224.485 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175021.00,A,3648.16499,N,12147.21476,W,0.078,246.98,101219,,,A*75 2019-12-10T17:50:24.487Z,1576000224.487 [NAL9602](INFO): GPS fix at 20191210T175021: (36.802750, -121.786913) 2019-12-10T17:50:33.839Z,1576000233.839 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): 0.008692 CHAN A1 (24V): 0.008306 CHAN A2 (12V): 0.003470 CHAN A3 (5V): -0.004496 CHAN B0 (3.3V): -0.004118 CHAN B1 (3.15aV): -0.004337 CHAN B2 (3.15bV): -0.004104 CHAN B3 (GND): -0.006456 OPEN: 0.006910 Full Scale Calc: 4.765 mA, -1.589 mA 2019-12-10T17:50:38.233Z,1576000238.233 [NAL9602](INFO): SBD MO Status=0, MOMSN=36190, MT Status=0, MTMSN=0 2019-12-10T17:50:38.233Z,1576000238.233 [NAL9602](INFO): No messages in MT queue 2019-12-10T17:50:39.440Z,1576000239.440 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175036.00,A,3648.16478,N,12147.21481,W,0.097,246.98,101219,,,A*75 2019-12-10T17:50:39.442Z,1576000239.442 [NAL9602](INFO): GPS fix at 20191210T175036: (36.802746, -121.786913) 2019-12-10T17:50:42.674Z,1576000242.674 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175039.00,A,3648.16479,N,12147.21474,W,0.136,246.98,101219,,,A*7B 2019-12-10T17:50:42.677Z,1576000242.677 [NAL9602](INFO): GPS fix at 20191210T175039: (36.802746, -121.786912) 2019-12-10T17:50:45.904Z,1576000245.904 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175042.00,A,3648.16484,N,12147.21468,W,0.117,246.98,101219,,,A*7B 2019-12-10T17:50:45.906Z,1576000245.906 [NAL9602](INFO): GPS fix at 20191210T175042: (36.802747, -121.786911) 2019-12-10T17:50:48.735Z,1576000248.735 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175045.00,A,3648.16490,N,12147.21461,W,0.039,246.98,101219,,,A*7D 2019-12-10T17:50:48.737Z,1576000248.737 [NAL9602](INFO): GPS fix at 20191210T175045: (36.802748, -121.786910) 2019-12-10T17:50:51.574Z,1576000251.574 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175048.00,A,3648.16502,N,12147.21434,W,0.039,246.98,101219,,,A*7A 2019-12-10T17:50:51.576Z,1576000251.576 [NAL9602](INFO): GPS fix at 20191210T175048: (36.802750, -121.786906) 2019-12-10T17:50:54.797Z,1576000254.797 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175051.00,A,3648.16516,N,12147.21408,W,0.117,246.98,101219,,,A*75 2019-12-10T17:50:54.799Z,1576000254.799 [NAL9602](INFO): GPS fix at 20191210T175051: (36.802753, -121.786901) 2019-12-10T17:50:57.619Z,1576000257.619 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175054.00,A,3648.16523,N,12147.21381,W,0.078,246.98,101219,,,A*78 2019-12-10T17:50:57.625Z,1576000257.625 [NAL9602](INFO): GPS fix at 20191210T175054: (36.802754, -121.786897) 2019-12-10T17:51:00.861Z,1576000260.861 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175057.00,A,3648.16513,N,12147.21384,W,0.078,246.98,101219,,,A*7D 2019-12-10T17:51:00.863Z,1576000260.863 [NAL9602](INFO): GPS fix at 20191210T175057: (36.802752, -121.786897) 2019-12-10T17:51:03.682Z,1576000263.682 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175100.00,A,3648.16507,N,12147.21390,W,0.097,246.98,101219,,,A*7F 2019-12-10T17:51:03.685Z,1576000263.685 [NAL9602](INFO): GPS fix at 20191210T175100: (36.802751, -121.786898) 2019-12-10T17:51:06.923Z,1576000266.923 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175103.00,A,3648.16502,N,12147.21410,W,0.253,246.98,101219,,,A*7C 2019-12-10T17:51:06.927Z,1576000266.927 [NAL9602](INFO): GPS fix at 20191210T175103: (36.802750, -121.786902) 2019-12-10T17:51:09.414Z,1576000269.414 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 5 Latitude: 36.802750 Longitude: -121.786903 2019-12-10T17:51:09.748Z,1576000269.748 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175106.00,A,3648.16514,N,12147.21396,W,0.117,246.98,101219,,,A*74 2019-12-10T17:51:09.750Z,1576000269.750 [NAL9602](INFO): GPS fix at 20191210T175106: (36.802752, -121.786899) 2019-12-10T17:51:09.796Z,1576000269.796 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 0.000000 Voltage: 0.000000 2019-12-10T17:51:09.796Z,1576000269.796 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah 2019-12-10T17:51:09.797Z,1576000269.797 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V 2019-12-10T17:51:10.204Z,1576000270.204 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2019-12-10T17:51:10.205Z,1576000270.205 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2019-12-10T17:51:10.205Z,1576000270.205 [IBIT](IMPORTANT): Pressure:9.746277 PSI 2019-12-10T17:51:10.205Z,1576000270.205 [IBIT](IMPORTANT): Humidity:30.844828 % 2019-12-10T17:51:10.579Z,1576000270.579 [IBIT](IMPORTANT): Vehicle Pitch:3.718762 degrees 2019-12-10T17:51:10.579Z,1576000270.579 [IBIT](IMPORTANT): Vehicle Roll:6.504468 degrees 2019-12-10T17:51:10.579Z,1576000270.579 [IBIT](IMPORTANT): Vehicle Heading:196.919266 degrees 2019-12-10T17:51:11.031Z,1576000271.031 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m 2019-12-10T17:51:11.031Z,1576000271.031 [IBIT](IMPORTANT): buoyancyNeutral: 209.000000 cc 2019-12-10T17:51:11.031Z,1576000271.031 [IBIT](IMPORTANT): massDefault: 1.300000 cm 2019-12-10T17:51:11.031Z,1576000271.031 [IBIT](IMPORTANT): stopDepth: 50.000000 m 2019-12-10T17:51:11.032Z,1576000271.032 [IBIT](IMPORTANT): abortDepth: 60.000000 m 2019-12-10T17:51:11.032Z,1576000271.032 [IBIT](IMPORTANT): IBIT PASSED 2019-12-10T17:51:28.764Z,1576000288.764 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T17:51:28.764Z,1576000288.764 [Default:CheckIn:C.Wait] Stopped 2019-12-10T17:51:28.764Z,1576000288.764 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T17:51:28.764Z,1576000288.764 [Default:CheckIn:D] Running Loop=1 2019-12-10T17:51:29.155Z,1576000289.155 [Default:CheckIn:D] Stopped 2019-12-10T17:51:29.155Z,1576000289.155 [Default:CheckIn:E] Running Loop=1 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.100285 min 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn:E] Stopped 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn] Stopped 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn](INFO): Running loop #5 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn] Running Loop=5 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T17:51:29.571Z,1576000289.571 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T17:51:31.554Z,1576000291.554 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175128.00,A,3648.16538,N,12147.21467,W,0.175,246.98,101219,,,A*7B 2019-12-10T17:51:31.568Z,1576000291.568 [NAL9602](INFO): GPS fix at 20191210T175128: (36.802756, -121.786911) 2019-12-10T17:51:31.591Z,1576000291.591 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T17:51:31.591Z,1576000291.591 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T17:51:41.168Z,1576000301.168 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191210T171904/Courier0022.lzma 2019-12-10T17:51:43.174Z,1576000303.174 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0022.lzma.bak 2019-12-10T17:51:43.175Z,1576000303.175 [DataOverHttps](INFO): SBD MOMSN=12138820 2019-12-10T17:51:52.567Z,1576000312.567 [DVL_micro](ERROR): Failed to parse: :T000000008.1,0000.0,1489.0,000 2019-12-10T17:52:00.001Z,1576000320.001 [DataOverHttps](INFO): Sending 764 bytes from file Logs/20191210T171904/Express0023.lzma 2019-12-10T17:52:02.006Z,1576000322.006 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0023.lzma.bak 2019-12-10T17:52:02.006Z,1576000322.006 [DataOverHttps](INFO): SBD MOMSN=12138823 2019-12-10T17:52:04.284Z,1576000324.284 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T17:52:19.288Z,1576000339.288 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20191210T171904/Express0026.lzma 2019-12-10T17:52:21.294Z,1576000341.294 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0026.lzma.bak 2019-12-10T17:52:21.294Z,1576000341.294 [DataOverHttps](INFO): SBD MOMSN=12138849 2019-12-10T17:52:22.482Z,1576000342.482 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T17:52:22.482Z,1576000342.482 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T17:52:22.482Z,1576000342.482 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T17:53:00.891Z,1576000380.891 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+18.1,0000.0,1489.0,000 2019-12-10T17:53:59.050Z,1576000439.050 [DVL_micro](ERROR): only read 3 of 4 data items 2019-12-10T17:53:59.050Z,1576000439.050 [DVL_micro](ERROR): Failed to parse: :BI,-0090,-01260,+00000,I 2019-12-10T17:54:47.117Z,1576000487.117 [DVL_micro](ERROR): Failed to parse: :000000000,35.0,+18.1,0000.0,1489.0,000 2019-12-10T17:54:59.672Z,1576000499.672 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:54:59.672Z,1576000499.672 [DVL_micro](ERROR): Failed to parse: :TS,000000000000+18.1,0000.0,1489.0,000 2019-12-10T17:55:45.321Z,1576000545.321 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:55:45.321Z,1576000545.321 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+0.0,1489:WI,-01134,+00056,-01256,+00000,A 2019-12-10T17:56:33.390Z,1576000593.390 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:56:33.390Z,1576000593.390 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+18.1,089.0,000 2019-12-10T17:57:23.117Z,1576000643.117 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T17:57:23.117Z,1576000643.117 [Default:CheckIn:C.Wait] Stopped 2019-12-10T17:57:23.117Z,1576000643.117 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T17:57:23.117Z,1576000643.117 [Default:CheckIn:D] Running Loop=1 2019-12-10T17:57:23.512Z,1576000643.512 [Default:CheckIn:D] Stopped 2019-12-10T17:57:23.512Z,1576000643.512 [Default:CheckIn:E] Running Loop=1 2019-12-10T17:57:23.928Z,1576000643.928 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.006232 min 2019-12-10T17:57:23.928Z,1576000643.928 [Default:CheckIn:E] Stopped 2019-12-10T17:57:23.928Z,1576000643.928 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T17:57:23.929Z,1576000643.929 [Default:CheckIn] Stopped 2019-12-10T17:57:23.929Z,1576000643.929 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T17:57:23.929Z,1576000643.929 [Default:CheckIn](INFO): Running loop #6 2019-12-10T17:57:23.929Z,1576000643.929 [Default:CheckIn] Running Loop=6 2019-12-10T17:57:23.929Z,1576000643.929 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T17:57:23.929Z,1576000643.929 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T17:57:25.907Z,1576000645.907 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175721.00,A,3648.16537,N,12147.21405,W,0.039,246.98,101219,,,A*76 2019-12-10T17:57:25.920Z,1576000645.920 [NAL9602](INFO): GPS fix at 20191210T175721: (36.802756, -121.786901) 2019-12-10T17:57:25.943Z,1576000645.943 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T17:57:25.943Z,1576000645.943 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T17:57:33.752Z,1576000653.752 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191210T171904/Courier0028.lzma 2019-12-10T17:57:35.758Z,1576000655.758 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0028.lzma.bak 2019-12-10T17:57:35.759Z,1576000655.759 [DataOverHttps](INFO): SBD MOMSN=12138865 2019-12-10T17:57:52.180Z,1576000672.180 [NAL9602](INFO): SBD MO Status=0, MOMSN=36191, MT Status=0, MTMSN=0 2019-12-10T17:57:52.180Z,1576000672.180 [NAL9602](INFO): No messages in MT queue 2019-12-10T17:57:52.880Z,1576000672.880 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191210T171904/Express0029.lzma 2019-12-10T17:57:54.886Z,1576000674.886 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0029.lzma.bak 2019-12-10T17:57:54.886Z,1576000674.886 [DataOverHttps](INFO): SBD MOMSN=12138868 2019-12-10T17:57:56.237Z,1576000676.237 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T17:57:56.238Z,1576000676.238 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T17:57:56.238Z,1576000676.238 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T17:58:22.869Z,1576000702.869 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T17:59:10.155Z,1576000750.155 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T17:59:10.155Z,1576000750.155 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+18.1,0000.,000 2019-12-10T17:59:58.244Z,1576000798.244 [DVL_micro](ERROR): only read 2 of 4 data items 2019-12-10T17:59:58.244Z,1576000798.244 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,,+9999.99 2019-12-10T18:00:08.333Z,1576000808.333 [DVL_micro](ERROR): Failed to parse: :BI,-00911,01170,+0:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-12-10T18:00:56.407Z,1576000856.407 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T18:00:56.407Z,1576000856.407 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+18.,1489.0,000 2019-12-10T18:01:46.923Z,1576000906.923 [DVL_micro](ERROR): Failed to parse: :SA,+01.68,+06.51,010.2 2019-12-10T18:02:45.151Z,1576000965.151 [DVL_micro](ERROR): only read 3 of 4 data items 2019-12-10T18:02:45.151Z,1576000965.151 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+99999.99 2019-12-10T18:02:56.849Z,1576000976.849 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:02:56.850Z,1576000976.850 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:02:56.850Z,1576000976.850 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:02:56.850Z,1576000976.850 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:02:57.247Z,1576000977.247 [Default:CheckIn:D] Stopped 2019-12-10T18:02:57.247Z,1576000977.247 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:02:57.657Z,1576000977.657 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.568490 min 2019-12-10T18:02:57.657Z,1576000977.657 [Default:CheckIn:E] Stopped 2019-12-10T18:02:57.657Z,1576000977.657 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:02:57.657Z,1576000977.657 [Default:CheckIn] Stopped 2019-12-10T18:02:57.657Z,1576000977.657 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:02:57.658Z,1576000977.658 [Default:CheckIn](INFO): Running loop #7 2019-12-10T18:02:57.658Z,1576000977.658 [Default:CheckIn] Running Loop=7 2019-12-10T18:02:57.658Z,1576000977.658 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:02:57.658Z,1576000977.658 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:02:59.652Z,1576000979.652 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180255.00,A,3648.37290,N,12147.11701,W,4.685,2.83,101219,,,D*7F 2019-12-10T18:02:59.654Z,1576000979.654 [NAL9602](INFO): GPS fix at 20191210T180255: (36.806215, -121.785284) 2019-12-10T18:02:59.678Z,1576000979.678 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:02:59.678Z,1576000979.678 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:03:07.232Z,1576000987.232 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191210T171904/Courier0031.lzma 2019-12-10T18:03:09.238Z,1576000989.238 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0031.lzma.bak 2019-12-10T18:03:09.238Z,1576000989.238 [DataOverHttps](INFO): SBD MOMSN=12138907 2019-12-10T18:03:12.633Z,1576000992.633 [NAL9602](INFO): SBD MO Status=0, MOMSN=36192, MT Status=0, MTMSN=0 2019-12-10T18:03:12.633Z,1576000992.633 [NAL9602](INFO): No messages in MT queue 2019-12-10T18:03:23.089Z,1576001003.089 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-12-10T18:03:23.089Z,1576001003.089 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+18.2,0000.0,1489.0,,-01325,+00212,-01236,+00000,A 2019-12-10T18:03:26.296Z,1576001006.296 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20191210T171904/Express0032.lzma 2019-12-10T18:03:28.302Z,1576001008.302 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0032.lzma.bak 2019-12-10T18:03:28.302Z,1576001008.302 [DataOverHttps](INFO): SBD MOMSN=12138914 2019-12-10T18:03:29.570Z,1576001009.570 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T18:03:29.570Z,1576001009.570 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T18:03:29.570Z,1576001009.570 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T18:03:43.288Z,1576001023.288 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:05:11.763Z,1576001111.763 [DVL_micro](ERROR): Failed to parse: 92,+00319,-0100,A 2019-12-10T18:05:21.875Z,1576001121.875 [DVL_micro](ERROR): Failed to parse: :WI,+00166,+00033,-00958,+00000,A 2019-12-10T18:08:30.195Z,1576001310.195 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:08:30.195Z,1576001310.195 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:08:30.195Z,1576001310.195 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:08:30.195Z,1576001310.195 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:08:30.599Z,1576001310.599 [Default:CheckIn:D] Stopped 2019-12-10T18:08:30.599Z,1576001310.599 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:08:31.021Z,1576001311.021 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 45.124349 min 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn:E] Stopped 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn] Stopped 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn](INFO): Running loop #8 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn] Running Loop=8 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:08:31.022Z,1576001311.022 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:08:32.990Z,1576001312.990 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180827.00,A,3648.28642,N,12148.54518,W,25.542,255.38,101219,,,A*4F 2019-12-10T18:08:32.993Z,1576001312.993 [NAL9602](INFO): GPS fix at 20191210T180827: (36.804774, -121.809086) 2019-12-10T18:08:33.020Z,1576001313.020 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:08:33.020Z,1576001313.020 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:08:40.596Z,1576001320.596 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191210T171904/Courier0034.lzma 2019-12-10T18:08:42.602Z,1576001322.602 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0034.lzma.bak 2019-12-10T18:08:42.602Z,1576001322.602 [DataOverHttps](INFO): SBD MOMSN=12138932 2019-12-10T18:08:50.763Z,1576001330.763 [NAL9602](INFO): SBD MO Status=0, MOMSN=36193, MT Status=0, MTMSN=0 2019-12-10T18:08:50.764Z,1576001330.764 [NAL9602](INFO): No messages in MT queue 2019-12-10T18:09:06.372Z,1576001346.372 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20191210T171904/Express0035.lzma 2019-12-10T18:09:08.378Z,1576001348.378 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0035.lzma.bak 2019-12-10T18:09:08.378Z,1576001348.378 [DataOverHttps](INFO): SBD MOMSN=12138935 2019-12-10T18:09:09.406Z,1576001349.406 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T18:09:09.406Z,1576001349.406 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T18:09:09.407Z,1576001349.407 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T18:09:21.498Z,1576001361.498 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:10:27.370Z,1576001427.370 [DVL_micro](ERROR): Failed to parse: :WI,-00080,-00345,-01029,+00000,A 2019-12-10T18:10:35.117Z,1576001435.117 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-12-10T18:10:35.117Z,1576001435.117 [DVL_micro] Communications Fault, FailCount= 1 2019-12-10T18:10:35.117Z,1576001435.117 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:10:35.117Z,1576001435.117 [DVL_micro](ERROR): Failed to parse: 2019-12-10T18:10:35.157Z,1576001435.157 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:10:35.517Z,1576001435.517 [DVL_micro](INFO): Powering down 2019-12-10T18:10:36.291Z,1576001436.291 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:10:36.292Z,1576001436.292 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:10:54.031Z,1576001454.031 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:10:54.031Z,1576001454.031 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:10:54.031Z,1576001454.031 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:10:54.063Z,1576001454.063 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:10:54.501Z,1576001454.501 [DVL_micro](INFO): Powering down 2019-12-10T18:10:55.263Z,1576001455.263 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:10:55.263Z,1576001455.263 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:11:13.037Z,1576001473.037 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:11:13.038Z,1576001473.038 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:11:13.038Z,1576001473.038 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:11:13.098Z,1576001473.098 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:11:13.098Z,1576001473.098 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:11:13.513Z,1576001473.513 [DVL_micro](INFO): Powering down 2019-12-10T18:11:13.555Z,1576001473.555 [CBIT](INFO): Critical error at 20191210T181113 2019-12-10T18:13:44.369Z,1576001624.369 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:14:10.019Z,1576001650.019 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:14:10.019Z,1576001650.019 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:14:10.019Z,1576001650.019 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:14:10.019Z,1576001650.019 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:14:10.407Z,1576001650.407 [Default:CheckIn:D] Stopped 2019-12-10T18:14:10.408Z,1576001650.408 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:14:10.818Z,1576001650.818 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.787830 min 2019-12-10T18:14:10.818Z,1576001650.818 [Default:CheckIn:E] Stopped 2019-12-10T18:14:10.818Z,1576001650.818 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:14:10.818Z,1576001650.818 [Default:CheckIn] Stopped 2019-12-10T18:14:10.818Z,1576001650.818 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:14:10.818Z,1576001650.818 [Default:CheckIn](INFO): Running loop #9 2019-12-10T18:14:10.819Z,1576001650.819 [Default:CheckIn] Running Loop=9 2019-12-10T18:14:10.819Z,1576001650.819 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:14:10.819Z,1576001650.819 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:14:12.826Z,1576001652.826 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181407.00,A,3647.82044,N,12150.96877,W,16.834,270.42,101219,,,A*4A 2019-12-10T18:14:12.829Z,1576001652.829 [NAL9602](INFO): GPS fix at 20191210T181407: (36.797007, -121.849480) 2019-12-10T18:14:12.854Z,1576001652.854 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:14:12.854Z,1576001652.854 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:14:13.288Z,1576001653.288 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:14:13.288Z,1576001653.288 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:14:15.493Z,1576001655.493 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:14:21.297Z,1576001661.297 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:14:21.297Z,1576001661.297 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:14:21.297Z,1576001661.297 [DVL_micro](ERROR): Data Fault 2019-12-10T18:14:21.329Z,1576001661.329 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:14:21.777Z,1576001661.777 [DVL_micro](INFO): Powering down 2019-12-10T18:14:22.553Z,1576001662.553 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:14:22.553Z,1576001662.553 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:14:40.284Z,1576001680.284 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:14:40.284Z,1576001680.284 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:14:40.284Z,1576001680.284 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:14:40.337Z,1576001680.337 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:14:40.761Z,1576001680.761 [DVL_micro](INFO): Powering down 2019-12-10T18:14:41.535Z,1576001681.535 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:14:41.535Z,1576001681.535 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:14:41.908Z,1576001681.908 [NAL9602](INFO): SBD MO Status=0, MOMSN=36194, MT Status=0, MTMSN=0 2019-12-10T18:14:41.909Z,1576001681.909 [NAL9602](INFO): No messages in MT queue 2019-12-10T18:14:46.617Z,1576001686.617 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:14:59.278Z,1576001699.278 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:14:59.278Z,1576001699.278 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:14:59.278Z,1576001699.278 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:14:59.316Z,1576001699.316 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:14:59.341Z,1576001699.341 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:14:59.749Z,1576001699.749 [DVL_micro](INFO): Powering down 2019-12-10T18:14:59.779Z,1576001699.779 [CBIT](INFO): Critical error at 20191210T181459 2019-12-10T18:15:12.604Z,1576001712.604 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:15:17.749Z,1576001717.749 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:15:48.901Z,1576001748.901 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:15:52.917Z,1576001752.917 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.783691 2019-12-10T18:16:14.474Z,1576001774.474 [NAL9602](INFO): SBD MO Status=1, MOMSN=36195, MT Status=0, MTMSN=0 2019-12-10T18:16:14.521Z,1576001774.521 [NAL9602](INFO): Sent 115 bytes from file Logs/20191210T171904/Courier0037.lzma 2019-12-10T18:16:14.521Z,1576001774.521 [NAL9602](INFO): Packets left to send: 0 2019-12-10T18:16:24.053Z,1576001784.053 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:16:25.852Z,1576001785.852 [NAL9602](INFO): SBD MO Status=1, MOMSN=36196, MT Status=0, MTMSN=0 2019-12-10T18:16:25.905Z,1576001785.905 [NAL9602](INFO): Sent 135 bytes from file Logs/20191210T171904/Express0038.lzma 2019-12-10T18:16:25.905Z,1576001785.905 [NAL9602](INFO): Packets left to send: 0 2019-12-10T18:16:36.350Z,1576001796.350 [NAL9602](INFO): SBD MO Status=0, MOMSN=36197, MT Status=0, MTMSN=0 2019-12-10T18:16:36.438Z,1576001796.438 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T18:16:36.439Z,1576001796.439 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T18:16:36.439Z,1576001796.439 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T18:16:55.197Z,1576001815.197 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:17:07.047Z,1576001827.047 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:17:26.321Z,1576001846.321 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:17:57.445Z,1576001877.445 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:17:59.610Z,1576001879.610 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:17:59.610Z,1576001879.610 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:18:07.652Z,1576001887.652 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:18:07.652Z,1576001887.652 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:18:07.652Z,1576001887.652 [DVL_micro](ERROR): Data Fault 2019-12-10T18:18:07.707Z,1576001887.707 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:18:08.117Z,1576001888.117 [DVL_micro](INFO): Powering down 2019-12-10T18:18:08.899Z,1576001888.899 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:18:08.899Z,1576001888.899 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:18:26.636Z,1576001906.636 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:18:26.636Z,1576001906.636 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:18:26.636Z,1576001906.636 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:18:26.696Z,1576001906.696 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:18:27.113Z,1576001907.113 [DVL_micro](INFO): Powering down 2019-12-10T18:18:27.889Z,1576001907.889 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:18:27.889Z,1576001907.889 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:18:28.569Z,1576001908.569 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:18:45.638Z,1576001925.638 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:18:45.638Z,1576001925.638 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:18:45.638Z,1576001925.638 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:18:45.694Z,1576001925.694 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:18:45.694Z,1576001925.694 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:18:46.113Z,1576001926.113 [DVL_micro](INFO): Powering down 2019-12-10T18:18:46.168Z,1576001926.168 [CBIT](INFO): Critical error at 20191210T181845 2019-12-10T18:18:59.701Z,1576001939.701 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:19:30.825Z,1576001970.825 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:20:01.949Z,1576002001.949 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:20:33.099Z,1576002033.099 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:21:04.223Z,1576002064.223 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:21:35.349Z,1576002095.349 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:21:36.946Z,1576002096.946 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:21:36.946Z,1576002096.946 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:21:36.946Z,1576002096.946 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:21:36.946Z,1576002096.946 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:21:37.353Z,1576002097.353 [Default:CheckIn:D] Stopped 2019-12-10T18:21:37.353Z,1576002097.353 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:21:37.762Z,1576002097.762 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.236922 min 2019-12-10T18:21:37.762Z,1576002097.762 [Default:CheckIn:E] Stopped 2019-12-10T18:21:37.762Z,1576002097.762 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:21:37.762Z,1576002097.762 [Default:CheckIn] Stopped 2019-12-10T18:21:37.763Z,1576002097.763 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:21:37.763Z,1576002097.763 [Default:CheckIn](INFO): Running loop #10 2019-12-10T18:21:37.763Z,1576002097.763 [Default:CheckIn] Running Loop=10 2019-12-10T18:21:37.763Z,1576002097.763 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:21:37.763Z,1576002097.763 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:21:39.750Z,1576002099.750 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182133.00,A,3647.93164,N,12152.43477,W,14.423,233.24,101219,,,A*41 2019-12-10T18:21:39.752Z,1576002099.752 [NAL9602](INFO): GPS fix at 20191210T182133: (36.798861, -121.873913) 2019-12-10T18:21:39.804Z,1576002099.804 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:21:39.804Z,1576002099.804 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:21:45.851Z,1576002105.851 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:21:45.852Z,1576002105.852 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:21:52.340Z,1576002112.340 [NAL9602](INFO): SBD MO Status=1, MOMSN=36198, MT Status=0, MTMSN=0 2019-12-10T18:21:52.393Z,1576002112.393 [NAL9602](INFO): Sent 121 bytes from file Logs/20191210T171904/Courier0040.lzma 2019-12-10T18:21:52.393Z,1576002112.393 [NAL9602](INFO): Packets left to send: 0 2019-12-10T18:21:55.641Z,1576002115.641 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:21:55.642Z,1576002115.642 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:21:55.642Z,1576002115.642 [DVL_micro](ERROR): Data Fault 2019-12-10T18:21:55.696Z,1576002115.696 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:21:56.117Z,1576002116.117 [DVL_micro](INFO): Powering down 2019-12-10T18:21:56.897Z,1576002116.897 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:21:56.897Z,1576002116.897 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:21:58.475Z,1576002118.475 [NAL9602](INFO): SBD MO Status=1, MOMSN=36199, MT Status=0, MTMSN=0 2019-12-10T18:21:58.529Z,1576002118.529 [NAL9602](INFO): Sent 190 bytes from file Logs/20191210T171904/Express0041.lzma 2019-12-10T18:21:58.529Z,1576002118.529 [NAL9602](INFO): Packets left to send: 0 2019-12-10T18:22:06.473Z,1576002126.473 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:22:06.956Z,1576002126.956 [NAL9602](INFO): SBD MO Status=0, MOMSN=36200, MT Status=0, MTMSN=0 2019-12-10T18:22:07.054Z,1576002127.054 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T18:22:07.054Z,1576002127.054 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T18:22:07.054Z,1576002127.054 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T18:22:14.638Z,1576002134.638 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:22:14.638Z,1576002134.638 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:22:14.638Z,1576002134.638 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:22:14.699Z,1576002134.699 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:22:15.105Z,1576002135.105 [DVL_micro](INFO): Powering down 2019-12-10T18:22:15.882Z,1576002135.882 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:22:15.882Z,1576002135.882 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:22:33.619Z,1576002153.619 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:22:33.619Z,1576002153.619 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:22:33.619Z,1576002153.619 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:22:33.675Z,1576002153.675 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:22:33.675Z,1576002153.675 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:22:34.093Z,1576002154.093 [DVL_micro](INFO): Powering down 2019-12-10T18:22:34.142Z,1576002154.142 [CBIT](INFO): Critical error at 20191210T182233 2019-12-10T18:22:37.605Z,1576002157.605 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:22:37.658Z,1576002157.658 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:23:08.665Z,1576002188.665 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting. 2019-12-10T18:23:18.037Z,1576002198.037 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003310 2019-12-10T18:24:40.907Z,1576002280.907 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:25:12.057Z,1576002312.057 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:25:33.859Z,1576002333.859 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:25:33.859Z,1576002333.859 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:25:41.903Z,1576002341.903 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:25:41.903Z,1576002341.903 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:25:41.903Z,1576002341.903 [DVL_micro](ERROR): Data Fault 2019-12-10T18:25:41.935Z,1576002341.935 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:25:42.385Z,1576002342.385 [DVL_micro](INFO): Powering down 2019-12-10T18:25:43.193Z,1576002343.193 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:25:43.193Z,1576002343.193 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:26:00.886Z,1576002360.886 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:26:00.887Z,1576002360.887 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:26:00.887Z,1576002360.887 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:26:00.957Z,1576002360.957 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:26:01.369Z,1576002361.369 [DVL_micro](INFO): Powering down 2019-12-10T18:26:02.145Z,1576002362.145 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:26:02.145Z,1576002362.145 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:26:19.883Z,1576002379.883 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:26:19.884Z,1576002379.884 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:26:19.884Z,1576002379.884 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:26:19.965Z,1576002379.965 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:26:19.965Z,1576002379.965 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:26:20.373Z,1576002380.373 [DVL_micro](INFO): Powering down 2019-12-10T18:26:20.438Z,1576002380.438 [CBIT](INFO): Critical error at 20191210T182619 2019-12-10T18:27:07.582Z,1576002427.582 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:27:07.582Z,1576002427.582 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:27:07.583Z,1576002427.583 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:27:07.583Z,1576002427.583 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:27:07.976Z,1576002427.976 [Default:CheckIn:D] Stopped 2019-12-10T18:27:07.976Z,1576002427.976 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:27:08.378Z,1576002428.378 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.747306 min 2019-12-10T18:27:08.378Z,1576002428.378 [Default:CheckIn:E] Stopped 2019-12-10T18:27:08.379Z,1576002428.379 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:27:08.379Z,1576002428.379 [Default:CheckIn] Stopped 2019-12-10T18:27:08.379Z,1576002428.379 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:27:08.379Z,1576002428.379 [Default:CheckIn](INFO): Running loop #11 2019-12-10T18:27:08.379Z,1576002428.379 [Default:CheckIn] Running Loop=11 2019-12-10T18:27:08.379Z,1576002428.379 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:27:08.379Z,1576002428.379 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:27:10.385Z,1576002430.385 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182703.00,A,3647.70808,N,12152.76887,W,1.672,95.01,101219,,,A*44 2019-12-10T18:27:10.387Z,1576002430.387 [NAL9602](INFO): GPS fix at 20191210T182703: (36.795135, -121.879481) 2019-12-10T18:27:10.419Z,1576002430.419 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:27:10.419Z,1576002430.419 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:27:18.128Z,1576002438.128 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20191210T171904/Courier0043.lzma 2019-12-10T18:27:20.134Z,1576002440.134 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0043.lzma.bak 2019-12-10T18:27:20.134Z,1576002440.134 [DataOverHttps](INFO): SBD MOMSN=12139000 2019-12-10T18:27:24.123Z,1576002444.123 [NAL9602](INFO): SBD MO Status=0, MOMSN=36201, MT Status=0, MTMSN=0 2019-12-10T18:27:24.123Z,1576002444.123 [NAL9602](INFO): No messages in MT queue 2019-12-10T18:27:37.185Z,1576002457.185 [DataOverHttps](INFO): Sending 189 bytes from file Logs/20191210T171904/Express0044.lzma 2019-12-10T18:27:39.190Z,1576002459.190 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0044.lzma.bak 2019-12-10T18:27:39.190Z,1576002459.190 [DataOverHttps](INFO): SBD MOMSN=12139005 2019-12-10T18:27:40.297Z,1576002460.297 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T18:27:40.297Z,1576002460.297 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T18:27:40.297Z,1576002460.297 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T18:27:54.824Z,1576002474.824 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:29:20.145Z,1576002560.145 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:29:20.145Z,1576002560.145 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:29:28.144Z,1576002568.144 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:29:28.145Z,1576002568.145 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:29:28.145Z,1576002568.145 [DVL_micro](ERROR): Data Fault 2019-12-10T18:29:28.198Z,1576002568.198 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:29:28.613Z,1576002568.613 [DVL_micro](INFO): Powering down 2019-12-10T18:29:29.404Z,1576002569.404 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:29:29.404Z,1576002569.404 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:29:47.131Z,1576002587.131 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:29:47.131Z,1576002587.131 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:29:47.131Z,1576002587.131 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:29:47.250Z,1576002587.250 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:29:47.601Z,1576002587.601 [DVL_micro](INFO): Powering down 2019-12-10T18:29:48.396Z,1576002588.396 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:29:48.396Z,1576002588.396 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:30:06.116Z,1576002606.116 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:30:06.117Z,1576002606.117 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:30:06.117Z,1576002606.117 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:30:06.173Z,1576002606.173 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:30:06.173Z,1576002606.173 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:30:06.593Z,1576002606.593 [DVL_micro](INFO): Powering down 2019-12-10T18:30:06.647Z,1576002606.647 [CBIT](INFO): Critical error at 20191210T183006 2019-12-10T18:31:20.885Z,1576002680.885 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2019-12-10T18:32:41.001Z,1576002761.001 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:32:41.001Z,1576002761.001 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:32:41.001Z,1576002761.001 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:32:41.001Z,1576002761.001 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:32:41.312Z,1576002761.312 [Default:CheckIn:D] Stopped 2019-12-10T18:32:41.316Z,1576002761.316 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:32:41.718Z,1576002761.718 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.302905 min 2019-12-10T18:32:41.718Z,1576002761.718 [Default:CheckIn:E] Stopped 2019-12-10T18:32:41.718Z,1576002761.718 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:32:41.719Z,1576002761.719 [Default:CheckIn] Stopped 2019-12-10T18:32:41.719Z,1576002761.719 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:32:41.719Z,1576002761.719 [Default:CheckIn](INFO): Running loop #12 2019-12-10T18:32:41.719Z,1576002761.719 [Default:CheckIn] Running Loop=12 2019-12-10T18:32:41.719Z,1576002761.719 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:32:41.719Z,1576002761.719 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:32:43.679Z,1576002763.679 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183236.00,A,3647.71946,N,12152.74632,W,2.721,240.84,101219,,,A*7D 2019-12-10T18:32:43.681Z,1576002763.681 [NAL9602](INFO): GPS fix at 20191210T183236: (36.795324, -121.879105) 2019-12-10T18:32:43.732Z,1576002763.732 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:32:43.732Z,1576002763.732 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:32:52.632Z,1576002772.632 [DataOverHttps](INFO): Sending 114 bytes from file Logs/20191210T171904/Courier0046.lzma 2019-12-10T18:32:54.638Z,1576002774.638 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0046.lzma.bak 2019-12-10T18:32:54.638Z,1576002774.638 [DataOverHttps](INFO): SBD MOMSN=12139013 2019-12-10T18:33:05.875Z,1576002785.875 [NAL9602](INFO): SBD MO Status=0, MOMSN=36202, MT Status=0, MTMSN=0 2019-12-10T18:33:05.876Z,1576002785.876 [NAL9602](INFO): No messages in MT queue 2019-12-10T18:33:06.324Z,1576002786.324 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:33:06.325Z,1576002786.325 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:33:11.657Z,1576002791.657 [DataOverHttps](INFO): Sending 181 bytes from file Logs/20191210T171904/Express0047.lzma 2019-12-10T18:33:13.662Z,1576002793.662 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0047.lzma.bak 2019-12-10T18:33:13.662Z,1576002793.662 [DataOverHttps](INFO): SBD MOMSN=12139017 2019-12-10T18:33:14.366Z,1576002794.366 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:33:14.366Z,1576002794.366 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:33:14.366Z,1576002794.366 [DVL_micro](ERROR): Data Fault 2019-12-10T18:33:14.399Z,1576002794.399 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:33:14.829Z,1576002794.829 [DVL_micro](INFO): Powering down 2019-12-10T18:33:14.864Z,1576002794.864 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T18:33:14.864Z,1576002794.864 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T18:33:14.864Z,1576002794.864 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T18:33:15.613Z,1576002795.613 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:33:15.613Z,1576002795.613 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:33:33.348Z,1576002813.348 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:33:33.348Z,1576002813.348 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:33:33.348Z,1576002813.348 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:33:33.380Z,1576002813.380 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:33:33.821Z,1576002813.821 [DVL_micro](INFO): Powering down 2019-12-10T18:33:34.668Z,1576002814.668 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:33:34.668Z,1576002814.668 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:33:36.578Z,1576002816.578 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:33:52.334Z,1576002832.334 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:33:52.334Z,1576002832.334 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:33:52.334Z,1576002832.334 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:33:52.366Z,1576002832.366 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:33:52.367Z,1576002832.367 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:33:52.809Z,1576002832.809 [DVL_micro](INFO): Powering down 2019-12-10T18:33:52.839Z,1576002832.839 [CBIT](INFO): Critical error at 20191210T183352 2019-12-10T18:36:52.580Z,1576003012.580 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:36:52.580Z,1576003012.580 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:37:00.600Z,1576003020.600 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:37:00.600Z,1576003020.600 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:37:00.600Z,1576003020.600 [DVL_micro](ERROR): Data Fault 2019-12-10T18:37:00.657Z,1576003020.657 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:37:01.065Z,1576003021.065 [DVL_micro](INFO): Powering down 2019-12-10T18:37:01.847Z,1576003021.847 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:37:01.848Z,1576003021.848 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:37:19.588Z,1576003039.588 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:37:19.588Z,1576003039.588 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:37:19.588Z,1576003039.588 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:37:19.652Z,1576003039.652 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:37:20.065Z,1576003040.065 [DVL_micro](INFO): Powering down 2019-12-10T18:37:20.840Z,1576003040.840 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:37:20.840Z,1576003040.840 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:37:38.579Z,1576003058.579 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:37:38.579Z,1576003058.579 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:37:38.579Z,1576003058.579 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:37:38.613Z,1576003058.613 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:37:38.613Z,1576003058.613 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:37:39.053Z,1576003059.053 [DVL_micro](INFO): Powering down 2019-12-10T18:37:39.114Z,1576003059.114 [CBIT](INFO): Critical error at 20191210T183738 2019-12-10T18:37:52.174Z,1576003072.174 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting. 2019-12-10T18:38:15.362Z,1576003095.362 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:38:15.362Z,1576003095.362 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:38:15.362Z,1576003095.362 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:38:15.362Z,1576003095.362 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:38:15.768Z,1576003095.768 [Default:CheckIn:D] Stopped 2019-12-10T18:38:15.769Z,1576003095.769 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:38:16.180Z,1576003096.180 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 74.877173 min 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn:E] Stopped 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn] Stopped 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn](INFO): Running loop #13 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn] Running Loop=13 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:38:16.181Z,1576003096.181 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:38:18.170Z,1576003098.170 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183810.00,A,3647.75779,N,12152.74079,W,1.555,195.95,101219,,,A*75 2019-12-10T18:38:18.172Z,1576003098.172 [NAL9602](INFO): GPS fix at 20191210T183810: (36.795963, -121.879013) 2019-12-10T18:38:18.224Z,1576003098.224 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:38:18.224Z,1576003098.224 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:38:31.288Z,1576003111.288 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191210T171904/Courier0049.lzma 2019-12-10T18:38:33.294Z,1576003113.294 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Courier0049.lzma.bak 2019-12-10T18:38:33.294Z,1576003113.294 [DataOverHttps](INFO): SBD MOMSN=12139052 2019-12-10T18:38:34.731Z,1576003114.731 [NAL9602](INFO): SBD MO Status=0, MOMSN=36203, MT Status=0, MTMSN=0 2019-12-10T18:38:34.731Z,1576003114.731 [NAL9602](INFO): No messages in MT queue 2019-12-10T18:38:50.424Z,1576003130.424 [DataOverHttps](INFO): Sending 184 bytes from file Logs/20191210T171904/Express0050.lzma 2019-12-10T18:39:02.470Z,1576003142.470 [DataOverHttps](INFO): Moved sent file to Logs/20191210T171904/Express0050.lzma.bak 2019-12-10T18:39:02.471Z,1576003142.471 [DataOverHttps](INFO): SBD MOMSN=12139059 2019-12-10T18:39:03.500Z,1576003143.500 [Default:CheckIn:Read_Iridium] Stopped 2019-12-10T18:39:03.500Z,1576003143.500 [Default:CheckIn:C.Wait] Running Loop=1 2019-12-10T18:39:03.500Z,1576003143.500 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-12-10T18:39:05.447Z,1576003145.447 [NAL9602](INFO): Not Powering down - fast GPS 2019-12-10T18:40:04.377Z,1576003204.377 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:40:35.509Z,1576003235.509 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:40:38.799Z,1576003238.799 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:40:38.799Z,1576003238.799 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:40:46.840Z,1576003246.840 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:40:46.840Z,1576003246.840 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:40:46.840Z,1576003246.840 [DVL_micro](ERROR): Data Fault 2019-12-10T18:40:46.916Z,1576003246.916 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:40:47.329Z,1576003247.329 [DVL_micro](INFO): Powering down 2019-12-10T18:40:48.086Z,1576003248.086 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:40:48.086Z,1576003248.086 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:41:05.830Z,1576003265.830 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:41:05.830Z,1576003265.830 [DVL_micro] Communications Fault, FailCount= 2 2019-12-10T18:41:05.830Z,1576003265.830 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:41:05.889Z,1576003265.889 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:41:06.305Z,1576003266.305 [DVL_micro](INFO): Powering down 2019-12-10T18:41:06.633Z,1576003266.633 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:41:07.070Z,1576003267.070 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:41:07.070Z,1576003267.070 [DVL_micro] No Fault, FailCount= 2 2019-12-10T18:41:17.169Z,1576003277.169 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2019-12-10T18:41:24.822Z,1576003284.822 [DVL_micro](ERROR): No DVL communication! Re-initializing 2019-12-10T18:41:24.822Z,1576003284.822 [DVL_micro] Communications Fault, FailCount= 3 2019-12-10T18:41:24.822Z,1576003284.822 [DVL_micro](ERROR): Communications Fault 2019-12-10T18:41:24.879Z,1576003284.879 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-12-10T18:41:24.879Z,1576003284.879 [CBIT](CRITICAL): Communications Fault in component: DVL_micro 2019-12-10T18:41:25.293Z,1576003285.293 [DVL_micro](INFO): Powering down 2019-12-10T18:41:25.341Z,1576003285.341 [CBIT](INFO): Critical error at 20191210T184124 2019-12-10T18:41:37.761Z,1576003297.761 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:42:08.885Z,1576003328.885 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:42:12.907Z,1576003332.907 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.777847 2019-12-10T18:43:10.141Z,1576003390.141 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:43:41.285Z,1576003421.285 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:44:04.020Z,1576003444.020 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-12-10T18:44:04.020Z,1576003444.020 [Default:CheckIn:C.Wait] Stopped 2019-12-10T18:44:04.020Z,1576003444.020 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-12-10T18:44:04.020Z,1576003444.020 [Default:CheckIn:D] Running Loop=1 2019-12-10T18:44:04.420Z,1576003444.420 [Default:CheckIn:D] Stopped 2019-12-10T18:44:04.420Z,1576003444.420 [Default:CheckIn:E] Running Loop=1 2019-12-10T18:44:04.836Z,1576003444.836 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.688029 min 2019-12-10T18:44:04.836Z,1576003444.836 [Default:CheckIn:E] Stopped 2019-12-10T18:44:04.836Z,1576003444.836 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-12-10T18:44:04.836Z,1576003444.836 [Default:CheckIn] Stopped 2019-12-10T18:44:04.836Z,1576003444.836 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-12-10T18:44:04.837Z,1576003444.837 [Default:CheckIn](INFO): Running loop #14 2019-12-10T18:44:04.837Z,1576003444.837 [Default:CheckIn] Running Loop=14 2019-12-10T18:44:04.837Z,1576003444.837 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-12-10T18:44:04.837Z,1576003444.837 [Default:CheckIn:Read_GPS] Running Loop=1 2019-12-10T18:44:06.822Z,1576003446.822 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184358.00,A,3647.77560,N,12152.76866,W,1.225,355.62,101219,,,D*7A 2019-12-10T18:44:06.824Z,1576003446.824 [NAL9602](INFO): GPS fix at 20191210T184358: (36.796260, -121.879478) 2019-12-10T18:44:06.869Z,1576003446.869 [Default:CheckIn:Read_GPS] Stopped 2019-12-10T18:44:06.869Z,1576003446.869 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-12-10T18:44:12.417Z,1576003452.417 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-12-10T18:44:24.659Z,1576003464.659 [NAL9602](INFO): SBD MO Status=2, MOMSN=36204, MT Status=2, MTMSN=0 2019-12-10T18:44:24.659Z,1576003464.659 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-12-10T18:44:25.155Z,1576003465.155 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:44:25.155Z,1576003465.155 [DVL_micro] No Fault, FailCount= 3 2019-12-10T18:44:33.192Z,1576003473.192 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-12-10T18:44:33.192Z,1576003473.192 [DVL_micro] Data Fault, FailCount= 1 2019-12-10T18:44:33.193Z,1576003473.193 [DVL_micro](ERROR): Data Fault 2019-12-10T18:44:33.252Z,1576003473.252 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-12-10T18:44:33.673Z,1576003473.673 [DVL_micro](INFO): Powering down 2019-12-10T18:44:34.451Z,1576003474.451 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-12-10T18:44:34.452Z,1576003474.452 [DVL_micro] No Fault, FailCount= 1 2019-12-10T18:44:35.223Z,1576003475.223 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=36204, MT Status=1, MTMSN=2596 2019-12-10T18:44:35.273Z,1576003475.273 [NAL9602](INFO): Sent 115 bytes from file Logs/20191210T171904/Courier0052.lzma 2019-12-10T18:44:35.273Z,1576003475.273 [NAL9602](INFO): Packets left to send: 0 2019-12-10T18:44:35.729Z,1576003475.729 [NAL9602](INFO): Received command:restart logs