2019-09-23T22:10:50.050Z,1569276650.050 [Supervisor](DEBUG): Initializing supervisor.
2019-09-23T22:10:50.053Z,1569276650.053 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-09-23T22:10:50.054Z,1569276650.054 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-09-23T22:10:50.054Z,1569276650.054 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-09-23T22:10:50.055Z,1569276650.055 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-09-23T22:10:50.055Z,1569276650.055 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-09-23T22:10:50.058Z,1569276650.058 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-09-23T22:10:50.069Z,1569276650.069 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-09-23T22:10:50.070Z,1569276650.070 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-09-23T22:10:50.070Z,1569276650.070 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-09-23T22:10:50.071Z,1569276650.071 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-09-23T22:10:50.072Z,1569276650.072 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-09-23T22:10:50.072Z,1569276650.072 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-09-23T22:10:50.074Z,1569276650.074 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-09-23T22:10:50.074Z,1569276650.074 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-09-23T22:10:50.079Z,1569276650.079 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-09-23T22:10:50.173Z,1569276650.173 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-09-23T22:10:50.175Z,1569276650.175 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-09-23T22:10:50.721Z,1569276650.721 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-09-23T22:10:50.723Z,1569276650.723 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-09-23T22:10:50.820Z,1569276650.820 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-09-23T22:10:50.821Z,1569276650.821 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-09-23T22:10:50.921Z,1569276650.921 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-09-23T22:10:50.923Z,1569276650.923 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-09-23T22:10:51.003Z,1569276651.003 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-09-23T22:10:51.140Z,1569276651.140 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-09-23T22:10:51.142Z,1569276651.142 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-09-23T22:10:51.430Z,1569276651.430 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-09-23T22:10:51.432Z,1569276651.432 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-09-23T22:10:51.879Z,1569276651.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-09-23T22:10:51.881Z,1569276651.881 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-09-23T22:10:52.024Z,1569276652.024 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-09-23T22:10:52.025Z,1569276652.025 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-09-23T22:10:52.220Z,1569276652.220 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-09-23T22:10:52.221Z,1569276652.221 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-09-23T22:10:52.663Z,1569276652.663 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-09-23T22:10:52.663Z,1569276652.663 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-09-23T22:10:52.872Z,1569276652.872 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-09-23T22:10:52.874Z,1569276652.874 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-09-23T22:10:53.073Z,1569276653.073 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-09-23T22:10:53.074Z,1569276653.074 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-09-23T22:10:53.458Z,1569276653.458 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-09-23T22:10:53.664Z,1569276653.664 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-09-23T22:10:54.320Z,1569276654.320 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-09-23T22:10:54.322Z,1569276654.322 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2019-09-23T22:10:54.365Z,1569276654.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2019-09-23T22:10:54.448Z,1569276654.448 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2019-09-23T22:10:54.602Z,1569276654.602 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2019-09-23T22:10:54.710Z,1569276654.710 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2019-09-23T22:10:54.795Z,1569276654.795 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2019-09-23T22:10:54.890Z,1569276654.890 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2019-09-23T22:10:55.080Z,1569276655.080 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2019-09-23T22:10:55.305Z,1569276655.305 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-09-23T22:10:55.306Z,1569276655.306 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2019-09-23T22:10:55.399Z,1569276655.399 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2019-09-23T22:10:55.496Z,1569276655.496 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2019-09-23T22:10:55.630Z,1569276655.630 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2019-09-23T22:10:55.729Z,1569276655.729 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-09-23T22:10:55.744Z,1569276655.744 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-09-23T22:10:55.831Z,1569276655.831 [VerticalControl](DEBUG): Construct VerticalControl.
2019-09-23T22:10:55.940Z,1569276655.940 [VerticalControl] Loaded
2019-09-23T22:10:55.941Z,1569276655.941 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-09-23T22:10:55.941Z,1569276655.941 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-09-23T22:10:56.009Z,1569276656.009 [HorizontalControl] Loaded
2019-09-23T22:10:56.009Z,1569276656.009 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-09-23T22:10:56.010Z,1569276656.010 [SpeedControl](DEBUG): Construct SpeedControl.
2019-09-23T22:10:56.015Z,1569276656.015 [SpeedControl] Loaded
2019-09-23T22:10:56.015Z,1569276656.015 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-09-23T22:10:56.016Z,1569276656.016 [LoopControl](DEBUG): Construct LoopControl.
2019-09-23T22:10:56.017Z,1569276656.017 [LoopControl] Loaded
2019-09-23T22:10:56.017Z,1569276656.017 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-09-23T22:10:56.017Z,1569276656.017 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-09-23T22:10:56.018Z,1569276656.018 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-09-23T22:10:56.074Z,1569276656.074 [DepthRateCalculator] Loaded
2019-09-23T22:10:56.074Z,1569276656.074 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-09-23T22:10:56.079Z,1569276656.079 [PitchRateCalculator] Loaded
2019-09-23T22:10:56.080Z,1569276656.080 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-09-23T22:10:56.095Z,1569276656.095 [SpeedCalculator] Loaded
2019-09-23T22:10:56.095Z,1569276656.095 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-09-23T22:10:56.116Z,1569276656.116 [TempGradientCalculator] Loaded
2019-09-23T22:10:56.116Z,1569276656.116 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-09-23T22:10:56.121Z,1569276656.121 [YawRateCalculator] Loaded
2019-09-23T22:10:56.121Z,1569276656.121 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-09-23T22:10:56.149Z,1569276656.149 [ElevatorOffsetCalculator] Loaded
2019-09-23T22:10:56.150Z,1569276656.150 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-09-23T22:10:56.150Z,1569276656.150 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-09-23T22:10:56.151Z,1569276656.151 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-09-23T22:10:56.199Z,1569276656.199 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-09-23T22:10:56.199Z,1569276656.199 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-09-23T22:10:56.310Z,1569276656.310 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-09-23T22:10:56.311Z,1569276656.311 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-09-23T22:10:56.643Z,1569276656.643 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-09-23T22:10:56.643Z,1569276656.643 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-09-23T22:10:56.766Z,1569276656.766 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-09-23T22:10:56.767Z,1569276656.767 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-09-23T22:10:57.243Z,1569276657.243 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-09-23T22:10:57.248Z,1569276657.248 [AHRS_M2](INFO): created writer for : platform_orientation
2019-09-23T22:10:57.249Z,1569276657.249 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-09-23T22:10:57.255Z,1569276657.255 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-09-23T22:10:57.255Z,1569276657.255 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-09-23T22:10:57.260Z,1569276657.260 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-09-23T22:10:57.261Z,1569276657.261 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-09-23T22:10:57.266Z,1569276657.266 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-09-23T22:10:57.443Z,1569276657.443 [AHRS_M2] Loaded
2019-09-23T22:10:57.443Z,1569276657.443 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-09-23T22:10:57.585Z,1569276657.585 [DataOverHttps] Loaded
2019-09-23T22:10:57.586Z,1569276657.586 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-09-23T22:10:57.587Z,1569276657.587 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408B94E0
2019-09-23T22:10:57.587Z,1569276657.587 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 888
2019-09-23T22:10:57.600Z,1569276657.600 [Depth_Keller] Loaded
2019-09-23T22:10:57.600Z,1569276657.600 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-09-23T22:10:57.605Z,1569276657.605 [DropWeight] Loaded
2019-09-23T22:10:57.605Z,1569276657.605 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-09-23T22:10:57.700Z,1569276657.700 [NAL9602] Loaded
2019-09-23T22:10:57.700Z,1569276657.700 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-09-23T22:10:57.716Z,1569276657.716 [Onboard] Loaded
2019-09-23T22:10:57.716Z,1569276657.716 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-09-23T22:10:57.719Z,1569276657.719 [Radio_Surface] Loaded
2019-09-23T22:10:57.720Z,1569276657.720 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-09-23T22:10:57.721Z,1569276657.721 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408E94E0
2019-09-23T22:10:57.721Z,1569276657.721 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 889
2019-09-23T22:10:57.765Z,1569276657.765 [RDI_Pathfinder] Loaded
2019-09-23T22:10:57.765Z,1569276657.765 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-09-23T22:10:57.888Z,1569276657.888 [DAT] Loaded
2019-09-23T22:10:57.888Z,1569276657.888 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-09-23T22:10:59.847Z,1569276659.847 [BPC1] Loaded
2019-09-23T22:10:59.847Z,1569276659.847 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-09-23T22:10:59.848Z,1569276659.848 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-09-23T22:10:59.848Z,1569276659.848 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-09-23T22:10:59.965Z,1569276659.965 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-09-23T22:10:59.966Z,1569276659.966 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-09-23T22:10:59.986Z,1569276659.986 [NavChart] Loaded
2019-09-23T22:10:59.986Z,1569276659.986 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-09-23T22:10:59.990Z,1569276659.990 [UniversalFixResidualReporter] Loaded
2019-09-23T22:10:59.990Z,1569276659.990 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-09-23T22:10:59.991Z,1569276659.991 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-09-23T22:10:59.993Z,1569276659.993 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-09-23T22:11:00.154Z,1569276660.154 [SBIT](DEBUG): Construct Startup Built In Test.
2019-09-23T22:11:00.165Z,1569276660.165 [SBIT] Loaded
2019-09-23T22:11:00.165Z,1569276660.165 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-09-23T22:11:00.166Z,1569276660.166 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-09-23T22:11:00.177Z,1569276660.177 [IBIT] Loaded
2019-09-23T22:11:00.178Z,1569276660.178 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-09-23T22:11:00.181Z,1569276660.181 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-09-23T22:11:00.316Z,1569276660.316 [CBIT] Loaded
2019-09-23T22:11:00.316Z,1569276660.316 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-09-23T22:11:00.317Z,1569276660.317 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-09-23T22:11:00.318Z,1569276660.318 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-09-23T22:11:00.443Z,1569276660.443 [BuoyancyServo] Loaded
2019-09-23T22:11:00.443Z,1569276660.443 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-09-23T22:11:00.454Z,1569276660.454 [ElevatorServo] Loaded
2019-09-23T22:11:00.455Z,1569276660.455 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-09-23T22:11:00.466Z,1569276660.466 [MassServo] Loaded
2019-09-23T22:11:00.466Z,1569276660.466 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-09-23T22:11:00.477Z,1569276660.477 [RudderServo] Loaded
2019-09-23T22:11:00.477Z,1569276660.477 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-09-23T22:11:00.487Z,1569276660.487 [ThrusterServo] Loaded
2019-09-23T22:11:00.488Z,1569276660.488 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-09-23T22:11:00.488Z,1569276660.488 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-09-23T22:11:00.489Z,1569276660.489 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-09-23T22:11:00.512Z,1569276660.512 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-09-23T22:11:00.513Z,1569276660.513 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-09-23T22:11:00.758Z,1569276660.758 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-09-23T22:11:00.763Z,1569276660.763 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-09-23T22:11:00.763Z,1569276660.763 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-09-23T22:11:00.768Z,1569276660.768 [CTD_Seabird](INFO): created writer for : depth
2019-09-23T22:11:00.769Z,1569276660.769 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-09-23T22:11:00.774Z,1569276660.774 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-09-23T22:11:00.774Z,1569276660.774 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-09-23T22:11:00.779Z,1569276660.779 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-09-23T22:11:00.780Z,1569276660.780 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-09-23T22:11:00.785Z,1569276660.785 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-09-23T22:11:00.786Z,1569276660.786 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-09-23T22:11:00.791Z,1569276660.791 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-09-23T22:11:00.791Z,1569276660.791 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-09-23T22:11:00.796Z,1569276660.796 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-09-23T22:11:00.823Z,1569276660.823 [CTD_Seabird] Loaded
2019-09-23T22:11:00.823Z,1569276660.823 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-09-23T22:11:00.824Z,1569276660.824 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A6E4E0
2019-09-23T22:11:00.825Z,1569276660.825 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 891
2019-09-23T22:11:00.873Z,1569276660.873 [WetLabsBB2FL] Loaded
2019-09-23T22:11:00.873Z,1569276660.873 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-09-23T22:11:00.874Z,1569276660.874 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A9E4E0
2019-09-23T22:11:00.874Z,1569276660.874 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 892
2019-09-23T22:11:01.109Z,1569276661.109 [WetLabsUBAT..SerialDriver](INFO): Created logger
2019-09-23T22:11:01.110Z,1569276661.110 [WetLabsUBAT..SerialDriver](INFO): publishing on LCM channel WetLabsUBAT
2019-09-23T22:11:01.110Z,1569276661.110 [WetLabsUBAT..StreamSerialDriver](INFO): Created logger
2019-09-23T22:11:01.116Z,1569276661.116 [WetLabsUBAT](INFO): readConfig(): serialNo_: UBAT0051, uartName_: /dev/ttyC1, optionalArgs_: -ldir /mnt/mmc/LRAUV/Logs/latest
2019-09-23T22:11:01.116Z,1569276661.116 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsUBAT.biolum_potential
2019-09-23T22:11:01.116Z,1569276661.116 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(): dataName: biolum_potential
2019-09-23T22:11:01.120Z,1569276661.120 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsUBAT.flow_rate
2019-09-23T22:11:01.121Z,1569276661.121 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(): dataName: flow_rate
2019-09-23T22:11:01.125Z,1569276661.125 [WetLabsUBAT] Loaded
2019-09-23T22:11:01.125Z,1569276661.125 [ComponentRegistry](DEBUG): Component "WetLabsUBAT" handled in its own thread.
2019-09-23T22:11:01.126Z,1569276661.126 [WetLabsUBAT ThreadHandler](DEBUG): Created PCaller Thread at 40ACE4E0
2019-09-23T22:11:01.126Z,1569276661.126 [WetLabsUBAT ThreadHandler](INFO): Protected caller Thread ID is 893
2019-09-23T22:11:01.127Z,1569276661.127 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-09-23T22:11:01.130Z,1569276661.130 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-09-23T22:11:01.131Z,1569276661.131 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-09-23T22:11:01.138Z,1569276661.138 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-09-23T22:11:01.139Z,1569276661.139 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AFE4E0
2019-09-23T22:11:01.139Z,1569276661.139 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 894
2019-09-23T22:11:01.144Z,1569276661.144 [Supervisor](INFO): Main Thread ID is 802
2019-09-23T22:11:01.144Z,1569276661.144 [Supervisor](DEBUG): Running supervisor.
2019-09-23T22:11:01.144Z,1569276661.144 [CommandLine ThreadHandler](INFO): Handler Thread ID is 895
2019-09-23T22:11:01.147Z,1569276661.147 [controlThread ThreadHandler](INFO): Handler Thread ID is 896
2019-09-23T22:11:01.148Z,1569276661.148 [controlThread](DEBUG): Initializing ControlThread
2019-09-23T22:11:01.148Z,1569276661.148 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-09-23T22:11:01.150Z,1569276661.150 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-09-23T22:11:01.151Z,1569276661.151 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-09-23T22:11:01.151Z,1569276661.151 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-09-23T22:11:01.151Z,1569276661.151 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-09-23T22:11:01.152Z,1569276661.152 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-09-23T22:11:01.152Z,1569276661.152 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-09-23T22:11:01.152Z,1569276661.152 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-09-23T22:11:01.153Z,1569276661.153 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-09-23T22:11:01.153Z,1569276661.153 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-09-23T22:11:01.160Z,1569276661.160 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-09-23T22:11:01.160Z,1569276661.160 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-09-23T22:11:01.161Z,1569276661.161 [SBIT](INFO): Initialize SBIT Component.
2019-09-23T22:11:01.161Z,1569276661.161 [SBIT](IMPORTANT): git: 2019-09-23_TRN
2019-09-23T22:11:01.161Z,1569276661.161 [SBIT](INFO): git hash: b27c1371b29a4d283a78612ae64620b720d8eb64
2019-09-23T22:11:01.162Z,1569276661.162 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-09-23T22:11:01.162Z,1569276661.162 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-09-23T22:11:01.163Z,1569276661.163 [SBIT](INFO): Beginning SBIT in 59.000000 seconds.
2019-09-23T22:11:01.163Z,1569276661.163 [IBIT](INFO): Initialize IBIT Component.
2019-09-23T22:11:01.164Z,1569276661.164 [CBIT](DEBUG): Initialize CBIT Component.
2019-09-23T22:11:01.165Z,1569276661.165 [logger ThreadHandler](INFO): Handler Thread ID is 897
2019-09-23T22:11:01.177Z,1569276661.177 [CBIT](DEBUG): Initialized mux pins.
2019-09-23T22:11:01.177Z,1569276661.177 [CBIT](DEBUG): Initializing the watchdog timer.
2019-09-23T22:11:01.185Z,1569276661.185 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 898
2019-09-23T22:11:01.186Z,1569276661.186 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-09-23T22:11:01.197Z,1569276661.197 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 899
2019-09-23T22:11:01.201Z,1569276661.201 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-09-23T22:11:01.201Z,1569276661.201 [CBIT](DEBUG): Initializing heartbeat.
2019-09-23T22:11:01.209Z,1569276661.209 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 900
2019-09-23T22:11:01.210Z,1569276661.210 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-09-23T22:11:01.213Z,1569276661.213 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-09-23T22:11:01.215Z,1569276661.215 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 902
2019-09-23T22:11:01.216Z,1569276661.216 [WetLabsBB2FL](INFO): Powering down
2019-09-23T22:11:01.245Z,1569276661.245 [WetLabsUBAT ThreadHandler](INFO): Handler Thread ID is 903
2019-09-23T22:11:01.257Z,1569276661.257 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 904
2019-09-23T22:11:01.267Z,1569276661.267 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-09-23T22:11:01.267Z,1569276661.267 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-09-23T22:11:01.267Z,1569276661.267 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-09-23T22:11:01.267Z,1569276661.267 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-09-23T22:11:01.268Z,1569276661.268 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-09-23T22:11:01.268Z,1569276661.268 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-09-23T22:11:01.268Z,1569276661.268 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-09-23T22:11:01.268Z,1569276661.268 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-09-23T22:11:01.268Z,1569276661.268 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-09-23T22:11:01.268Z,1569276661.268 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-09-23T22:11:01.269Z,1569276661.269 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-09-23T22:11:01.269Z,1569276661.269 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-09-23T22:11:01.269Z,1569276661.269 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-09-23T22:11:01.269Z,1569276661.269 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-09-23T22:11:01.269Z,1569276661.269 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-09-23T22:11:01.270Z,1569276661.270 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-09-23T22:11:01.273Z,1569276661.273 [CBIT](DEBUG): Deactivating GF circuits.
2019-09-23T22:11:01.273Z,1569276661.273 [CBIT](DEBUG): Deactivating emergency mode.
2019-09-23T22:11:01.309Z,1569276661.309 [CBIT](DEBUG): Backplane powered.
2019-09-23T22:11:01.311Z,1569276661.311 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-09-23T22:11:01.334Z,1569276661.334 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-09-23T22:11:01.344Z,1569276661.344 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2019-09-23T22:11:01.357Z,1569276661.357 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-09-23T22:11:01.429Z,1569276661.429 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-09-23T22:11:01.430Z,1569276661.430 [Default:A.Wait](DEBUG): Construct Wait.
2019-09-23T22:11:01.432Z,1569276661.432 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-09-23T22:11:01.475Z,1569276661.475 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-09-23T22:11:01.493Z,1569276661.493 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-09-23T22:11:01.499Z,1569276661.499 [Default:E.Execute](DEBUG): Construct Execute.
2019-09-23T22:11:01.510Z,1569276661.510 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2019-09-23T22:11:01.516Z,1569276661.516 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,RDI_Pathfinder,DAT,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-09-23T22:11:01.532Z,1569276661.532 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-09-23T22:11:01.601Z,1569276661.601 [Radio_Surface](INFO): Powering up
2019-09-23T22:11:01.644Z,1569276661.644 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar
2019-09-23T22:11:01.676Z,1569276661.676 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-09-23T22:11:01.676Z,1569276661.676 [DAT](INFO): Powering up
2019-09-23T22:11:01.676Z,1569276661.676 [DAT](DEBUG): Initializing DAT.
2019-09-23T22:11:01.737Z,1569276661.737 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-09-23T22:11:01.753Z,1569276661.753 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-09-23T22:11:01.828Z,1569276661.828 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-09-23T22:11:01.833Z,1569276661.833 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-09-23T22:11:01.834Z,1569276661.834 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-09-23T22:11:01.841Z,1569276661.841 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-09-23T22:11:01.843Z,1569276661.843 [MassServo](DEBUG): Initializing EZServoServo.
2019-09-23T22:11:01.853Z,1569276661.853 [MassServo](DEBUG): Initializing MassServo.
2019-09-23T22:11:01.854Z,1569276661.854 [RudderServo](DEBUG): Initializing EZServoServo.
2019-09-23T22:11:01.865Z,1569276661.865 [RudderServo](DEBUG): Initializing RudderServo.
2019-09-23T22:11:01.866Z,1569276661.866 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-09-23T22:11:01.877Z,1569276661.877 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-09-23T22:11:01.985Z,1569276661.985 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-09-23T22:11:15.283Z,1569276675.283 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-09-23T22:11:16.085Z,1569276676.085 [DAT](INFO): setting local address to 4
2019-09-23T22:11:16.514Z,1569276676.514 [DAT](INFO): set local address to 4
2019-09-23T22:11:27.790Z,1569276687.790 [NAL9602](INFO): Powering up NAL9602
2019-09-23T22:11:38.690Z,1569276698.690 [NAL9602](INFO): NAL9602 initialized
2019-09-23T22:11:39.517Z,1569276699.517 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:12:00.104Z,1569276720.104 [NAL9602](INFO): SBD MO Status=2, MOMSN=1436, MT Status=2, MTMSN=0
2019-09-23T22:12:00.104Z,1569276720.104 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T22:12:00.953Z,1569276720.953 [SBIT](IMPORTANT): Beginning Startup BIT
2019-09-23T22:12:00.961Z,1569276720.961 [CBIT](IMPORTANT): Beginning ground fault scan
2019-09-23T22:12:11.983Z,1569276731.983 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.018938
CHAN A1 (24V): 0.001357
CHAN A2 (12V): -0.007965
CHAN A3 (5V): -0.002855
CHAN B0 (3.3V): -0.000534
CHAN B1 (3.15aV): -0.000882
CHAN B2 (3.15bV): -0.000472
CHAN B3 (GND): 0.001721
OPEN: -0.003519
Full Scale Calc: 4.765 mA, -1.589 mA
2019-09-23T22:12:26.218Z,1569276746.218 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-09-23T22:12:26.218Z,1569276746.218 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-3276,-32768,V
2019-09-23T22:12:42.755Z,1569276762.755 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T22:12:42.755Z,1569276762.755 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-09-23T22:12:54.597Z,1569276774.597 [SBIT](IMPORTANT): SBIT PASSED
2019-09-23T22:12:54.641Z,1569276774.641 [CommandLine](IMPORTANT): got command configSet list
2019-09-23T22:12:54.642Z,1569276774.642 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-09-23T22:12:54.642Z,1569276774.642 [CommandLine](IMPORTANT): CBIT.gf24Offset=143 microampere;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): Express none RDI_Pathfinder.height_above_sea_floor;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): Express linearApproximation Tracking.range_to_contact 10.000000 meter;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): Express linearApproximation WetLabsUBAT.biolum_potential 10000000.000000 none;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 1.000000 liter_per_second;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): Express none height_above_sea_floor;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): Normal linearApproximation WetLabsUBAT.biolum_potential 1000000.000000 none;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=80 cubic_centimeter;

2019-09-23T22:12:54.643Z,1569276774.643 [CommandLine](IMPORTANT): VerticalControl.massDefault=10 millimeter;

2019-09-23T22:12:54.974Z,1569276774.974 [MissionManager](IMPORTANT): Started mission Startup
2019-09-23T22:12:54.974Z,1569276774.974 [Startup] Running Loop=1
2019-09-23T22:12:54.974Z,1569276774.974 [Startup](DEBUG): Aggregate::initialize Startup
2019-09-23T22:12:54.974Z,1569276774.974 [Startup:A.GoToSurface] Running Loop=1
2019-09-23T22:12:54.974Z,1569276774.974 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-09-23T22:12:54.975Z,1569276774.975 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-09-23T22:12:54.975Z,1569276774.975 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-09-23T22:12:54.976Z,1569276774.976 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-09-23T22:12:54.976Z,1569276774.976 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-09-23T22:12:54.977Z,1569276774.977 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-09-23T22:12:54.998Z,1569276774.998 [Startup:StartupSatComms] Running Loop=1
2019-09-23T22:12:54.998Z,1569276774.998 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-09-23T22:12:54.998Z,1569276774.998 [Startup:StartupSatComms:A] Running Loop=1
2019-09-23T22:12:55.387Z,1569276775.387 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-09-23T22:13:55.174Z,1569276835.174 [Startup:StartupSatComms:A](INFO): Timed out from 2019-09-23T22:12:54.0Z
2019-09-23T22:13:55.174Z,1569276835.174 [Startup:StartupSatComms:A] Stopped
2019-09-23T22:13:55.175Z,1569276835.175 [Startup:StartupSatComms:B] Running Loop=1
2019-09-23T22:13:55.578Z,1569276835.578 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-09-23T22:14:01.228Z,1569276841.228 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-09-23T22:14:01.228Z,1569276841.228 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-09-23T22:14:01.267Z,1569276841.267 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-09-23T22:14:01.647Z,1569276841.647 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-09-23T22:14:01.647Z,1569276841.647 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-09-23T22:14:03.363Z,1569276843.363 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005009
2019-09-23T22:14:10.868Z,1569276850.868 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190923T220245/Courier0007.lzma
2019-09-23T22:14:12.874Z,1569276852.874 [DataOverHttps](INFO): Moved sent file to Logs/20190923T220245/Courier0007.lzma.bak
2019-09-23T22:14:12.875Z,1569276852.875 [DataOverHttps](INFO): SBD MOMSN=11806173
2019-09-23T22:14:30.022Z,1569276870.022 [DataOverHttps](INFO): Sending 405 bytes from file Logs/20190923T220245/Express0005.lzma
2019-09-23T22:14:32.026Z,1569276872.026 [DataOverHttps](INFO): Moved sent file to Logs/20190923T220245/Express0005.lzma.bak
2019-09-23T22:14:32.026Z,1569276872.026 [DataOverHttps](INFO): SBD MOMSN=11806175
2019-09-23T22:14:49.040Z,1569276889.040 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190923T220245/Express0008.lzma
2019-09-23T22:14:51.046Z,1569276891.046 [DataOverHttps](INFO): Moved sent file to Logs/20190923T220245/Express0008.lzma.bak
2019-09-23T22:14:51.047Z,1569276891.047 [DataOverHttps](INFO): SBD MOMSN=11806186
2019-09-23T22:14:55.414Z,1569276895.414 [Startup:StartupSatComms:B](INFO): Timed out from 2019-09-23T22:13:55.2Z
2019-09-23T22:14:55.414Z,1569276895.414 [Startup:StartupSatComms:B] Stopped
2019-09-23T22:14:55.414Z,1569276895.414 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-09-23T22:14:55.414Z,1569276895.414 [Startup:StartupSatComms] Stopped
2019-09-23T22:14:55.415Z,1569276895.415 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-09-23T22:14:55.415Z,1569276895.415 [Startup](INFO): Completed Startup
2019-09-23T22:14:55.415Z,1569276895.415 [MissionManager](INFO): Startup is completed.
2019-09-23T22:14:55.416Z,1569276895.416 [MissionManager](INFO): Uninitializing Mission Startup
2019-09-23T22:14:55.416Z,1569276895.416 [Startup] Stopped
2019-09-23T22:14:55.416Z,1569276895.416 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-09-23T22:14:55.416Z,1569276895.416 [Startup:A.GoToSurface] Stopped
2019-09-23T22:14:55.416Z,1569276895.416 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-09-23T22:14:55.778Z,1569276895.778 [MissionManager](IMPORTANT): Started mission Default
2019-09-23T22:14:55.778Z,1569276895.778 [Default] Running Loop=1
2019-09-23T22:14:55.778Z,1569276895.778 [Default](DEBUG): Aggregate::initialize Default
2019-09-23T22:14:55.778Z,1569276895.778 [Default:B.GoToSurface] Running Loop=1
2019-09-23T22:14:55.778Z,1569276895.778 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-09-23T22:14:55.779Z,1569276895.779 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-09-23T22:14:55.779Z,1569276895.779 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-09-23T22:14:55.779Z,1569276895.779 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-09-23T22:14:55.779Z,1569276895.779 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-09-23T22:14:55.780Z,1569276895.780 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-09-23T22:14:55.780Z,1569276895.780 [Default:A.Wait] Running Loop=1
2019-09-23T22:14:55.780Z,1569276895.780 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:14:56.584Z,1569276896.584 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T22:14:56.584Z,1569276896.584 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092322160127,35.0, -0.1, 48.9,  0
2019-09-23T22:15:08.330Z,1569276908.330 [DataOverHttps](INFO): Sending 893 bytes from file Logs/20190923T221050/Express0001.lzma
2019-09-23T22:15:09.105Z,1569276909.105 [Default:A.Wait](INFO): Done Waiting.
2019-09-23T22:15:09.105Z,1569276909.105 [Default:A.Wait] Stopped
2019-09-23T22:15:09.105Z,1569276909.105 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:15:09.503Z,1569276909.503 [Default:CheckIn] Running Loop=1
2019-09-23T22:15:09.503Z,1569276909.503 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:15:09.503Z,1569276909.503 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:15:09.907Z,1569276909.907 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-09-23T22:15:10.334Z,1569276910.334 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0001.lzma.bak
2019-09-23T22:15:10.334Z,1569276910.334 [DataOverHttps](INFO): SBD MOMSN=11806188
2019-09-23T22:16:38.395Z,1569276998.395 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-09-23T22:16:41.998Z,1569277001.998 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T22:16:42.817Z,1569277002.817 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:16:43.216Z,1569277003.216 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221642.00,A,3648.16154,N,12147.28080,W,0.253,0.00,230919,,,A*74
2019-09-23T22:16:43.219Z,1569277003.219 [NAL9602](INFO): GPS fix at 20190923T221642: (36.802692, -121.788013)
2019-09-23T22:16:43.264Z,1569277003.264 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:16:43.264Z,1569277003.264 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:16:43.675Z,1569277003.675 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-09-23T22:17:00.281Z,1569277020.281 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190923T221050/Courier0004.lzma
2019-09-23T22:17:02.298Z,1569277022.298 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0004.lzma.bak
2019-09-23T22:17:02.298Z,1569277022.298 [DataOverHttps](INFO): SBD MOMSN=11806219
2019-09-23T22:17:15.534Z,1569277035.534 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:17:19.901Z,1569277039.901 [DataOverHttps](INFO): Sending 301 bytes from file Logs/20190923T221050/Express0005.lzma
2019-09-23T22:17:21.906Z,1569277041.906 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0005.lzma.bak
2019-09-23T22:17:21.907Z,1569277041.907 [DataOverHttps](INFO): SBD MOMSN=11806222
2019-09-23T22:17:23.240Z,1569277043.240 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:17:23.240Z,1569277043.240 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:17:23.240Z,1569277043.240 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:18:04.873Z,1569277084.873 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-09-23T22:18:04.876Z,1569277084.876 [BPC1](INFO): Received data from all battery sticks.
2019-09-23T22:18:32.054Z,1569277112.054 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.295925
2019-09-23T22:18:45.189Z,1569277125.189 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.008864
2019-09-23T22:19:36.273Z,1569277176.273 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-09-23T22:19:36.273Z,1569277176.273 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-09-23T22:19:36.273Z,1569277176.273 [RDI_Pathfinder](ERROR): Communications Fault
2019-09-23T22:19:36.273Z,1569277176.273 [RDI_Pathfinder](ERROR): Failed to parse:
2019-09-23T22:19:36.296Z,1569277176.296 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-09-23T22:19:36.653Z,1569277176.653 [RDI_Pathfinder](INFO): Powering down
2019-09-23T22:19:37.393Z,1569277177.393 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-09-23T22:19:37.393Z,1569277177.393 [RDI_Pathfinder] No Fault, FailCount= 1
2019-09-23T22:19:51.105Z,1569277191.105 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-09-23T22:22:23.828Z,1569277343.828 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T22:22:23.828Z,1569277343.828 [Default:CheckIn:C.Wait] Stopped
2019-09-23T22:22:23.828Z,1569277343.828 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:22:23.828Z,1569277343.828 [Default:CheckIn:D] Running Loop=1
2019-09-23T22:22:24.244Z,1569277344.244 [Default:CheckIn:D] Stopped
2019-09-23T22:22:24.244Z,1569277344.244 [Default:CheckIn:E] Running Loop=1
2019-09-23T22:22:24.643Z,1569277344.643 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.474426 min 
2019-09-23T22:22:24.643Z,1569277344.643 [Default:CheckIn:E] Stopped
2019-09-23T22:22:24.643Z,1569277344.643 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T22:22:24.643Z,1569277344.643 [Default:CheckIn] Stopped
2019-09-23T22:22:24.644Z,1569277344.644 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T22:22:24.644Z,1569277344.644 [Default:CheckIn](INFO): Running loop #2
2019-09-23T22:22:24.644Z,1569277344.644 [Default:CheckIn] Running Loop=2
2019-09-23T22:22:24.644Z,1569277344.644 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:22:24.644Z,1569277344.644 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:22:26.241Z,1569277346.241 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:22:26.632Z,1569277346.632 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222225.00,A,3648.16442,N,12147.27866,W,0.097,0.00,230919,,,A*75
2019-09-23T22:22:26.634Z,1569277346.634 [NAL9602](INFO): GPS fix at 20190923T222225: (36.802740, -121.787978)
2019-09-23T22:22:26.676Z,1569277346.676 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:22:26.676Z,1569277346.676 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:22:27.861Z,1569277347.861 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:22:36.285Z,1569277356.285 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190923T221050/Courier0007.lzma
2019-09-23T22:22:38.290Z,1569277358.290 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0007.lzma.bak
2019-09-23T22:22:38.291Z,1569277358.291 [DataOverHttps](INFO): SBD MOMSN=11806237
2019-09-23T22:22:55.773Z,1569277375.773 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20190923T221050/Express0008.lzma
2019-09-23T22:22:57.334Z,1569277377.334 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-09-23T22:22:57.413Z,1569277377.413 [NAL9602](FAULT): received: K
CSQ:1

OK36, 2, 0, 0, 0

OK
2019-09-23T22:22:57.413Z,1569277377.413 [NAL9602] Data Fault, FailCount= 1
2019-09-23T22:22:57.413Z,1569277377.413 [NAL9602](ERROR): Data Fault
2019-09-23T22:22:57.521Z,1569277377.521 [CBIT](ERROR): Data Fault in component: NAL9602
2019-09-23T22:22:57.738Z,1569277377.738 [NAL9602](INFO): Powering down
2019-09-23T22:22:57.778Z,1569277377.778 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0008.lzma.bak
2019-09-23T22:22:57.779Z,1569277377.779 [DataOverHttps](INFO): SBD MOMSN=11806240
2019-09-23T22:22:58.582Z,1569277378.582 [CBIT](INFO): Clearing failed state for component NAL9602
2019-09-23T22:22:58.582Z,1569277378.582 [NAL9602] No Fault, FailCount= 1
2019-09-23T22:22:59.400Z,1569277379.400 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:22:59.400Z,1569277379.400 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:22:59.400Z,1569277379.400 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:23:28.042Z,1569277408.042 [NAL9602](INFO): Powering up NAL9602
2019-09-23T22:23:38.946Z,1569277418.946 [NAL9602](INFO): NAL9602 initialized
2019-09-23T22:24:10.054Z,1569277450.054 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:24:15.345Z,1569277455.345 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-09-23T22:27:59.961Z,1569277679.961 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T22:27:59.961Z,1569277679.961 [Default:CheckIn:C.Wait] Stopped
2019-09-23T22:27:59.961Z,1569277679.961 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:27:59.961Z,1569277679.961 [Default:CheckIn:D] Running Loop=1
2019-09-23T22:28:00.383Z,1569277680.383 [Default:CheckIn:D] Stopped
2019-09-23T22:28:00.383Z,1569277680.383 [Default:CheckIn:E] Running Loop=1
2019-09-23T22:28:00.784Z,1569277680.784 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.076756 min 
2019-09-23T22:28:00.784Z,1569277680.784 [Default:CheckIn:E] Stopped
2019-09-23T22:28:00.784Z,1569277680.784 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T22:28:00.784Z,1569277680.784 [Default:CheckIn] Stopped
2019-09-23T22:28:00.784Z,1569277680.784 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T22:28:00.785Z,1569277680.785 [Default:CheckIn](INFO): Running loop #3
2019-09-23T22:28:00.785Z,1569277680.785 [Default:CheckIn] Running Loop=3
2019-09-23T22:28:00.785Z,1569277680.785 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:28:00.785Z,1569277680.785 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:28:02.385Z,1569277682.385 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:28:02.766Z,1569277682.766 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222801.00,A,3648.13747,N,12147.23296,W,0.019,124.29,230919,,,A*71
2019-09-23T22:28:02.768Z,1569277682.768 [NAL9602](INFO): GPS fix at 20190923T222801: (36.802291, -121.787216)
2019-09-23T22:28:02.809Z,1569277682.809 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:28:02.809Z,1569277682.809 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:28:04.792Z,1569277684.792 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:28:05.190Z,1569277685.190 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T22:28:09.992Z,1569277689.992 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T221050/Courier0010.lzma
2019-09-23T22:28:17.021Z,1569277697.021 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0010.lzma.bak
2019-09-23T22:28:17.021Z,1569277697.021 [DataOverHttps](INFO): SBD MOMSN=11806254
2019-09-23T22:28:35.906Z,1569277715.906 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:28:36.624Z,1569277716.624 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190923T221050/Express0011.lzma
2019-09-23T22:28:38.630Z,1569277718.630 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0011.lzma.bak
2019-09-23T22:28:38.630Z,1569277718.630 [DataOverHttps](INFO): SBD MOMSN=11806257
2019-09-23T22:28:39.969Z,1569277719.969 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:28:39.969Z,1569277719.969 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:28:39.970Z,1569277719.970 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:33:40.568Z,1569278020.568 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T22:33:40.568Z,1569278020.568 [Default:CheckIn:C.Wait] Stopped
2019-09-23T22:33:40.568Z,1569278020.568 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:33:40.568Z,1569278020.568 [Default:CheckIn:D] Running Loop=1
2019-09-23T22:33:40.996Z,1569278020.996 [Default:CheckIn:D] Stopped
2019-09-23T22:33:40.996Z,1569278020.996 [Default:CheckIn:E] Running Loop=1
2019-09-23T22:33:41.357Z,1569278021.357 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.753634 min 
2019-09-23T22:33:41.357Z,1569278021.357 [Default:CheckIn:E] Stopped
2019-09-23T22:33:41.357Z,1569278021.357 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T22:33:41.358Z,1569278021.358 [Default:CheckIn] Stopped
2019-09-23T22:33:41.358Z,1569278021.358 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T22:33:41.358Z,1569278021.358 [Default:CheckIn](INFO): Running loop #4
2019-09-23T22:33:41.358Z,1569278021.358 [Default:CheckIn] Running Loop=4
2019-09-23T22:33:41.358Z,1569278021.358 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:33:41.358Z,1569278021.358 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:33:42.969Z,1569278022.969 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:33:43.357Z,1569278023.357 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223342.00,A,3648.13705,N,12147.23318,W,0.000,124.29,230919,,,D*70
2019-09-23T22:33:43.359Z,1569278023.359 [NAL9602](INFO): GPS fix at 20190923T223342: (36.802284, -121.787220)
2019-09-23T22:33:43.382Z,1569278023.382 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:33:43.382Z,1569278023.382 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:33:44.978Z,1569278024.978 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:33:51.024Z,1569278031.024 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T221050/Courier0013.lzma
2019-09-23T22:33:53.044Z,1569278033.044 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0013.lzma.bak
2019-09-23T22:33:53.044Z,1569278033.044 [DataOverHttps](INFO): SBD MOMSN=11806273
2019-09-23T22:34:10.418Z,1569278050.418 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190923T221050/Express0014.lzma
2019-09-23T22:34:12.422Z,1569278052.422 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0014.lzma.bak
2019-09-23T22:34:12.422Z,1569278052.422 [DataOverHttps](INFO): SBD MOMSN=11806276
2019-09-23T22:34:13.704Z,1569278053.704 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:34:13.704Z,1569278053.704 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:34:13.704Z,1569278053.704 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:35:15.063Z,1569278115.063 [NAL9602](INFO): SBD MO Status=2, MOMSN=1436, MT Status=2, MTMSN=0
2019-09-23T22:35:15.064Z,1569278115.064 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T22:35:37.695Z,1569278137.695 [NAL9602](INFO): SBD MO Status=0, MOMSN=1436, MT Status=0, MTMSN=0
2019-09-23T22:35:37.696Z,1569278137.696 [NAL9602](INFO): No messages in MT queue
2019-09-23T22:36:08.406Z,1569278168.406 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:39:14.279Z,1569278354.279 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T22:39:14.280Z,1569278354.280 [Default:CheckIn:C.Wait] Stopped
2019-09-23T22:39:14.280Z,1569278354.280 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:39:14.280Z,1569278354.280 [Default:CheckIn:D] Running Loop=1
2019-09-23T22:39:14.660Z,1569278354.660 [Default:CheckIn:D] Stopped
2019-09-23T22:39:14.661Z,1569278354.661 [Default:CheckIn:E] Running Loop=1
2019-09-23T22:39:15.078Z,1569278355.078 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.314705 min 
2019-09-23T22:39:15.078Z,1569278355.078 [Default:CheckIn:E] Stopped
2019-09-23T22:39:15.079Z,1569278355.079 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T22:39:15.079Z,1569278355.079 [Default:CheckIn] Stopped
2019-09-23T22:39:15.079Z,1569278355.079 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T22:39:15.079Z,1569278355.079 [Default:CheckIn](INFO): Running loop #5
2019-09-23T22:39:15.079Z,1569278355.079 [Default:CheckIn] Running Loop=5
2019-09-23T22:39:15.079Z,1569278355.079 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:39:15.079Z,1569278355.079 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:39:16.667Z,1569278356.667 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:39:17.064Z,1569278357.064 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223917.00,A,3648.13781,N,12147.23202,W,0.019,124.29,230919,,,D*74
2019-09-23T22:39:17.066Z,1569278357.066 [NAL9602](INFO): GPS fix at 20190923T223917: (36.802297, -121.787200)
2019-09-23T22:39:17.117Z,1569278357.117 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:39:17.117Z,1569278357.117 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:39:19.138Z,1569278359.138 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:39:24.480Z,1569278364.480 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190923T221050/Courier0016.lzma
2019-09-23T22:39:26.486Z,1569278366.486 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0016.lzma.bak
2019-09-23T22:39:26.487Z,1569278366.487 [DataOverHttps](INFO): SBD MOMSN=11806295
2019-09-23T22:39:33.276Z,1569278373.276 [NAL9602](INFO): SBD MO Status=0, MOMSN=1437, MT Status=0, MTMSN=0
2019-09-23T22:39:33.276Z,1569278373.276 [NAL9602](INFO): No messages in MT queue
2019-09-23T22:39:46.776Z,1569278386.776 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190923T221050/Express0017.lzma
2019-09-23T22:39:48.782Z,1569278388.782 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0017.lzma.bak
2019-09-23T22:39:48.783Z,1569278388.783 [DataOverHttps](INFO): SBD MOMSN=11806299
2019-09-23T22:39:50.296Z,1569278390.296 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:39:50.296Z,1569278390.296 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:39:50.296Z,1569278390.296 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:40:03.974Z,1569278403.974 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:44:50.858Z,1569278690.858 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T22:44:50.858Z,1569278690.858 [Default:CheckIn:C.Wait] Stopped
2019-09-23T22:44:50.858Z,1569278690.858 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:44:50.858Z,1569278690.858 [Default:CheckIn:D] Running Loop=1
2019-09-23T22:44:51.275Z,1569278691.275 [Default:CheckIn:D] Stopped
2019-09-23T22:44:51.275Z,1569278691.275 [Default:CheckIn:E] Running Loop=1
2019-09-23T22:44:51.660Z,1569278691.660 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.924955 min 
2019-09-23T22:44:51.661Z,1569278691.661 [Default:CheckIn:E] Stopped
2019-09-23T22:44:51.661Z,1569278691.661 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T22:44:51.661Z,1569278691.661 [Default:CheckIn] Stopped
2019-09-23T22:44:51.661Z,1569278691.661 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T22:44:51.661Z,1569278691.661 [Default:CheckIn](INFO): Running loop #6
2019-09-23T22:44:51.661Z,1569278691.661 [Default:CheckIn] Running Loop=6
2019-09-23T22:44:51.661Z,1569278691.661 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:44:51.662Z,1569278691.662 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:44:53.261Z,1569278693.261 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:44:53.661Z,1569278693.661 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224453.00,A,3648.15647,N,12147.21983,W,0.097,22.78,230919,,,D*46
2019-09-23T22:44:53.663Z,1569278693.663 [NAL9602](INFO): GPS fix at 20190923T224453: (36.802608, -121.786997)
2019-09-23T22:44:53.686Z,1569278693.686 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:44:53.687Z,1569278693.687 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:44:54.962Z,1569278694.962 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:45:00.970Z,1569278700.970 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190923T221050/Courier0019.lzma
2019-09-23T22:45:02.974Z,1569278702.974 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0019.lzma.bak
2019-09-23T22:45:02.974Z,1569278702.974 [DataOverHttps](INFO): SBD MOMSN=11806314
2019-09-23T22:45:09.887Z,1569278709.887 [NAL9602](INFO): SBD MO Status=0, MOMSN=1438, MT Status=0, MTMSN=0
2019-09-23T22:45:09.888Z,1569278709.888 [NAL9602](INFO): No messages in MT queue
2019-09-23T22:45:20.320Z,1569278720.320 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190923T221050/Express0020.lzma
2019-09-23T22:45:22.326Z,1569278722.326 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0020.lzma.bak
2019-09-23T22:45:22.326Z,1569278722.326 [DataOverHttps](INFO): SBD MOMSN=11806317
2019-09-23T22:45:23.647Z,1569278723.647 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:45:23.647Z,1569278723.647 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:45:23.647Z,1569278723.647 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:45:40.583Z,1569278740.583 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:50:24.255Z,1569279024.255 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T22:50:24.255Z,1569279024.255 [Default:CheckIn:C.Wait] Stopped
2019-09-23T22:50:24.255Z,1569279024.255 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:50:24.255Z,1569279024.255 [Default:CheckIn:D] Running Loop=1
2019-09-23T22:50:24.627Z,1569279024.627 [Default:CheckIn:D] Stopped
2019-09-23T22:50:24.627Z,1569279024.627 [Default:CheckIn:E] Running Loop=1
2019-09-23T22:50:25.100Z,1569279025.100 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.480806 min 
2019-09-23T22:50:25.100Z,1569279025.100 [Default:CheckIn:E] Stopped
2019-09-23T22:50:25.100Z,1569279025.100 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T22:50:25.100Z,1569279025.100 [Default:CheckIn] Stopped
2019-09-23T22:50:25.109Z,1569279025.109 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T22:50:25.109Z,1569279025.109 [Default:CheckIn](INFO): Running loop #7
2019-09-23T22:50:25.109Z,1569279025.109 [Default:CheckIn] Running Loop=7
2019-09-23T22:50:25.109Z,1569279025.109 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:50:25.109Z,1569279025.109 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:50:26.629Z,1569279026.629 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:50:27.028Z,1569279027.028 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225027.00,A,3648.15865,N,12147.21856,W,0.039,74.56,230919,,,D*4C
2019-09-23T22:50:27.030Z,1569279027.030 [NAL9602](INFO): GPS fix at 20190923T225027: (36.802644, -121.786976)
2019-09-23T22:50:27.084Z,1569279027.084 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:50:27.084Z,1569279027.084 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:50:29.054Z,1569279029.054 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:50:34.340Z,1569279034.340 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T221050/Courier0022.lzma
2019-09-23T22:50:36.346Z,1569279036.346 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0022.lzma.bak
2019-09-23T22:50:36.347Z,1569279036.347 [DataOverHttps](INFO): SBD MOMSN=11806336
2019-09-23T22:50:39.951Z,1569279039.951 [NAL9602](INFO): SBD MO Status=0, MOMSN=1439, MT Status=0, MTMSN=0
2019-09-23T22:50:39.951Z,1569279039.951 [NAL9602](INFO): No messages in MT queue
2019-09-23T22:50:53.736Z,1569279053.736 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190923T221050/Express0023.lzma
2019-09-23T22:50:55.743Z,1569279055.743 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0023.lzma.bak
2019-09-23T22:50:55.743Z,1569279055.743 [DataOverHttps](INFO): SBD MOMSN=11806339
2019-09-23T22:50:57.367Z,1569279057.367 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:50:57.368Z,1569279057.368 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:50:57.368Z,1569279057.368 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T22:51:10.658Z,1569279070.658 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:53:28.678Z,1569279208.678 [DataOverHttps](IMPORTANT): SBD MTMSN=20190923T225328
2019-09-23T22:53:36.425Z,1569279216.425 [DataOverHttps](INFO): Received command:Ibit
2019-09-23T22:53:36.466Z,1569279216.466 [CommandLine](IMPORTANT): got command ibit
2019-09-23T22:53:36.552Z,1569279216.552 [IBIT](IMPORTANT): Beginning Initiated BIT
2019-09-23T22:53:36.552Z,1569279216.552 [IBIT](IMPORTANT): Beginning control surface checks.
2019-09-23T22:53:36.555Z,1569279216.555 [CBIT](IMPORTANT): Beginning ground fault scan
2019-09-23T22:53:37.741Z,1569279217.741 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:53:38.128Z,1569279218.128 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225338.00,A,3648.15835,N,12147.21898,W,0.039,74.56,230919,,,D*46
2019-09-23T22:53:38.131Z,1569279218.131 [NAL9602](INFO): GPS fix at 20190923T225338: (36.802639, -121.786983)
2019-09-23T22:53:39.755Z,1569279219.755 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:53:47.454Z,1569279227.454 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.020376
CHAN A1 (24V): 0.000295
CHAN A2 (12V): -0.007886
CHAN A3 (5V): -0.002331
CHAN B0 (3.3V): 0.000201
CHAN B1 (3.15aV): 0.000292
CHAN B2 (3.15bV): 0.000363
CHAN B3 (GND): 0.002306
OPEN: 0.004926
Full Scale Calc: 4.765 mA, -1.589 mA
2019-09-23T22:53:56.329Z,1569279236.329 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T22:53:56.329Z,1569279236.329 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092322550104,35.   0.0,1448.9,  0
2019-09-23T22:54:47.264Z,1569279287.264 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 1
Latitude: 36.802639 Longitude: -121.786980
2019-09-23T22:54:47.665Z,1569279287.665 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 0.000000
2019-09-23T22:54:47.665Z,1569279287.665 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2019-09-23T22:54:47.666Z,1569279287.666 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2019-09-23T22:54:48.066Z,1569279288.066 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2019-09-23T22:54:48.066Z,1569279288.066 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2019-09-23T22:54:48.066Z,1569279288.066 [IBIT](IMPORTANT): Pressure:7.582671 PSI
2019-09-23T22:54:48.067Z,1569279288.067 [IBIT](IMPORTANT): Humidity:4.486632 %
2019-09-23T22:54:48.465Z,1569279288.465 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2019-09-23T22:54:48.465Z,1569279288.465 [IBIT](IMPORTANT): buoyancyNeutral: 80.000000 cc
2019-09-23T22:54:48.466Z,1569279288.466 [IBIT](IMPORTANT): massDefault: 1.000000 cm
2019-09-23T22:54:48.466Z,1569279288.466 [IBIT](IMPORTANT): stopDepth: 215.000000 m
2019-09-23T22:54:48.466Z,1569279288.466 [IBIT](IMPORTANT): abortDepth: 255.000000 m
2019-09-23T22:54:48.466Z,1569279288.466 [IBIT](IMPORTANT): IBIT PASSED
2019-09-23T22:55:06.200Z,1569279306.200 [NAL9602](INFO): SBD MO Status=2, MOMSN=1440, MT Status=2, MTMSN=0
2019-09-23T22:55:06.200Z,1569279306.200 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T22:55:10.302Z,1569279310.302 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-09-23T22:55:10.303Z,1569279310.303 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,           ,        +0.00,   0.00,2118.82
2019-09-23T22:55:57.942Z,1569279357.942 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T22:55:57.942Z,1569279357.942 [Default:CheckIn:C.Wait] Stopped
2019-09-23T22:55:57.942Z,1569279357.942 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T22:55:57.942Z,1569279357.942 [Default:CheckIn:D] Running Loop=1
2019-09-23T22:55:58.358Z,1569279358.358 [Default:CheckIn:D] Stopped
2019-09-23T22:55:58.358Z,1569279358.358 [Default:CheckIn:E] Running Loop=1
2019-09-23T22:55:58.748Z,1569279358.748 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.043005 min 
2019-09-23T22:55:58.749Z,1569279358.749 [Default:CheckIn:E] Stopped
2019-09-23T22:55:58.749Z,1569279358.749 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T22:55:58.749Z,1569279358.749 [Default:CheckIn] Stopped
2019-09-23T22:55:58.749Z,1569279358.749 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T22:55:58.749Z,1569279358.749 [Default:CheckIn](INFO): Running loop #8
2019-09-23T22:55:58.749Z,1569279358.749 [Default:CheckIn] Running Loop=8
2019-09-23T22:55:58.749Z,1569279358.749 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T22:55:58.750Z,1569279358.750 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T22:56:06.399Z,1569279366.399 [NAL9602](INFO): SBD MO Status=2, MOMSN=1440, MT Status=2, MTMSN=0
2019-09-23T22:56:06.399Z,1569279366.399 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T22:57:09.021Z,1569279429.021 [NAL9602](INFO): SBD MO Status=2, MOMSN=1440, MT Status=2, MTMSN=0
2019-09-23T22:57:09.021Z,1569279429.021 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T22:57:36.087Z,1569279456.087 [NAL9602](INFO): SBD MO Status=0, MOMSN=1440, MT Status=0, MTMSN=0
2019-09-23T22:57:36.087Z,1569279456.087 [NAL9602](INFO): No messages in MT queue
2019-09-23T22:57:36.905Z,1569279456.905 [NAL9602](DEBUG): Fix Requested
2019-09-23T22:57:37.296Z,1569279457.296 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225737.00,A,3648.15802,N,12147.21875,W,0.019,74.56,230919,,,D*48
2019-09-23T22:57:37.298Z,1569279457.298 [NAL9602](INFO): GPS fix at 20190923T225737: (36.802634, -121.786979)
2019-09-23T22:57:37.357Z,1569279457.357 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T22:57:37.357Z,1569279457.357 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T22:57:38.918Z,1569279458.918 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T22:57:47.744Z,1569279467.744 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T221050/Courier0025.lzma
2019-09-23T22:57:49.750Z,1569279469.750 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0025.lzma.bak
2019-09-23T22:57:49.751Z,1569279469.751 [DataOverHttps](INFO): SBD MOMSN=11806356
2019-09-23T22:58:07.260Z,1569279487.260 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190923T221050/Courier0028.lzma
2019-09-23T22:58:09.269Z,1569279489.269 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0028.lzma.bak
2019-09-23T22:58:09.270Z,1569279489.270 [DataOverHttps](INFO): SBD MOMSN=11806359
2019-09-23T22:58:09.618Z,1569279489.618 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T22:58:30.968Z,1569279510.968 [DataOverHttps](INFO): Sending 732 bytes from file Logs/20190923T221050/Express0026.lzma
2019-09-23T22:58:32.929Z,1569279512.929 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0026.lzma.bak
2019-09-23T22:58:32.930Z,1569279512.930 [DataOverHttps](INFO): SBD MOMSN=11806361
2019-09-23T22:58:50.308Z,1569279530.308 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190923T221050/Express0029.lzma
2019-09-23T22:58:52.315Z,1569279532.315 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0029.lzma.bak
2019-09-23T22:58:52.315Z,1569279532.315 [DataOverHttps](INFO): SBD MOMSN=11806385
2019-09-23T22:58:53.680Z,1569279533.680 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T22:58:53.680Z,1569279533.680 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T22:58:53.680Z,1569279533.680 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T23:01:38.121Z,1569279698.121 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-09-23T23:01:38.121Z,1569279698.121 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.00,        +0.0  +0.00,   0.00,2506.72
2019-09-23T23:03:54.272Z,1569279834.272 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T23:03:54.272Z,1569279834.272 [Default:CheckIn:C.Wait] Stopped
2019-09-23T23:03:54.277Z,1569279834.277 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T23:03:54.277Z,1569279834.277 [Default:CheckIn:D] Running Loop=1
2019-09-23T23:03:54.653Z,1569279834.653 [Default:CheckIn:D] Stopped
2019-09-23T23:03:54.653Z,1569279834.653 [Default:CheckIn:E] Running Loop=1
2019-09-23T23:03:55.077Z,1569279835.077 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.981254 min 
2019-09-23T23:03:55.077Z,1569279835.077 [Default:CheckIn:E] Stopped
2019-09-23T23:03:55.077Z,1569279835.077 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T23:03:55.077Z,1569279835.077 [Default:CheckIn] Stopped
2019-09-23T23:03:55.077Z,1569279835.077 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T23:03:55.078Z,1569279835.078 [Default:CheckIn](INFO): Running loop #9
2019-09-23T23:03:55.078Z,1569279835.078 [Default:CheckIn] Running Loop=9
2019-09-23T23:03:55.078Z,1569279835.078 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T23:03:55.078Z,1569279835.078 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T23:03:56.669Z,1569279836.669 [NAL9602](DEBUG): Fix Requested
2019-09-23T23:03:57.054Z,1569279837.054 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230357.00,A,3648.50190,N,12147.21731,W,5.443,243.35,230919,,,D*7F
2019-09-23T23:03:57.056Z,1569279837.056 [NAL9602](INFO): GPS fix at 20190923T230357: (36.808365, -121.786955)
2019-09-23T23:03:57.118Z,1569279837.118 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T23:03:57.118Z,1569279837.118 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T23:03:58.734Z,1569279838.734 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T23:04:04.535Z,1569279844.535 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T221050/Courier0030.lzma
2019-09-23T23:04:06.539Z,1569279846.539 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0030.lzma.bak
2019-09-23T23:04:06.540Z,1569279846.540 [DataOverHttps](IMPORTANT): SBD MOMSN=11806424, MTMSN=20190923T230405
2019-09-23T23:04:14.217Z,1569279854.217 [DataOverHttps](INFO): Received command:sched asap "load Engineering/portuguese_ledge.xml;set portuguese_ledge.NeedCommsTime 20 minute;set portuguese_ledge.MaxDepth 30 meter;set portuguese_ledge.MinOffshore 2 kilometer;set portuguese_ledge.MinAltitude 7 meter" 38ler 1 2
2019-09-23T23:04:14.274Z,1569279854.274 [CommandLine](IMPORTANT): got command schedule asap "load Engineering/portuguese_ledge.xml;set portuguese_ledge.NeedCommsTime 20 minute;set portuguese_ledge.MaxDepth 30 meter;set portuguese_ledge.MinOffshore 2 kilometer;set portuguese_ledge.MinAltitude 7 meter" 38ler 1 2.000000
2019-09-23T23:04:14.275Z,1569279854.275 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=38ler
2019-09-23T23:04:14.275Z,1569279854.275 [CommandLine](IMPORTANT): Scheduled #1 (#1 of 2 with id='38ler'): "load Engineering/portuguese_ledge.xml;set portuguese_ledge.NeedCommsTime 20 minute;set portuguese_ledge.MaxDepth 30 meter;set portuguese_ledge.MinOffshore 2 kilometer;set portuguese_ledge.MinAltitude 7 meter" ASAP
2019-09-23T23:04:16.223Z,1569279856.223 [DataOverHttps](IMPORTANT): SBD MTMSN=20190923T230415
2019-09-23T23:04:27.501Z,1569279867.501 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190923T221050/Express0032.lzma
2019-09-23T23:04:27.509Z,1569279867.509 [DataOverHttps](INFO): Received command:sched asap "set portuguese_ledge.ContactLabel 5 count;set portuguese_ledge.TrackingUpdatePeriod 35 second;run " 38ler 2 2
2019-09-23T23:04:27.594Z,1569279867.594 [CommandLine](IMPORTANT): got command schedule asap "set portuguese_ledge.ContactLabel 5 count;set portuguese_ledge.TrackingUpdatePeriod 35 second;run " 38ler 2 2.000000
2019-09-23T23:04:27.595Z,1569279867.595 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=38ler
2019-09-23T23:04:27.596Z,1569279867.596 [CommandLine](IMPORTANT): Scheduled #2 (#2 of 2 with id='38ler'): "set portuguese_ledge.ContactLabel 5 count;set portuguese_ledge.TrackingUpdatePeriod 35 second;run " ASAP
2019-09-23T23:04:27.804Z,1569279867.804 [CommandLine](IMPORTANT): got command load ./Missions/Engineering/portuguese_ledge.xml
2019-09-23T23:04:27.804Z,1569279867.804 [MissionManager](INFO): Loading Mission: ./Missions/Engineering/portuguese_ledge.xml
2019-09-23T23:04:28.027Z,1569279868.027 [MissionManager](INFO): DefineArg portuguese_ledge.MissionTimeout = 4.000000 h
2019-09-23T23:04:28.031Z,1569279868.031 [MissionManager](INFO): DefineArg portuguese_ledge.NeedCommsTime = 120.000000 min
2019-09-23T23:04:28.034Z,1569279868.034 [MissionManager](INFO): DefineArg portuguese_ledge.AcousticContactTimeout = 15.000000 min
2019-09-23T23:04:28.036Z,1569279868.036 [MissionManager](INFO): DefineArg portuguese_ledge.Depth = 50.000000 m
2019-09-23T23:04:28.076Z,1569279868.076 [MissionManager](INFO): DefineArg portuguese_ledge.Speed = 1.000000 m/s
2019-09-23T23:04:28.104Z,1569279868.104 [MissionManager](INFO): DefineArg portuguese_ledge.MaxDepth = 60.000000 m
2019-09-23T23:04:28.108Z,1569279868.108 [MissionManager](INFO): DefineArg portuguese_ledge.MinOffshore = 4.000000 km
2019-09-23T23:04:28.134Z,1569279868.134 [MissionManager](INFO): DefineArg portuguese_ledge.MinAltitude = 5.000000 m
2019-09-23T23:04:28.147Z,1569279868.147 [MissionManager](INFO): DefineArg portuguese_ledge.MassHold = 1 bool
2019-09-23T23:04:28.152Z,1569279868.152 [MissionManager](INFO): DefineArg portuguese_ledge.BuoyancyHold = 1 bool
2019-09-23T23:04:28.155Z,1569279868.155 [MissionManager](INFO): DefineArg portuguese_ledge.Repeat = 4.000000 count
2019-09-23T23:04:28.160Z,1569279868.160 [MissionManager](INFO): DefineArg portuguese_ledge.Lat1 = 36.695944 arcdeg
2019-09-23T23:04:28.168Z,1569279868.168 [MissionManager](INFO): DefineArg portuguese_ledge.Lon1 = -121.945120 arcdeg
2019-09-23T23:04:28.171Z,1569279868.171 [MissionManager](INFO): DefineArg portuguese_ledge.Lat2 = 36.696536 arcdeg
2019-09-23T23:04:28.174Z,1569279868.174 [MissionManager](INFO): DefineArg portuguese_ledge.Lon2 = -121.937544 arcdeg
2019-09-23T23:04:28.176Z,1569279868.176 [MissionManager](INFO): DefineArg portuguese_ledge.Lat3 = 36.693760 arcdeg
2019-09-23T23:04:28.202Z,1569279868.202 [MissionManager](INFO): DefineArg portuguese_ledge.Lon3 = -121.938647 arcdeg
2019-09-23T23:04:28.205Z,1569279868.205 [MissionManager](INFO): DefineArg portuguese_ledge.Lat4 = 36.698094 arcdeg
2019-09-23T23:04:28.208Z,1569279868.208 [MissionManager](INFO): DefineArg portuguese_ledge.Lon4 = -121.940450 arcdeg
2019-09-23T23:04:28.279Z,1569279868.279 [MissionManager](INFO): DefineArg portuguese_ledge.Lat5 = 36.695944 arcdeg
2019-09-23T23:04:28.286Z,1569279868.286 [MissionManager](INFO): DefineArg portuguese_ledge.Lon5 = -121.945120 arcdeg
2019-09-23T23:04:28.301Z,1569279868.301 [MissionManager](INFO): DefineArg portuguese_ledge.ContactLabel = 0.000000 count
2019-09-23T23:04:28.304Z,1569279868.304 [MissionManager](INFO): DefineArg portuguese_ledge.ContactDepth = nan m
2019-09-23T23:04:28.315Z,1569279868.315 [MissionManager](INFO): DefineArg portuguese_ledge.TrackingUpdatePeriod = 60.000000 s
2019-09-23T23:04:28.318Z,1569279868.318 [MissionManager](INFO): DefineArg portuguese_ledge.NumberOfPings = 1.000000 count
2019-09-23T23:04:28.319Z,1569279868.319 [MissionManager](INFO): Inserting Stack: Missions/Insert/AbortDrift.xml
2019-09-23T23:04:28.348Z,1569279868.348 [MissionManager](INFO): DefineArg portuguese_ledge:AbortDrift.AcousticTimeout = 96.000000 h
2019-09-23T23:04:28.355Z,1569279868.355 [portuguese_ledge:AbortDrift:B.AbortDrift](DEBUG): Construct AbortDrift.
2019-09-23T23:04:28.362Z,1569279868.362 [portuguese_ledge:AbortDrift:C.Execute](DEBUG): Construct Execute.
2019-09-23T23:04:28.364Z,1569279868.364 [MissionManager](INFO): RedefineArg portuguese_ledge:AbortDrift.AcousticTimeout = reader:portuguese_ledge.AcousticContactTimeout
2019-09-23T23:04:28.549Z,1569279868.549 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2019-09-23T23:04:29.086Z,1569279869.086 [MissionManager](INFO): DefineArg portuguese_ledge:Science.SampleISUS = 0 bool
2019-09-23T23:04:29.101Z,1569279869.101 [MissionManager](INFO): DefineArg portuguese_ledge:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2019-09-23T23:04:29.104Z,1569279869.104 [MissionManager](INFO): DefineArg portuguese_ledge:Science.SampleISUSminPitch = -60.000000 arcdeg
2019-09-23T23:04:29.112Z,1569279869.112 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectChlActive = 0 bool
2019-09-23T23:04:29.123Z,1569279869.123 [MissionManager](INFO): DefineArg portuguese_ledge:Science.TimeWindowPeakReport = nan min
2019-09-23T23:04:29.126Z,1569279869.126 [MissionManager](INFO): DefineArg portuguese_ledge:Science.HighestChlPeakReportActive = 0 bool
2019-09-23T23:04:29.128Z,1569279869.128 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PatchTracking = 0 bool
2019-09-23T23:04:29.135Z,1569279869.135 [MissionManager](INFO): DefineArg portuguese_ledge:Science.FilterWidthHorizontal = 3.000000 count
2019-09-23T23:04:29.139Z,1569279869.139 [MissionManager](INFO): DefineArg portuguese_ledge:Science.NumProfilesSlidingwindow = 100.000000 count
2019-09-23T23:04:29.150Z,1569279869.150 [MissionManager](INFO): DefineArg portuguese_ledge:Science.OffPeakFractionHorizontal = 80.000000 %
2019-09-23T23:04:29.152Z,1569279869.152 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectNO3Active = 0 bool
2019-09-23T23:04:29.159Z,1569279869.159 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectOilActive = 0 bool
2019-09-23T23:04:29.162Z,1569279869.162 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectFDOMActive = 0 bool
2019-09-23T23:04:29.173Z,1569279869.173 [MissionManager](INFO): DefineArg portuguese_ledge:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2019-09-23T23:04:29.176Z,1569279869.176 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledAanderaaO2 = 0.000000 bool
2019-09-23T23:04:29.180Z,1569279869.180 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledNeilBrown = 0.000000 bool
2019-09-23T23:04:29.191Z,1569279869.191 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledSeabird = 1.000000 bool
2019-09-23T23:04:29.195Z,1569279869.195 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledTurbulence_NPS = 0.000000 bool
2019-09-23T23:04:29.207Z,1569279869.207 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledWetLabsBB2FL = 1.000000 bool
2019-09-23T23:04:29.215Z,1569279869.215 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool
2019-09-23T23:04:29.219Z,1569279869.219 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledWetLabsUBAT = 1.000000 bool
2019-09-23T23:04:29.236Z,1569279869.236 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledISUS = 0.000000 bool
2019-09-23T23:04:29.239Z,1569279869.239 [MissionManager](INFO): DefineArg portuguese_ledge:Science.LowPassWindowLength = 20.000000 count
2019-09-23T23:04:29.242Z,1569279869.242 [MissionManager](INFO): DefineArg portuguese_ledge:Science.MedianFilterLen = 5.000000 count
2019-09-23T23:04:29.262Z,1569279869.262 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakChlShallowBound = nan m
2019-09-23T23:04:29.270Z,1569279869.270 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakChlDeepBound = nan m
2019-09-23T23:04:29.288Z,1569279869.288 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakShallowBound = nan m
2019-09-23T23:04:29.291Z,1569279869.291 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDeepBound = nan m
2019-09-23T23:04:29.294Z,1569279869.294 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChl = 0.000000 ug/l
2019-09-23T23:04:29.309Z,1569279869.309 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlDepth = 0.000000 m
2019-09-23T23:04:29.312Z,1569279869.312 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlTemperature = 0.000000 degC
2019-09-23T23:04:29.315Z,1569279869.315 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlLatitude = nan arcdeg
2019-09-23T23:04:29.318Z,1569279869.318 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlLongitude = nan arcdeg
2019-09-23T23:04:29.331Z,1569279869.331 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3 = 0.000000 umol/l
2019-09-23T23:04:29.334Z,1569279869.334 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3Depth = 0.000000 m
2019-09-23T23:04:29.337Z,1569279869.337 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3Latitude = nan arcdeg
2019-09-23T23:04:29.340Z,1569279869.340 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3Longitude = nan arcdeg
2019-09-23T23:04:29.359Z,1569279869.359 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChl = 0.000000 m
2019-09-23T23:04:29.362Z,1569279869.362 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlDepth = 0.000000 m
2019-09-23T23:04:29.364Z,1569279869.364 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlLatitude = nan arcdeg
2019-09-23T23:04:29.367Z,1569279869.367 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlLongitude = nan arcdeg
2019-09-23T23:04:29.382Z,1569279869.382 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlDistance = nan m
2019-09-23T23:04:29.385Z,1569279869.385 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOil = 0.000000 kg/m3
2019-09-23T23:04:29.388Z,1569279869.388 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOilDepth = 0.000000 m
2019-09-23T23:04:29.391Z,1569279869.391 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOilLatitude = nan arcdeg
2019-09-23T23:04:29.410Z,1569279869.410 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOilLongitude = nan arcdeg
2019-09-23T23:04:29.413Z,1569279869.413 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOM = 0.000000 ppb
2019-09-23T23:04:29.416Z,1569279869.416 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOMDepth = 0.000000 m
2019-09-23T23:04:29.419Z,1569279869.419 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOMLatitude = nan arcdeg
2019-09-23T23:04:29.458Z,1569279869.458 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOMLongitude = nan arcdeg
2019-09-23T23:04:29.480Z,1569279869.480 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchFDOMDistance = nan m
2019-09-23T23:04:29.506Z,1569279869.506 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0032.lzma.bak
2019-09-23T23:04:29.507Z,1569279869.507 [DataOverHttps](INFO): SBD MOMSN=11806428
2019-09-23T23:04:29.547Z,1569279869.547 [portuguese_ledge:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-09-23T23:04:29.576Z,1569279869.576 [portuguese_ledge:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2019-09-23T23:04:29.606Z,1569279869.606 [portuguese_ledge:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-09-23T23:04:29.629Z,1569279869.629 [portuguese_ledge:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-09-23T23:04:29.648Z,1569279869.648 [portuguese_ledge:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-09-23T23:04:29.675Z,1569279869.675 [MissionManager](INFO): RedefineArg portuguese_ledge:Science.SampleISUS = value:1 bool
2019-09-23T23:04:29.681Z,1569279869.681 [MissionManager](INFO): RedefineArg portuguese_ledge:Science.PeakDetectChlActive = value:1 bool
2019-09-23T23:04:29.682Z,1569279869.682 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml
2019-09-23T23:04:29.752Z,1569279869.752 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.DiveInterval = 3.000000 h
2019-09-23T23:04:29.759Z,1569279869.759 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.WaitForPitchUp = 10.000000 min
2019-09-23T23:04:29.763Z,1569279869.763 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.SurfacePitch = 20.000000 arcdeg
2019-09-23T23:04:29.775Z,1569279869.775 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.SurfaceDepthRate = nan m/s
2019-09-23T23:04:29.778Z,1569279869.778 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.SurfaceSpeed = 1.000000 m/s
2019-09-23T23:04:29.790Z,1569279869.790 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.GPSTimeout = 7.000000 min
2019-09-23T23:04:29.799Z,1569279869.799 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.CommsTimeout = 30.000000 min
2019-09-23T23:04:29.814Z,1569279869.814 [portuguese_ledge:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-09-23T23:04:29.890Z,1569279869.890 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml
2019-09-23T23:04:29.935Z,1569279869.935 [MissionManager](INFO): DefineArg portuguese_ledge:StandardEnvelopes.MinAltitude = 5.000000 m
2019-09-23T23:04:29.949Z,1569279869.949 [MissionManager](INFO): DefineArg portuguese_ledge:StandardEnvelopes.MaxDepth = 200.000000 m
2019-09-23T23:04:29.952Z,1569279869.952 [MissionManager](INFO): DefineArg portuguese_ledge:StandardEnvelopes.MinOffshore = 2000.000000 m
2019-09-23T23:04:29.957Z,1569279869.957 [portuguese_ledge:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2019-09-23T23:04:29.968Z,1569279869.968 [portuguese_ledge:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2019-09-23T23:04:29.989Z,1569279869.989 [portuguese_ledge:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2019-09-23T23:04:30.018Z,1569279870.018 [portuguese_ledge:BuoyancyHold.Buoyancy](DEBUG): Construct Buoyancy.
2019-09-23T23:04:30.026Z,1569279870.026 [portuguese_ledge:MassHold.Pitch](DEBUG): Construct.
2019-09-23T23:04:30.036Z,1569279870.036 [portuguese_ledge:Transit:A.Pitch](DEBUG): Construct.
2019-09-23T23:04:30.050Z,1569279870.050 [portuguese_ledge:Transit:B.SetSpeed](DEBUG): Construct.
2019-09-23T23:04:30.070Z,1569279870.070 [portuguese_ledge:Transit:Lap:Wpt1:A.Waypoint](DEBUG): Construct Waypoint.
2019-09-23T23:04:30.085Z,1569279870.085 [portuguese_ledge:Transit:Lap:Wpt2:A.Waypoint](DEBUG): Construct Waypoint.
2019-09-23T23:04:30.092Z,1569279870.092 [portuguese_ledge:Transit:Lap:Wpt3:A.Waypoint](DEBUG): Construct Waypoint.
2019-09-23T23:04:30.110Z,1569279870.110 [portuguese_ledge:Transit:Lap:Wpt4:A.Waypoint](DEBUG): Construct Waypoint.
2019-09-23T23:04:30.130Z,1569279870.130 [portuguese_ledge:Transit:Lap:Wpt5:A.Waypoint](DEBUG): Construct Waypoint.
2019-09-23T23:04:30.194Z,1569279870.194 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="utf-8"?>
<Mission xmlns="Tethys"
        xmlns:Control="Tethys/Control"
        xmlns:Guidance="Tethys/Guidance" 
        xmlns:Units="Tethys/Units"
        xmlns:Universal="Tethys/Universal"
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                            Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                            Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd                            
                            Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                            Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd" 
        Id="portuguese_ledge">

    <Description>
        O ve좵lo nada uma vez ao redor do percurso e depois vem �uperf좩e.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:hour/><Value>4</Value></DefineArg>

    <DefineArg Name="NeedCommsTime"><Description>
        How often to surface for commumications
    </Description><Units:minute/><Value>120</Value></DefineArg>

    <DefineArg Name="AcousticContactTimeout"><Description>
        If the vehicle does not receive an acoustic signal for more than this
        length of time, it will surface for communications with shore.
    </Description><Units:minute/><Value>15</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth of flat and level flight during the mission.
    </Description><Units:meter /><Value>50</Value></DefineArg>

    <DefineArg Name="Speed"><Description>
        Speed of vehicle (relative to water) during the mission.
    </Description><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="MaxDepth"><Description>
        Maximum depth for the entire mission.
    </Description><Units:meter/><Value>60</Value></DefineArg>

    <DefineArg Name="MinOffshore"><Description>
        Minimum distance offshore for the entire mission.
    </Description><Units:kilometer/><Value>4</Value></DefineArg>

    <DefineArg Name="MinAltitude"><Description>
        Minimum height above the sea floor for the entire mission.
    </Description><Units:meter/><Value>5</Value></DefineArg>

    <DefineArg Name="MassHold"><Description>
        Set to True in order to hold mass at default position, False to allow
        mass to run on its own.
    </Description><True/></DefineArg>

    <DefineArg Name="BuoyancyHold"><Description>
        Set to True in order to hold buoyancy at neutral position, False to
        allow buoyancy to run on its own.
    </Description><True/></DefineArg>

    <DefineArg Name="Repeat"><Description>
        Number of times the vehicle should try to cycle through waypoints..
    </Description><Units:count/><Value>4</Value></DefineArg>

    <DefineArg Name="Lat1"><Description>
        Latitude of waypoint 1. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>36.695944</Value></DefineArg>

    <DefineArg Name="Lon1"><Description>
        Longitude of waypoint 1. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>-121.945120</Value></DefineArg>

    <DefineArg Name="Lat2"><Description>
        Latitude of waypoint 2. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>36.696536</Value></DefineArg>

    <DefineArg Name="Lon2"><Description>
        Longitude of waypoint 2. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>-121.937544</Value></DefineArg>

    <DefineArg Name="Lat3"><Description>
        Latitude of waypoint 3. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>36.693760</Value></DefineArg>

    <DefineArg Name="Lon3"><Description>
        Longitude of waypoint 3. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>-121.938647</Value></DefineArg>

    <DefineArg Name="Lat4"><Description>
        Latitude of waypoint 4. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>36.698094</Value></DefineArg>

    <DefineArg Name="Lon4"><Description>
        Longitude of waypoint 4. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>-121.940450</Value></DefineArg>

    <DefineArg Name="Lat5"><Description>
        Latitude of waypoint 5. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>36.695944</Value></DefineArg>

    <DefineArg Name="Lon5"><Description>
        Longitude of waypoint 5. If nan, waypoint is skipped.
    </Description><Units:degree/><Value>-121.945120</Value></DefineArg>

    <DefineArg Name="ContactLabel"><Description>
        The acoustic address of the asset to be tracked
    </Description><Units:count/><Value>0</Value></DefineArg>

    <DefineArg Name="ContactDepth"><Description>
        The acoustic address of the asset to be tracked
    </Description><Units:meter/><Value>NaN</Value></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>60</Value></DefineArg>

    <DefineArg Name="NumberOfPings"><Description>
        Number of return pings to request with each acoustic query (more than 1 will
        activate oneway mode)
    </Description><Units:count/><Value>1</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <!-- Add tracking directive high in the stack (above NeedComms to enable tracking from surface). -->

    <Insert Filename="Insert/AbortDrift.xml">
        <RedefineArg Name="AcousticTimeout"><Arg Name="AcousticContactTimeout"/></RedefineArg>
    </Insert>

    <Estimation:Tracking>
        <Parallel/>
        <Setting><Estimation:Tracking.contactDepthSetting/><Arg Name="ContactDepth"/></Setting>
        <Setting><Estimation:Tracking.contactLabelSetting/><Arg Name="ContactLabel"/></Setting>
        <Setting><Estimation:Tracking.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:Tracking.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:Tracking>

    <Insert Filename="Insert/Science.xml">
        <Description>
            Most missions will run the science sensors. If you don't place this
            aggregate above NeedComms, science instruments get turned off on the
            last upcast and while floating on the surface.
        </Description>
        <RedefineArg Name="SampleISUS"><True/></RedefineArg>
        <RedefineArg Name="PeakDetectChlActive"><True/></RedefineArg>
    </Insert>

    <Insert Filename="Insert/NeedComms.xml" Id="NeedComms"/>

    <Assign><Sequence/><Arg Name="NeedComms:DiveInterval"/><Arg Name="NeedCommsTime"/></Assign>

    <Insert Filename="Insert/StandardEnvelopes.xml"/>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinAltitude"/><Arg Name="MinAltitude"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MaxDepth"/><Arg Name="MaxDepth"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinOffshore"/><Arg Name="MinOffshore"/></Assign>

    <Guidance:Buoyancy Id="BuoyancyHold">
        <While>
            <Arg Name="BuoyancyHold"/>
        </While>
        <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyNeutral/></Setting>
    </Guidance:Buoyancy>

    <Guidance:Pitch Id="MassHold">
        <While>
            <Arg Name="MassHold"/>
        </While>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="Transit">

        <Sequence/>

        <Guidance:Pitch>
            <Parallel/>
            <Setting><Guidance:Pitch.depth/><Arg Name="Depth"/></Setting>
        </Guidance:Pitch>

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.speed/><Arg Name="Speed"/></Setting>
        </Guidance:SetSpeed>

        <Aggregate Id="Lap">

            <Sequence Repeat="Repeat"/>

            <Aggregate Id="Wpt1">

                <Sequence/>

                <Guidance:Waypoint>
                    <Sequence/>
                    <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat1"/></Setting>
                    <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon1"/></Setting>
                </Guidance:Waypoint>

            </Aggregate>

            <Aggregate Id="Wpt2">

                <Sequence/>

                <Guidance:Waypoint>
                    <Sequence/>
                    <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat2"/></Setting>
                    <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon2"/></Setting>
                </Guidance:Waypoint>

            </Aggregate>

            <Aggregate Id="Wpt3">

                <Sequence/>

                <Guidance:Waypoint>
                    <Sequence/>
                    <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat3"/></Setting>
                    <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon3"/></Setting>
                </Guidance:Waypoint>

            </Aggregate>

            <Aggregate Id="Wpt4">

                <Sequence/>

                <Guidance:Waypoint>
                    <Sequence/>
                    <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat4"/></Setting>
                    <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon4"/></Setting>
                </Guidance:Waypoint>

            </Aggregate>

            <Aggregate Id="Wpt5">

                <Sequence/>

                <Guidance:Waypoint>
                    <Sequence/>
                    <Setting><Guidance:Waypoint.latitude/><Arg Name="Lat5"/></Setting>
                    <Setting><Guidance:Waypoint.longitude/><Arg Name="Lon5"/></Setting>
                </Guidance:Waypoint>

            </Aggregate>

            <Call Id="Ligue para casa" RefId="NeedComms"/>

        </Aggregate>

    </Aggregate>

</Mission>


2019-09-23T23:04:30.196Z,1569279870.196 [CommandLine](IMPORTANT): Loaded ./Missions/Engineering/portuguese_ledge.xml
2019-09-23T23:04:36.315Z,1569279876.315 [NAL9602](INFO): SBD MO Status=0, MOMSN=1441, MT Status=0, MTMSN=0
2019-09-23T23:04:36.316Z,1569279876.316 [NAL9602](INFO): No messages in MT queue
2019-09-23T23:04:43.146Z,1569279883.146 [CommandLine](IMPORTANT): got command set portuguese_ledge.NeedCommsTime 20.000000 minute
2019-09-23T23:04:43.147Z,1569279883.147 [CommandLine](IMPORTANT): got command set portuguese_ledge.MaxDepth 30.000000 meter
2019-09-23T23:04:43.147Z,1569279883.147 [CommandLine](IMPORTANT): got command set portuguese_ledge.MinOffshore 2.000000 kilometer
2019-09-23T23:04:43.148Z,1569279883.148 [CommandLine](IMPORTANT): got command set portuguese_ledge.MinAltitude 7.000000 meter
2019-09-23T23:04:49.839Z,1569279889.839 [CommandLine](IMPORTANT): got command set portuguese_ledge.ContactLabel 5.000000 count
2019-09-23T23:04:49.840Z,1569279889.840 [CommandLine](IMPORTANT): got command set portuguese_ledge.TrackingUpdatePeriod 35.000000 second
2019-09-23T23:04:49.841Z,1569279889.841 [CommandLine](IMPORTANT): got command run 
2019-09-23T23:04:49.844Z,1569279889.844 [CommandLine](IMPORTANT): Running 
2019-09-23T23:04:50.088Z,1569279890.088 [Default] Stopped
2019-09-23T23:04:50.088Z,1569279890.088 [Default](DEBUG): Aggregate::uninitialize Default
2019-09-23T23:04:50.088Z,1569279890.088 [Default:B.GoToSurface] Stopped
2019-09-23T23:04:50.088Z,1569279890.088 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-09-23T23:04:50.088Z,1569279890.088 [Default:CheckIn] Stopped
2019-09-23T23:04:50.088Z,1569279890.088 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T23:04:50.088Z,1569279890.088 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T23:04:50.088Z,1569279890.088 [MissionManager](IMPORTANT): Started mission portuguese_ledge
2019-09-23T23:04:50.093Z,1569279890.093 [portuguese_ledge] Running Loop=1
2019-09-23T23:04:50.093Z,1569279890.093 [portuguese_ledge](DEBUG): Aggregate::initialize portuguese_ledge
2019-09-23T23:04:50.093Z,1569279890.093 [portuguese_ledge:AbortDrift] Running Loop=1
2019-09-23T23:04:50.093Z,1569279890.093 [portuguese_ledge:AbortDrift](DEBUG): Aggregate::initialize portuguese_ledge:AbortDrift
2019-09-23T23:04:50.093Z,1569279890.093 [portuguese_ledge:AbortDrift:A] Running Loop=1
2019-09-23T23:04:50.093Z,1569279890.093 [portuguese_ledge:B.] Running Loop=1
2019-09-23T23:04:50.093Z,1569279890.093 [portuguese_ledge:B.](INFO): Initializing Tracking.
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science](DEBUG): Aggregate::initialize portuguese_ledge:Science
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:A] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:B] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:C] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:D] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:E] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:F] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:G] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:H] Running Loop=1
2019-09-23T23:04:50.094Z,1569279890.094 [portuguese_ledge:Science:Read_Oil] Running Loop=1
2019-09-23T23:04:50.095Z,1569279890.095 [portuguese_ledge:Science:PeakDetectChl] Running Loop=1
2019-09-23T23:04:50.095Z,1569279890.095 [portuguese_ledge:Science:PeakDetectChl](DEBUG): Aggregate::initialize portuguese_ledge:Science:PeakDetectChl
2019-09-23T23:04:50.095Z,1569279890.095 [portuguese_ledge:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2019-09-23T23:04:50.096Z,1569279890.096 [portuguese_ledge:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-09-23T23:04:50.122Z,1569279890.122 [portuguese_ledge:Science:HighestChlPeakReport] Running Loop=1
2019-09-23T23:04:50.122Z,1569279890.122 [portuguese_ledge:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize portuguese_ledge:Science:HighestChlPeakReport
2019-09-23T23:04:50.122Z,1569279890.122 [portuguese_ledge:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2019-09-23T23:04:50.122Z,1569279890.122 [portuguese_ledge:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2019-09-23T23:04:50.123Z,1569279890.123 [portuguese_ledge:Science:PeakDetectNO3] Running Loop=1
2019-09-23T23:04:50.123Z,1569279890.123 [portuguese_ledge:Science:PeakDetectNO3](DEBUG): Aggregate::initialize portuguese_ledge:Science:PeakDetectNO3
2019-09-23T23:04:50.123Z,1569279890.123 [portuguese_ledge:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2019-09-23T23:04:50.123Z,1569279890.123 [portuguese_ledge:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-09-23T23:04:50.133Z,1569279890.133 [portuguese_ledge:Science:PeakDetectOil] Running Loop=1
2019-09-23T23:04:50.133Z,1569279890.133 [portuguese_ledge:Science:PeakDetectOil](DEBUG): Aggregate::initialize portuguese_ledge:Science:PeakDetectOil
2019-09-23T23:04:50.133Z,1569279890.133 [portuguese_ledge:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2019-09-23T23:04:50.133Z,1569279890.133 [portuguese_ledge:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-09-23T23:04:50.135Z,1569279890.135 [portuguese_ledge:Science:PeakDetectFDOM] Running Loop=1
2019-09-23T23:04:50.135Z,1569279890.135 [portuguese_ledge:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize portuguese_ledge:Science:PeakDetectFDOM
2019-09-23T23:04:50.135Z,1569279890.135 [portuguese_ledge:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2019-09-23T23:04:50.136Z,1569279890.136 [portuguese_ledge:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-09-23T23:04:50.142Z,1569279890.142 [portuguese_ledge:StandardEnvelopes] Running Loop=1
2019-09-23T23:04:50.142Z,1569279890.142 [portuguese_ledge:StandardEnvelopes](DEBUG): Aggregate::initialize portuguese_ledge:StandardEnvelopes
2019-09-23T23:04:50.142Z,1569279890.142 [portuguese_ledge:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-09-23T23:04:50.142Z,1569279890.142 [portuguese_ledge:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2019-09-23T23:04:50.142Z,1569279890.142 [portuguese_ledge:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-09-23T23:04:50.142Z,1569279890.142 [portuguese_ledge:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2019-09-23T23:04:50.143Z,1569279890.143 [portuguese_ledge:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-09-23T23:04:50.143Z,1569279890.143 [portuguese_ledge:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2019-09-23T23:04:50.143Z,1569279890.143 [portuguese_ledge:BuoyancyHold.Buoyancy] Running Loop=1
2019-09-23T23:04:50.143Z,1569279890.143 [portuguese_ledge:BuoyancyHold.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-09-23T23:04:50.143Z,1569279890.143 [portuguese_ledge:MassHold.Pitch] Running Loop=1
2019-09-23T23:04:50.143Z,1569279890.143 [portuguese_ledge:MassHold.Pitch](DEBUG): Initialize.
2019-09-23T23:04:50.143Z,1569279890.143 [portuguese_ledge:E] Running Loop=1
2019-09-23T23:04:50.144Z,1569279890.144 [portuguese_ledge:MassHold.Pitch] Running Loop=1
2019-09-23T23:04:50.144Z,1569279890.144 [portuguese_ledge:BuoyancyHold.Buoyancy] Running Loop=1
2019-09-23T23:04:50.157Z,1569279890.157 [portuguese_ledge:StandardEnvelopes] Running Loop=1
2019-09-23T23:04:50.157Z,1569279890.157 [portuguese_ledge:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-09-23T23:04:50.182Z,1569279890.182 [portuguese_ledge:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-09-23T23:04:50.183Z,1569279890.183 [portuguese_ledge:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-09-23T23:04:50.183Z,1569279890.183 [portuguese_ledge:E] Stopped
2019-09-23T23:04:50.184Z,1569279890.184 [portuguese_ledge:G] Running Loop=1
2019-09-23T23:04:50.184Z,1569279890.184 [portuguese_ledge:Science] Running Loop=1
2019-09-23T23:04:50.193Z,1569279890.193 [portuguese_ledge:Science:PeakDetectFDOM] Stopped
2019-09-23T23:04:50.193Z,1569279890.193 [portuguese_ledge:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize portuguese_ledge:Science:PeakDetectFDOM
2019-09-23T23:04:50.193Z,1569279890.193 [portuguese_ledge:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2019-09-23T23:04:50.193Z,1569279890.193 [portuguese_ledge:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectOil] Stopped
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize portuguese_ledge:Science:PeakDetectOil
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectNO3] Stopped
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize portuguese_ledge:Science:PeakDetectNO3
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:HighestChlPeakReport] Stopped
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize portuguese_ledge:Science:HighestChlPeakReport
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2019-09-23T23:04:50.194Z,1569279890.194 [portuguese_ledge:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2019-09-23T23:04:50.195Z,1569279890.195 [portuguese_ledge:Science:PeakDetectChl] Running Loop=1
2019-09-23T23:04:50.195Z,1569279890.195 [portuguese_ledge:Science:Read_Oil] Stopped
2019-09-23T23:04:50.195Z,1569279890.195 [portuguese_ledge:Science:H] Running Loop=1
2019-09-23T23:04:50.196Z,1569279890.196 [portuguese_ledge:Science:H](DEBUG): Initialize ReadDataComponent to sense WetLabsUBAT.biolum_potential
2019-09-23T23:04:50.196Z,1569279890.196 [portuguese_ledge:Science:G] Running Loop=1
2019-09-23T23:04:50.196Z,1569279890.196 [portuguese_ledge:Science:G](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T23:04:50.196Z,1569279890.196 [portuguese_ledge:Science:F] Stopped
2019-09-23T23:04:50.197Z,1569279890.197 [portuguese_ledge:Science:E] Stopped
2019-09-23T23:04:50.212Z,1569279890.212 [portuguese_ledge:Science:D] Running Loop=1
2019-09-23T23:04:50.212Z,1569279890.212 [portuguese_ledge:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_temperature
2019-09-23T23:04:50.225Z,1569279890.225 [portuguese_ledge:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_salinity
2019-09-23T23:04:50.225Z,1569279890.225 [portuguese_ledge:Science:C] Running Loop=1
2019-09-23T23:04:50.227Z,1569279890.227 [portuguese_ledge:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2019-09-23T23:04:50.228Z,1569279890.228 [portuguese_ledge:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2019-09-23T23:04:50.241Z,1569279890.241 [portuguese_ledge:Science:B] Stopped
2019-09-23T23:04:50.241Z,1569279890.241 [portuguese_ledge:Science:A] Stopped
2019-09-23T23:04:50.241Z,1569279890.241 [portuguese_ledge:B.] Running Loop=1
2019-09-23T23:04:50.241Z,1569279890.241 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:50.242Z,1569279890.242 [portuguese_ledge:AbortDrift] Running Loop=1
2019-09-23T23:04:50.242Z,1569279890.242 [portuguese_ledge:AbortDrift:A](INFO): Insert acoustic timeout set to 0.250000 h .
2019-09-23T23:04:50.243Z,1569279890.243 [portuguese_ledge:AbortDrift:A] Stopped
2019-09-23T23:04:50.243Z,1569279890.243 [portuguese_ledge:AbortDrift:B.AbortDrift] Running Loop=1
2019-09-23T23:04:50.243Z,1569279890.243 [portuguese_ledge:AbortDrift:B.AbortDrift](INFO): Initializing AbortDrift.
2019-09-23T23:04:50.244Z,1569279890.244 [portuguese_ledge:AbortDrift:B.AbortDrift](IMPORTANT): Acoustic timeout set to: 0.25 hours.
2019-09-23T23:04:50.457Z,1569279890.457 [WetLabsBB2FL](INFO): Opening uart, block timeout 10ths=2
2019-09-23T23:04:50.458Z,1569279890.458 [WetLabsBB2FL](INFO): Powering up
2019-09-23T23:04:50.523Z,1569279890.523 [portuguese_ledge:G] Stopped
2019-09-23T23:04:50.523Z,1569279890.523 [portuguese_ledge:H] Running Loop=1
2019-09-23T23:04:50.557Z,1569279890.557 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:50.558Z,1569279890.558 [portuguese_ledge:AbortDrift:B.AbortDrift](INFO): Received valid gps time fix: 1569279872.00. Resetting abort timer.
2019-09-23T23:04:50.617Z,1569279890.617 [WetLabsUBAT](INFO): Initializing
2019-09-23T23:04:50.619Z,1569279890.619 [WetLabsUBAT](INFO): readConfig(): serialNo_: UBAT0051, uartName_: /dev/ttyC1, optionalArgs_: -ldir /mnt/mmc/LRAUV/Logs/latest
2019-09-23T23:04:50.619Z,1569279890.619 [WetLabsUBAT](INFO): Powering up
2019-09-23T23:04:50.619Z,1569279890.619 [WetLabsUBAT](INFO): Checking LCM
2019-09-23T23:04:50.619Z,1569279890.619 [WetLabsUBAT](INFO): LCM OK
2019-09-23T23:04:50.624Z,1569279890.624 [WetLabsUBAT](INFO): setup() - setLineFormat()
2019-09-23T23:04:50.714Z,1569279890.714 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-09-23T23:04:50.885Z,1569279890.885 [portuguese_ledge:H] Stopped
2019-09-23T23:04:50.885Z,1569279890.885 [portuguese_ledge:I] Running Loop=1
2019-09-23T23:04:50.959Z,1569279890.959 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:51.033Z,1569279891.033 [BuoyancyServo](FAULT): Reading outside of valid range:0.000000

2019-09-23T23:04:51.033Z,1569279891.033 [BuoyancyServo](FAULT): Buoyancy engine reporting null position
2019-09-23T23:04:51.034Z,1569279891.034 [BuoyancyServo] Hardware Fault, FailCount= 1
2019-09-23T23:04:51.034Z,1569279891.034 [BuoyancyServo](ERROR): Hardware Fault
2019-09-23T23:04:51.164Z,1569279891.164 [CBIT](ERROR): Hardware Fault in component: BuoyancyServo
2019-09-23T23:04:51.321Z,1569279891.321 [portuguese_ledge:I] Stopped
2019-09-23T23:04:51.321Z,1569279891.321 [portuguese_ledge:Transit] Running Loop=1
2019-09-23T23:04:51.321Z,1569279891.321 [portuguese_ledge:Transit](DEBUG): Aggregate::initialize portuguese_ledge:Transit
2019-09-23T23:04:51.321Z,1569279891.321 [portuguese_ledge:Transit:A.Pitch] Running Loop=1
2019-09-23T23:04:51.321Z,1569279891.321 [portuguese_ledge:Transit:A.Pitch](DEBUG): Initialize.
2019-09-23T23:04:51.321Z,1569279891.321 [portuguese_ledge:Transit:B.SetSpeed] Running Loop=1
2019-09-23T23:04:51.322Z,1569279891.322 [portuguese_ledge:Transit:B.SetSpeed](DEBUG): Initialize.
2019-09-23T23:04:51.322Z,1569279891.322 [portuguese_ledge:Transit:Lap] Running Loop=1
2019-09-23T23:04:51.322Z,1569279891.322 [portuguese_ledge:Transit:Lap](DEBUG): Aggregate::initialize portuguese_ledge:Transit:Lap
2019-09-23T23:04:51.322Z,1569279891.322 [portuguese_ledge:Transit:Lap:Wpt1] Running Loop=1
2019-09-23T23:04:51.322Z,1569279891.322 [portuguese_ledge:Transit:Lap:Wpt1](DEBUG): Aggregate::initialize portuguese_ledge:Transit:Lap:Wpt1
2019-09-23T23:04:51.322Z,1569279891.322 [portuguese_ledge:Transit:Lap:Wpt1:A.Waypoint] Running Loop=1
2019-09-23T23:04:51.322Z,1569279891.322 [portuguese_ledge:Transit:Lap:Wpt1:A.Waypoint](DEBUG): Initialize WaypointComponent.
2019-09-23T23:04:51.361Z,1569279891.361 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:51.733Z,1569279891.733 [portuguese_ledge:Transit:B.SetSpeed] Running Loop=1
2019-09-23T23:04:51.733Z,1569279891.733 [portuguese_ledge:Transit:A.Pitch] Running Loop=1
2019-09-23T23:04:51.752Z,1569279891.752 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:52.168Z,1569279892.168 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:52.560Z,1569279892.560 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:52.936Z,1569279892.936 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T23:04:52.936Z,1569279892.936 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-09-23T23:04:52.986Z,1569279892.986 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:52.995Z,1569279892.995 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-09-23T23:04:52.995Z,1569279892.995 [BuoyancyServo](INFO): Powering down
2019-09-23T23:04:53.352Z,1569279893.352 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:53.676Z,1569279893.676 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190923T221050/Courier0034.lzma
2019-09-23T23:04:53.726Z,1569279893.726 [CTD_Seabird](ERROR): Failed to parse device response: <!--startlogging-->
2019-09-23T23:04:53.785Z,1569279893.785 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:53.920Z,1569279893.920 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-09-23T23:04:53.921Z,1569279893.921 [BuoyancyServo] No Fault, FailCount= 1
2019-09-23T23:04:54.163Z,1569279894.163 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:54.184Z,1569279894.184 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-09-23T23:04:54.189Z,1569279894.189 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-09-23T23:04:54.570Z,1569279894.570 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:54.988Z,1569279894.988 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:55.363Z,1569279895.363 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:55.683Z,1569279895.683 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0034.lzma.bak
2019-09-23T23:04:55.683Z,1569279895.683 [DataOverHttps](INFO): SBD MOMSN=11806432
2019-09-23T23:04:55.777Z,1569279895.777 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:56.302Z,1569279896.302 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:56.565Z,1569279896.565 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:57.033Z,1569279897.033 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:57.353Z,1569279897.353 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T23:04:57.360Z,1569279897.360 [RDI_Pathfinder](ERROR): Failed to parse:
:TS3060204,35.0, -0.1,   0.0,1448.9,  0
2019-09-23T23:04:57.381Z,1569279897.381 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:57.802Z,1569279897.802 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:58.207Z,1569279898.207 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:58.598Z,1569279898.598 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:59.053Z,1569279899.053 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:59.486Z,1569279899.486 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:04:59.858Z,1569279899.858 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:00.251Z,1569279900.251 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:00.695Z,1569279900.695 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:01.218Z,1569279901.218 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:01.499Z,1569279901.499 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:01.868Z,1569279901.868 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:02.075Z,1569279902.075 [WetLabsUBAT](INFO): Got instrument prompt
2019-09-23T23:05:02.322Z,1569279902.322 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:02.700Z,1569279902.700 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:03.108Z,1569279903.108 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:03.494Z,1569279903.494 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:03.963Z,1569279903.963 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:04.212Z,1569279904.212 [WetLabsUBAT](INFO): Got instrument prompt
2019-09-23T23:05:04.318Z,1569279904.318 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:04.692Z,1569279904.692 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:05.131Z,1569279905.131 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:05.277Z,1569279905.277 [WetLabsUBAT..StreamSerialDriver](INFO): device metadata:
Override SerialDriver::getDeviceMetadata()
2019-09-23T23:05:05.489Z,1569279905.489 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:05.899Z,1569279905.899 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:06.319Z,1569279906.319 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:06.717Z,1569279906.717 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:07.065Z,1569279907.065 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T23:05:07.142Z,1569279907.142 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:07.510Z,1569279907.510 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:07.924Z,1569279907.924 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:08.356Z,1569279908.356 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:08.751Z,1569279908.751 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:09.130Z,1569279909.130 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:09.596Z,1569279909.596 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:09.955Z,1569279909.955 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:10.382Z,1569279910.382 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:10.749Z,1569279910.749 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:11.190Z,1569279911.190 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:11.585Z,1569279911.585 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:11.998Z,1569279911.998 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:12.365Z,1569279912.365 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:12.768Z,1569279912.768 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:13.193Z,1569279913.193 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:13.590Z,1569279913.590 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:14.015Z,1569279914.015 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:14.386Z,1569279914.386 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:14.801Z,1569279914.801 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:15.233Z,1569279915.233 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:15.615Z,1569279915.615 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:16.051Z,1569279916.051 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:16.432Z,1569279916.432 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:16.823Z,1569279916.823 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:17.235Z,1569279917.235 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:17.636Z,1569279917.636 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:18.031Z,1569279918.031 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:18.466Z,1569279918.466 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:18.840Z,1569279918.840 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:19.239Z,1569279919.239 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:19.695Z,1569279919.695 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:20.055Z,1569279920.055 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:20.478Z,1569279920.478 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:20.899Z,1569279920.899 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:21.280Z,1569279921.280 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:21.684Z,1569279921.684 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:22.097Z,1569279922.097 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:22.459Z,1569279922.459 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:22.914Z,1569279922.914 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:23.299Z,1569279923.299 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:23.715Z,1569279923.715 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:24.125Z,1569279924.125 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:24.492Z,1569279924.492 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:24.948Z,1569279924.948 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:25.318Z,1569279925.318 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:25.319Z,1569279925.319 [portuguese_ledge:B.](INFO): update period (35.000000 s) has elapsed, querying...
2019-09-23T23:05:25.319Z,1569279925.319 [portuguese_ledge:B.](INFO): *** querying DAT ***
2019-09-23T23:05:25.683Z,1569279925.683 [DAT](INFO): ****** ping requested ******
2019-09-23T23:05:25.742Z,1569279925.742 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:26.114Z,1569279926.114 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:26.536Z,1569279926.536 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:26.945Z,1569279926.945 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:27.324Z,1569279927.324 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:27.738Z,1569279927.738 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:28.163Z,1569279928.163 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:28.526Z,1569279928.526 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:28.947Z,1569279928.947 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:29.359Z,1569279929.359 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:29.771Z,1569279929.771 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:30.144Z,1569279930.144 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:30.560Z,1569279930.560 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:31.033Z,1569279931.033 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:31.379Z,1569279931.379 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:31.764Z,1569279931.764 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:32.195Z,1569279932.195 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:32.594Z,1569279932.594 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:33.039Z,1569279933.039 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:33.403Z,1569279933.403 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:33.809Z,1569279933.809 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:34.261Z,1569279934.261 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:34.618Z,1569279934.618 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:35.077Z,1569279935.077 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:35.452Z,1569279935.452 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:35.881Z,1569279935.881 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:36.276Z,1569279936.276 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:36.673Z,1569279936.673 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:37.153Z,1569279937.153 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:37.448Z,1569279937.448 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:37.914Z,1569279937.914 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:38.342Z,1569279938.342 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:38.693Z,1569279938.693 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:39.109Z,1569279939.109 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:39.506Z,1569279939.506 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:39.888Z,1569279939.888 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:40.323Z,1569279940.323 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:40.718Z,1569279940.718 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:41.110Z,1569279941.110 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:41.466Z,1569279941.466 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:41.882Z,1569279941.882 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:42.305Z,1569279942.305 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:42.686Z,1569279942.686 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:43.114Z,1569279943.114 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:43.491Z,1569279943.491 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:43.510Z,1569279943.510 [DataOverHttps](IMPORTANT): SBD MTMSN=20190923T230542
2019-09-23T23:05:43.931Z,1569279943.931 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:44.324Z,1569279944.324 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:44.707Z,1569279944.707 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:45.149Z,1569279945.149 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:45.523Z,1569279945.523 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:45.959Z,1569279945.959 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:46.326Z,1569279946.326 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:46.748Z,1569279946.748 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:47.232Z,1569279947.232 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:47.580Z,1569279947.580 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:47.965Z,1569279947.965 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:48.384Z,1569279948.384 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:48.797Z,1569279948.797 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:49.218Z,1569279949.218 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:49.610Z,1569279949.610 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:49.986Z,1569279949.986 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:50.430Z,1569279950.430 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:50.784Z,1569279950.784 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:51.273Z,1569279951.273 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:51.598Z,1569279951.598 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:52.045Z,1569279952.045 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:52.379Z,1569279952.379 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:52.786Z,1569279952.786 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:53.007Z,1569279953.007 [DataOverHttps](INFO): Received command:Stop
2019-09-23T23:05:53.085Z,1569279953.085 [CommandLine](IMPORTANT): got command stop
2019-09-23T23:05:53.086Z,1569279953.086 [CommandLine](IMPORTANT): Scheduling is paused
2019-09-23T23:05:53.086Z,1569279953.086 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-09-23T23:05:53.267Z,1569279953.267 [portuguese_ledge:B.](DEBUG): Tracking...
2019-09-23T23:05:53.268Z,1569279953.268 [MissionManager](INFO): MissionManager is completed.
2019-09-23T23:05:53.268Z,1569279953.268 [MissionManager](INFO): Uninitializing Mission portuguese_ledge
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge] Stopped
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge](DEBUG): Aggregate::uninitialize portuguese_ledge
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge:AbortDrift] Stopped
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge:AbortDrift](DEBUG): Aggregate::uninitialize portuguese_ledge:AbortDrift
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge:AbortDrift:B.AbortDrift] Stopped
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge:AbortDrift:B.AbortDrift](INFO): Uninitializing AbortDrift.
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge:B.] Stopped
2019-09-23T23:05:53.268Z,1569279953.268 [portuguese_ledge:B.](DEBUG): Uninitializing Tracking.
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science] Stopped
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science](DEBUG): Aggregate::uninitialize portuguese_ledge:Science
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science:C] Stopped
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science:D] Stopped
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science:G] Stopped
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science:H] Stopped
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science:PeakDetectChl] Stopped
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize portuguese_ledge:Science:PeakDetectChl
2019-09-23T23:05:53.273Z,1569279953.273 [portuguese_ledge:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes] Stopped
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes](DEBUG): Aggregate::uninitialize portuguese_ledge:StandardEnvelopes
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes:A.AltitudeEnvelope] Stopped
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes:B.DepthEnvelope] Stopped
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize.
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes:C.OffshoreEnvelope] Stopped
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:BuoyancyHold.Buoyancy] Stopped
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:BuoyancyHold.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:MassHold.Pitch] Stopped
2019-09-23T23:05:53.274Z,1569279953.274 [portuguese_ledge:Transit] Stopped
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit](DEBUG): Aggregate::uninitialize portuguese_ledge:Transit
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:A.Pitch] Stopped
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:B.SetSpeed] Stopped
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:B.SetSpeed](DEBUG): Uninitialize.
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:Lap] Stopped
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:Lap](DEBUG): Aggregate::uninitialize portuguese_ledge:Transit:Lap
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:Lap:Wpt1] Stopped
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:Lap:Wpt1](DEBUG): Aggregate::uninitialize portuguese_ledge:Transit:Lap:Wpt1
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:Lap:Wpt1:A.Waypoint] Stopped
2019-09-23T23:05:53.275Z,1569279953.275 [portuguese_ledge:Transit:Lap:Wpt1:A.Waypoint](DEBUG): Uninitialize WaypointComponent.
2019-09-23T23:05:53.578Z,1569279953.578 [WetLabsBB2FL](INFO): Powering down
2019-09-23T23:05:53.593Z,1569279953.593 [MissionManager](IMPORTANT): Started mission Default
2019-09-23T23:05:53.593Z,1569279953.593 [Default] Running Loop=1
2019-09-23T23:05:53.593Z,1569279953.593 [Default](DEBUG): Aggregate::initialize Default
2019-09-23T23:05:53.594Z,1569279953.594 [Default:B.GoToSurface] Running Loop=1
2019-09-23T23:05:53.594Z,1569279953.594 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-09-23T23:05:53.594Z,1569279953.594 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-09-23T23:05:53.594Z,1569279953.594 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-09-23T23:05:53.594Z,1569279953.594 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-09-23T23:05:53.595Z,1569279953.595 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-09-23T23:05:53.595Z,1569279953.595 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-09-23T23:05:53.596Z,1569279953.596 [Default:A.Wait] Running Loop=1
2019-09-23T23:05:53.596Z,1569279953.596 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-09-23T23:05:54.493Z,1569279954.493 [WetLabsUBAT](INFO): Powering down
2019-09-23T23:06:06.928Z,1569279966.928 [Default:A.Wait](INFO): Done Waiting.
2019-09-23T23:06:06.929Z,1569279966.929 [Default:A.Wait] Stopped
2019-09-23T23:06:06.929Z,1569279966.929 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T23:06:07.348Z,1569279967.348 [Default:CheckIn] Running Loop=1
2019-09-23T23:06:07.348Z,1569279967.348 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T23:06:07.349Z,1569279967.349 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T23:06:08.933Z,1569279968.933 [NAL9602](DEBUG): Fix Requested
2019-09-23T23:06:09.325Z,1569279969.325 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230609.00,A,3648.38852,N,12147.41684,W,4.957,230.75,230919,,,D*78
2019-09-23T23:06:09.327Z,1569279969.327 [NAL9602](INFO): GPS fix at 20190923T230609: (36.806475, -121.790281)
2019-09-23T23:06:09.361Z,1569279969.361 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T23:06:09.361Z,1569279969.361 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T23:06:10.961Z,1569279970.961 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T23:06:17.148Z,1569279977.148 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190923T221050/Courier0037.lzma
2019-09-23T23:06:19.154Z,1569279979.154 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0037.lzma.bak
2019-09-23T23:06:19.155Z,1569279979.155 [DataOverHttps](INFO): SBD MOMSN=11806444
2019-09-23T23:06:21.842Z,1569279981.842 [NAL9602](INFO): SBD MO Status=0, MOMSN=1442, MT Status=0, MTMSN=0
2019-09-23T23:06:21.842Z,1569279981.842 [NAL9602](INFO): No messages in MT queue
2019-09-23T23:06:39.624Z,1569279999.624 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190923T221050/Courier0040.lzma
2019-09-23T23:06:41.652Z,1569280001.652 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0040.lzma.bak
2019-09-23T23:06:41.652Z,1569280001.652 [DataOverHttps](INFO): SBD MOMSN=11806447
2019-09-23T23:06:52.558Z,1569280012.558 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T23:07:02.152Z,1569280022.152 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190923T221050/Courier0043.lzma
2019-09-23T23:07:04.158Z,1569280024.158 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0043.lzma.bak
2019-09-23T23:07:04.159Z,1569280024.159 [DataOverHttps](INFO): SBD MOMSN=11806451
2019-09-23T23:07:21.601Z,1569280041.601 [DataOverHttps](INFO): Sending 312 bytes from file Logs/20190923T221050/Express0035.lzma
2019-09-23T23:07:23.606Z,1569280043.606 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0035.lzma.bak
2019-09-23T23:07:23.607Z,1569280043.607 [DataOverHttps](INFO): SBD MOMSN=11806454
2019-09-23T23:07:40.950Z,1569280060.950 [DataOverHttps](INFO): Sending 302 bytes from file Logs/20190923T221050/Express0038.lzma
2019-09-23T23:07:42.942Z,1569280062.942 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0038.lzma.bak
2019-09-23T23:07:42.943Z,1569280062.943 [DataOverHttps](INFO): SBD MOMSN=11806463
2019-09-23T23:08:00.458Z,1569280080.458 [DataOverHttps](INFO): Sending 890 bytes from file Logs/20190923T221050/Express0041.lzma
2019-09-23T23:08:02.462Z,1569280082.462 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0041.lzma.bak
2019-09-23T23:08:02.463Z,1569280082.463 [DataOverHttps](INFO): SBD MOMSN=11806477
2019-09-23T23:08:19.753Z,1569280099.753 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190923T221050/Express0044.lzma
2019-09-23T23:08:21.759Z,1569280101.759 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0044.lzma.bak
2019-09-23T23:08:21.759Z,1569280101.759 [DataOverHttps](INFO): SBD MOMSN=11806497
2019-09-23T23:08:23.496Z,1569280103.496 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T23:08:23.497Z,1569280103.497 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T23:08:23.497Z,1569280103.497 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T23:13:24.127Z,1569280404.127 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T23:13:24.127Z,1569280404.127 [Default:CheckIn:C.Wait] Stopped
2019-09-23T23:13:24.127Z,1569280404.127 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T23:13:24.128Z,1569280404.128 [Default:CheckIn:D] Running Loop=1
2019-09-23T23:13:24.501Z,1569280404.501 [Default:CheckIn:D] Stopped
2019-09-23T23:13:24.501Z,1569280404.501 [Default:CheckIn:E] Running Loop=1
2019-09-23T23:13:24.949Z,1569280404.949 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.515129 min 
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn:E] Stopped
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn] Stopped
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn](INFO): Running loop #2
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn] Running Loop=2
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T23:13:24.950Z,1569280404.950 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T23:13:26.517Z,1569280406.517 [NAL9602](DEBUG): Fix Requested
2019-09-23T23:13:26.904Z,1569280406.904 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231327.00,A,3648.24340,N,12148.28172,W,9.700,246.60,230919,,,A*7A
2019-09-23T23:13:26.906Z,1569280406.906 [NAL9602](INFO): GPS fix at 20190923T231327: (36.804057, -121.804695)
2019-09-23T23:13:26.952Z,1569280406.952 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T23:13:26.952Z,1569280406.952 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T23:13:28.922Z,1569280408.922 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T23:13:34.464Z,1569280414.464 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T221050/Courier0046.lzma
2019-09-23T23:13:36.470Z,1569280416.470 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0046.lzma.bak
2019-09-23T23:13:36.471Z,1569280416.471 [DataOverHttps](INFO): SBD MOMSN=11806541
2019-09-23T23:13:40.284Z,1569280420.284 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-09-23T23:13:40.284Z,1569280420.284 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-3276,V
2019-09-23T23:13:52.752Z,1569280432.752 [NAL9602](INFO): SBD MO Status=0, MOMSN=1443, MT Status=0, MTMSN=0
2019-09-23T23:13:52.752Z,1569280432.752 [NAL9602](INFO): No messages in MT queue
2019-09-23T23:13:58.018Z,1569280438.018 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20190923T221050/Express0047.lzma
2019-09-23T23:14:00.023Z,1569280440.023 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0047.lzma.bak
2019-09-23T23:14:00.023Z,1569280440.023 [DataOverHttps](INFO): SBD MOMSN=11806544
2019-09-23T23:14:01.284Z,1569280441.284 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T23:14:01.284Z,1569280441.284 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T23:14:01.284Z,1569280441.284 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T23:14:23.454Z,1569280463.454 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T23:19:01.844Z,1569280741.844 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T23:19:01.845Z,1569280741.845 [Default:CheckIn:C.Wait] Stopped
2019-09-23T23:19:01.845Z,1569280741.845 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T23:19:01.845Z,1569280741.845 [Default:CheckIn:D] Running Loop=1
2019-09-23T23:19:02.262Z,1569280742.262 [Default:CheckIn:D] Stopped
2019-09-23T23:19:02.262Z,1569280742.262 [Default:CheckIn:E] Running Loop=1
2019-09-23T23:19:02.660Z,1569280742.660 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.144481 min 
2019-09-23T23:19:02.661Z,1569280742.661 [Default:CheckIn:E] Stopped
2019-09-23T23:19:02.661Z,1569280742.661 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T23:19:02.661Z,1569280742.661 [Default:CheckIn] Stopped
2019-09-23T23:19:02.661Z,1569280742.661 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T23:19:02.661Z,1569280742.661 [Default:CheckIn](INFO): Running loop #3
2019-09-23T23:19:02.661Z,1569280742.661 [Default:CheckIn] Running Loop=3
2019-09-23T23:19:02.661Z,1569280742.661 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T23:19:02.662Z,1569280742.662 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T23:19:04.253Z,1569280744.253 [NAL9602](DEBUG): Fix Requested
2019-09-23T23:19:04.648Z,1569280744.648 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231904.00,A,3648.38499,N,12149.09025,W,2.022,145.51,230919,,,A*70
2019-09-23T23:19:04.650Z,1569280744.650 [NAL9602](INFO): GPS fix at 20190923T231904: (36.806416, -121.818171)
2019-09-23T23:19:04.673Z,1569280744.673 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T23:19:04.673Z,1569280744.673 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T23:19:05.869Z,1569280745.869 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-09-23T23:19:17.696Z,1569280757.696 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T221050/Courier0049.lzma
2019-09-23T23:19:19.702Z,1569280759.702 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Courier0049.lzma.bak
2019-09-23T23:19:19.703Z,1569280759.703 [DataOverHttps](INFO): SBD MOMSN=11806605
2019-09-23T23:19:23.242Z,1569280763.242 [NAL9602](INFO): SBD MO Status=0, MOMSN=1444, MT Status=0, MTMSN=0
2019-09-23T23:19:23.242Z,1569280763.242 [NAL9602](INFO): No messages in MT queue
2019-09-23T23:19:37.433Z,1569280777.433 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190923T221050/Express0050.lzma
2019-09-23T23:19:39.438Z,1569280779.438 [DataOverHttps](INFO): Moved sent file to Logs/20190923T221050/Express0050.lzma.bak
2019-09-23T23:19:39.439Z,1569280779.439 [DataOverHttps](INFO): SBD MOMSN=11806608
2019-09-23T23:19:40.692Z,1569280780.692 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T23:19:40.692Z,1569280780.692 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T23:19:40.692Z,1569280780.692 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T23:19:53.938Z,1569280793.938 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T23:20:46.401Z,1569280846.401 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-09-23T23:20:49.415Z,1569280849.415 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.249180
2019-09-23T23:21:21.541Z,1569280881.541 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-09-23T23:21:56.681Z,1569280916.681 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-09-23T23:22:47.930Z,1569280967.930 [DataOverHttps](IMPORTANT): SBD MTMSN=20190923T232247
2019-09-23T23:22:47.934Z,1569280967.934 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004253
2019-09-23T23:22:55.748Z,1569280975.748 [DataOverHttps](INFO): Received command:restart logs