2020-07-15T19:18:18.698Z,1594840698.698 [Supervisor](DEBUG): Initializing supervisor.
2020-07-15T19:18:18.701Z,1594840698.701 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2020-07-15T19:18:18.701Z,1594840698.701 [SyncHandler](INFO): Protected caller Thread ID is 819
2020-07-15T19:18:18.702Z,1594840698.702 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2020-07-15T19:18:18.703Z,1594840698.703 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2020-07-15T19:18:18.703Z,1594840698.703 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 820
2020-07-15T19:18:18.705Z,1594840698.705 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2020-07-15T19:18:18.718Z,1594840698.718 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2020-07-15T19:18:18.719Z,1594840698.719 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2020-07-15T19:18:18.719Z,1594840698.719 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 821
2020-07-15T19:18:18.720Z,1594840698.720 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2020-07-15T19:18:18.721Z,1594840698.721 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2020-07-15T19:18:18.721Z,1594840698.721 [logger ThreadHandler](INFO): Protected caller Thread ID is 822
2020-07-15T19:18:18.723Z,1594840698.723 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2020-07-15T19:18:18.723Z,1594840698.723 [Supervisor](INFO): Looking for Config files in directory: Config/
2020-07-15T19:18:18.727Z,1594840698.727 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2020-07-15T19:18:19.057Z,1594840699.057 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2020-07-15T19:18:19.058Z,1594840699.058 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2020-07-15T19:18:19.650Z,1594840699.650 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2020-07-15T19:18:19.652Z,1594840699.652 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2020-07-15T19:18:19.795Z,1594840699.795 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2020-07-15T19:18:19.797Z,1594840699.797 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2020-07-15T19:18:20.258Z,1594840700.258 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2020-07-15T19:18:20.260Z,1594840700.260 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2020-07-15T19:18:20.355Z,1594840700.355 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2020-07-15T19:18:20.357Z,1594840700.357 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2020-07-15T19:18:20.437Z,1594840700.437 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2020-07-15T19:18:20.733Z,1594840700.733 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2020-07-15T19:18:20.733Z,1594840700.733 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2020-07-15T19:18:20.878Z,1594840700.878 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2020-07-15T19:18:20.879Z,1594840700.879 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2020-07-15T19:18:20.981Z,1594840700.981 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2020-07-15T19:18:20.982Z,1594840700.982 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2020-07-15T19:18:21.180Z,1594840701.180 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2020-07-15T19:18:21.181Z,1594840701.181 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2020-07-15T19:18:21.657Z,1594840701.657 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2020-07-15T19:18:21.658Z,1594840701.658 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2020-07-15T19:18:22.080Z,1594840702.080 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2020-07-15T19:18:22.637Z,1594840702.637 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2020-07-15T19:18:22.831Z,1594840702.831 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2020-07-15T19:18:22.831Z,1594840702.831 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2020-07-15T19:18:23.022Z,1594840703.022 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2020-07-15T19:18:23.024Z,1594840703.024 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2020-07-15T19:18:23.229Z,1594840703.229 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2020-07-15T19:18:23.231Z,1594840703.231 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2020-07-15T19:18:23.454Z,1594840703.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2020-07-15T19:18:23.456Z,1594840703.456 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2020-07-15T19:18:23.460Z,1594840703.460 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2020-07-15T19:18:23.553Z,1594840703.553 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2020-07-15T19:18:23.693Z,1594840703.693 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2020-07-15T19:18:23.779Z,1594840703.779 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2020-07-15T19:18:23.863Z,1594840703.863 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2020-07-15T19:18:23.969Z,1594840703.969 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2020-07-15T19:18:24.151Z,1594840704.151 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2020-07-15T19:18:24.377Z,1594840704.377 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2020-07-15T19:18:24.378Z,1594840704.378 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2020-07-15T19:18:24.487Z,1594840704.487 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2020-07-15T19:18:24.583Z,1594840704.583 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2020-07-15T19:18:24.681Z,1594840704.681 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2020-07-15T19:18:24.774Z,1594840704.774 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2020-07-15T19:18:24.777Z,1594840704.777 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2020-07-15T19:18:24.874Z,1594840704.874 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2020-07-15T19:18:24.874Z,1594840704.874 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2020-07-15T19:18:24.904Z,1594840704.904 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2020-07-15T19:18:24.906Z,1594840704.906 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2020-07-15T19:18:24.963Z,1594840704.963 [DepthRateCalculator] Loaded
2020-07-15T19:18:24.963Z,1594840704.963 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2020-07-15T19:18:24.969Z,1594840704.969 [PitchRateCalculator] Loaded
2020-07-15T19:18:24.969Z,1594840704.969 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2020-07-15T19:18:24.984Z,1594840704.984 [SpeedCalculator] Loaded
2020-07-15T19:18:24.985Z,1594840704.985 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2020-07-15T19:18:25.006Z,1594840705.006 [TempGradientCalculator] Loaded
2020-07-15T19:18:25.006Z,1594840705.006 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2020-07-15T19:18:25.012Z,1594840705.012 [YawRateCalculator] Loaded
2020-07-15T19:18:25.012Z,1594840705.012 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2020-07-15T19:18:25.051Z,1594840705.051 [ElevatorOffsetCalculator] Loaded
2020-07-15T19:18:25.052Z,1594840705.052 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2020-07-15T19:18:25.052Z,1594840705.052 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2020-07-15T19:18:25.053Z,1594840705.053 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2020-07-15T19:18:25.116Z,1594840705.116 [VerticalControl](DEBUG): Construct VerticalControl.
2020-07-15T19:18:25.215Z,1594840705.215 [VerticalControl] Loaded
2020-07-15T19:18:25.215Z,1594840705.215 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2020-07-15T19:18:25.215Z,1594840705.215 [HorizontalControl](DEBUG): Construct HorizontalControl.
2020-07-15T19:18:25.295Z,1594840705.295 [HorizontalControl] Loaded
2020-07-15T19:18:25.296Z,1594840705.296 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2020-07-15T19:18:25.296Z,1594840705.296 [SpeedControl](DEBUG): Construct SpeedControl.
2020-07-15T19:18:25.301Z,1594840705.301 [SpeedControl] Loaded
2020-07-15T19:18:25.302Z,1594840705.302 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2020-07-15T19:18:25.302Z,1594840705.302 [LoopControl](DEBUG): Construct LoopControl.
2020-07-15T19:18:25.303Z,1594840705.303 [LoopControl] Loaded
2020-07-15T19:18:25.303Z,1594840705.303 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2020-07-15T19:18:25.303Z,1594840705.303 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2020-07-15T19:18:25.305Z,1594840705.305 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2020-07-15T19:18:25.439Z,1594840705.439 [DeadReckonUsingMultipleVelocitySources] Loaded
2020-07-15T19:18:25.440Z,1594840705.440 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2020-07-15T19:18:25.460Z,1594840705.460 [NavChart] Loaded
2020-07-15T19:18:25.460Z,1594840705.460 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2020-07-15T19:18:25.464Z,1594840705.464 [UniversalFixResidualReporter] Loaded
2020-07-15T19:18:25.464Z,1594840705.464 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2020-07-15T19:18:25.464Z,1594840705.464 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2020-07-15T19:18:25.465Z,1594840705.465 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2020-07-15T19:18:25.592Z,1594840705.592 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2020-07-15T19:18:25.593Z,1594840705.593 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2020-07-15T19:18:26.143Z,1594840706.143 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2020-07-15T19:18:26.147Z,1594840706.147 [AHRS_M2](INFO): created writer for : platform_orientation
2020-07-15T19:18:26.149Z,1594840706.149 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2020-07-15T19:18:26.154Z,1594840706.154 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2020-07-15T19:18:26.155Z,1594840706.155 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2020-07-15T19:18:26.160Z,1594840706.160 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2020-07-15T19:18:26.160Z,1594840706.160 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2020-07-15T19:18:26.166Z,1594840706.166 [AHRS_M2](INFO): created writer for : platform_roll_angle
2020-07-15T19:18:26.342Z,1594840706.342 [AHRS_M2] Loaded
2020-07-15T19:18:26.343Z,1594840706.343 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2020-07-15T19:18:26.488Z,1594840706.488 [DataOverHttps] Loaded
2020-07-15T19:18:26.489Z,1594840706.489 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2020-07-15T19:18:26.490Z,1594840706.490 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408544E0
2020-07-15T19:18:26.490Z,1594840706.490 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 904
2020-07-15T19:18:26.504Z,1594840706.504 [Depth_Keller] Loaded
2020-07-15T19:18:26.504Z,1594840706.504 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2020-07-15T19:18:26.509Z,1594840706.509 [DropWeight] Loaded
2020-07-15T19:18:26.509Z,1594840706.509 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2020-07-15T19:18:26.554Z,1594840706.554 [DVL_micro] Loaded
2020-07-15T19:18:26.554Z,1594840706.554 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2020-07-15T19:18:26.650Z,1594840706.650 [NAL9602] Loaded
2020-07-15T19:18:26.650Z,1594840706.650 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2020-07-15T19:18:26.690Z,1594840706.690 [Onboard] Loaded
2020-07-15T19:18:26.690Z,1594840706.690 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2020-07-15T19:18:26.693Z,1594840706.693 [Radio_Surface] Loaded
2020-07-15T19:18:26.694Z,1594840706.694 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2020-07-15T19:18:26.695Z,1594840706.695 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408844E0
2020-07-15T19:18:26.695Z,1594840706.695 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 905
2020-07-15T19:18:26.827Z,1594840706.827 [DAT] Loaded
2020-07-15T19:18:26.827Z,1594840706.827 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2020-07-15T19:18:28.927Z,1594840708.927 [BPC1] Loaded
2020-07-15T19:18:28.927Z,1594840708.927 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2020-07-15T19:18:28.927Z,1594840708.927 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2020-07-15T19:18:28.928Z,1594840708.928 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2020-07-15T19:18:29.056Z,1594840709.056 [BuoyancyServo] Loaded
2020-07-15T19:18:29.057Z,1594840709.057 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2020-07-15T19:18:29.068Z,1594840709.068 [ElevatorServo] Loaded
2020-07-15T19:18:29.068Z,1594840709.068 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2020-07-15T19:18:29.079Z,1594840709.079 [MassServo] Loaded
2020-07-15T19:18:29.079Z,1594840709.079 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2020-07-15T19:18:29.091Z,1594840709.091 [RudderServo] Loaded
2020-07-15T19:18:29.091Z,1594840709.091 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2020-07-15T19:18:29.101Z,1594840709.101 [ThrusterServo] Loaded
2020-07-15T19:18:29.101Z,1594840709.101 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2020-07-15T19:18:29.102Z,1594840709.102 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2020-07-15T19:18:29.102Z,1594840709.102 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2020-07-15T19:18:29.227Z,1594840709.227 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2020-07-15T19:18:29.228Z,1594840709.228 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2020-07-15T19:18:29.269Z,1594840709.269 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2020-07-15T19:18:29.270Z,1594840709.270 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2020-07-15T19:18:29.605Z,1594840709.605 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2020-07-15T19:18:29.606Z,1594840709.606 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2020-07-15T19:18:29.874Z,1594840709.874 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2020-07-15T19:18:29.879Z,1594840709.879 [CTD_Seabird](INFO): created writer for : sea_water_density
2020-07-15T19:18:29.880Z,1594840709.880 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2020-07-15T19:18:29.884Z,1594840709.884 [CTD_Seabird](INFO): created writer for : depth
2020-07-15T19:18:29.885Z,1594840709.885 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2020-07-15T19:18:29.890Z,1594840709.890 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2020-07-15T19:18:29.890Z,1594840709.890 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2020-07-15T19:18:29.896Z,1594840709.896 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2020-07-15T19:18:29.896Z,1594840709.896 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2020-07-15T19:18:29.901Z,1594840709.901 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2020-07-15T19:18:29.902Z,1594840709.902 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2020-07-15T19:18:29.907Z,1594840709.907 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2020-07-15T19:18:29.908Z,1594840709.908 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2020-07-15T19:18:29.913Z,1594840709.913 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2020-07-15T19:18:29.940Z,1594840709.940 [CTD_Seabird] Loaded
2020-07-15T19:18:29.940Z,1594840709.940 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2020-07-15T19:18:29.941Z,1594840709.941 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A904E0
2020-07-15T19:18:29.942Z,1594840709.942 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 906
2020-07-15T19:18:29.956Z,1594840709.956 [PAR_Licor] Loaded
2020-07-15T19:18:29.957Z,1594840709.957 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2020-07-15T19:18:29.963Z,1594840709.963 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470
2020-07-15T19:18:29.963Z,1594840709.963 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470
2020-07-15T19:18:29.967Z,1594840709.967 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650
2020-07-15T19:18:29.967Z,1594840709.967 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650
2020-07-15T19:18:29.971Z,1594840709.971 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl
2020-07-15T19:18:29.972Z,1594840709.972 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl
2020-07-15T19:18:29.976Z,1594840709.976 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm
2020-07-15T19:18:29.976Z,1594840709.976 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm
2020-07-15T19:18:29.980Z,1594840709.980 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm
2020-07-15T19:18:29.980Z,1594840709.980 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm
2020-07-15T19:18:29.985Z,1594840709.985 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm
2020-07-15T19:18:29.985Z,1594840709.985 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm
2020-07-15T19:18:29.989Z,1594840709.989 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm
2020-07-15T19:18:29.989Z,1594840709.989 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm
2020-07-15T19:18:29.994Z,1594840709.994 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:29.998Z,1594840709.998 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:29.999Z,1594840709.999 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:29.999Z,1594840709.999 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:30.003Z,1594840710.003 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:30.003Z,1594840710.003 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:30.007Z,1594840710.007 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:30.008Z,1594840710.008 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T19:18:30.012Z,1594840710.012 [WetLabsBB2FL] Loaded
2020-07-15T19:18:30.012Z,1594840710.012 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2020-07-15T19:18:30.013Z,1594840710.013 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40AC04E0
2020-07-15T19:18:30.013Z,1594840710.013 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 907
2020-07-15T19:18:30.014Z,1594840710.014 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2020-07-15T19:18:30.016Z,1594840710.016 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2020-07-15T19:18:30.177Z,1594840710.177 [SBIT](DEBUG): Construct Startup Built In Test.
2020-07-15T19:18:30.188Z,1594840710.188 [SBIT] Loaded
2020-07-15T19:18:30.188Z,1594840710.188 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2020-07-15T19:18:30.189Z,1594840710.189 [IBIT](DEBUG): Construct Initiated Built In Test.
2020-07-15T19:18:30.201Z,1594840710.201 [IBIT] Loaded
2020-07-15T19:18:30.201Z,1594840710.201 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2020-07-15T19:18:30.205Z,1594840710.205 [CBIT](DEBUG): Construct Continuous Built In Test.
2020-07-15T19:18:30.342Z,1594840710.342 [CBIT] Loaded
2020-07-15T19:18:30.342Z,1594840710.342 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2020-07-15T19:18:30.342Z,1594840710.342 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2020-07-15T19:18:30.346Z,1594840710.346 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2020-07-15T19:18:30.347Z,1594840710.347 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2020-07-15T19:18:30.353Z,1594840710.353 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2020-07-15T19:18:30.354Z,1594840710.354 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B2B4E0
2020-07-15T19:18:30.355Z,1594840710.355 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 908
2020-07-15T19:18:30.359Z,1594840710.359 [Supervisor](INFO): Main Thread ID is 815
2020-07-15T19:18:30.359Z,1594840710.359 [Supervisor](DEBUG): Running supervisor.
2020-07-15T19:18:30.360Z,1594840710.360 [CommandLine ThreadHandler](INFO): Handler Thread ID is 909
2020-07-15T19:18:30.362Z,1594840710.362 [controlThread ThreadHandler](INFO): Handler Thread ID is 910
2020-07-15T19:18:30.363Z,1594840710.363 [controlThread](DEBUG): Initializing ControlThread
2020-07-15T19:18:30.363Z,1594840710.363 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2020-07-15T19:18:30.364Z,1594840710.364 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2020-07-15T19:18:30.364Z,1594840710.364 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2020-07-15T19:18:30.364Z,1594840710.364 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2020-07-15T19:18:30.365Z,1594840710.365 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2020-07-15T19:18:30.365Z,1594840710.365 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2020-07-15T19:18:30.366Z,1594840710.366 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2020-07-15T19:18:30.368Z,1594840710.368 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2020-07-15T19:18:30.368Z,1594840710.368 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2020-07-15T19:18:30.369Z,1594840710.369 [LoopControl](DEBUG): Initialize LoopControlComponent.
2020-07-15T19:18:30.369Z,1594840710.369 [NavChart](DEBUG): Initialize NavChart Navigation.
2020-07-15T19:18:30.370Z,1594840710.370 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2020-07-15T19:18:30.377Z,1594840710.377 [SBIT](INFO): Initialize SBIT Component.
2020-07-15T19:18:30.378Z,1594840710.378 [SBIT](IMPORTANT): git: 2020-06-09
2020-07-15T19:18:30.378Z,1594840710.378 [SBIT](INFO): git hash: 492c82351796d8646f9bb5d9c938bbc9efa48549
2020-07-15T19:18:30.378Z,1594840710.378 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2020-07-15T19:18:30.378Z,1594840710.378 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Tue Sep 24 11:12:27 PDT 2019
2020-07-15T19:18:30.379Z,1594840710.379 [SBIT](INFO): Beginning SBIT in 59.000000 seconds.
2020-07-15T19:18:30.380Z,1594840710.380 [IBIT](INFO): Initialize IBIT Component.
2020-07-15T19:18:30.381Z,1594840710.381 [CBIT](DEBUG): Initialize CBIT Component.
2020-07-15T19:18:30.382Z,1594840710.382 [logger ThreadHandler](INFO): Handler Thread ID is 911
2020-07-15T19:18:30.393Z,1594840710.393 [CBIT](DEBUG): Initialized mux pins.
2020-07-15T19:18:30.393Z,1594840710.393 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2020-07-15T19:18:30.393Z,1594840710.393 [CBIT](DEBUG): Initializing the watchdog timer.
2020-07-15T19:18:30.401Z,1594840710.401 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 912
2020-07-15T19:18:30.402Z,1594840710.402 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2020-07-15T19:18:30.413Z,1594840710.413 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 913
2020-07-15T19:18:30.417Z,1594840710.417 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2020-07-15T19:18:30.417Z,1594840710.417 [CBIT](DEBUG): Initializing heartbeat.
2020-07-15T19:18:30.425Z,1594840710.425 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 914
2020-07-15T19:18:30.426Z,1594840710.426 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2020-07-15T19:18:30.430Z,1594840710.430 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 916
2020-07-15T19:18:30.431Z,1594840710.431 [WetLabsBB2FL](INFO): Powering down
2020-07-15T19:18:30.489Z,1594840710.489 [CBIT](DEBUG): Deactivating GF circuits.
2020-07-15T19:18:30.489Z,1594840710.489 [CBIT](DEBUG): Deactivating emergency mode.
2020-07-15T19:18:30.543Z,1594840710.543 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 917
2020-07-15T19:18:30.544Z,1594840710.544 [CBIT](DEBUG): Backplane powered.
2020-07-15T19:18:30.550Z,1594840710.550 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2020-07-15T19:18:30.648Z,1594840710.648 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2020-07-15T19:18:30.648Z,1594840710.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2020-07-15T19:18:30.648Z,1594840710.648 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2020-07-15T19:18:30.649Z,1594840710.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2020-07-15T19:18:30.649Z,1594840710.649 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2020-07-15T19:18:30.649Z,1594840710.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2020-07-15T19:18:30.649Z,1594840710.649 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2020-07-15T19:18:30.649Z,1594840710.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2020-07-15T19:18:30.649Z,1594840710.649 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2020-07-15T19:18:30.650Z,1594840710.650 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2020-07-15T19:18:30.650Z,1594840710.650 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2020-07-15T19:18:30.650Z,1594840710.650 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2020-07-15T19:18:30.650Z,1594840710.650 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2020-07-15T19:18:30.650Z,1594840710.650 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2020-07-15T19:18:30.650Z,1594840710.650 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2020-07-15T19:18:30.651Z,1594840710.651 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2020-07-15T19:18:30.679Z,1594840710.679 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2020-07-15T19:18:30.761Z,1594840710.761 [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>


2020-07-15T19:18:30.762Z,1594840710.762 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2020-07-15T19:18:30.817Z,1594840710.817 [Radio_Surface](INFO): Powering up
2020-07-15T19:18:30.890Z,1594840710.890 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2020-07-15T19:18:30.891Z,1594840710.891 [Default:A.Wait](DEBUG): Construct Wait.
2020-07-15T19:18:30.892Z,1594840710.892 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2020-07-15T19:18:30.915Z,1594840710.915 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2020-07-15T19:18:30.934Z,1594840710.934 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2020-07-15T19:18:30.940Z,1594840710.940 [Default:E.Execute](DEBUG): Construct Execute.
2020-07-15T19:18:30.959Z,1594840710.959 [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>


2020-07-15T19:18:30.964Z,1594840710.964 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2020-07-15T19:18:30.973Z,1594840710.973 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2020-07-15T19:18:31.211Z,1594840711.211 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2020-07-15T19:18:31.211Z,1594840711.211 [DAT](INFO): Powering up
2020-07-15T19:18:31.211Z,1594840711.211 [DAT](DEBUG): Initializing DAT.
2020-07-15T19:18:31.262Z,1594840711.262 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2020-07-15T19:18:31.395Z,1594840711.395 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-07-15T19:18:31.401Z,1594840711.401 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-07-15T19:18:31.402Z,1594840711.402 [ElevatorServo](DEBUG): Initializing EZServoServo.
2020-07-15T19:18:31.409Z,1594840711.409 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2020-07-15T19:18:31.410Z,1594840711.410 [MassServo](DEBUG): Initializing EZServoServo.
2020-07-15T19:18:31.417Z,1594840711.417 [MassServo](DEBUG): Initializing MassServo.
2020-07-15T19:18:31.418Z,1594840711.418 [RudderServo](DEBUG): Initializing EZServoServo.
2020-07-15T19:18:31.425Z,1594840711.425 [RudderServo](DEBUG): Initializing RudderServo.
2020-07-15T19:18:31.426Z,1594840711.426 [ThrusterServo](DEBUG): Initializing EZServoServo.
2020-07-15T19:18:31.433Z,1594840711.433 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2020-07-15T19:18:45.207Z,1594840725.207 [DAT](INFO): commRate: 800
2020-07-15T19:18:45.207Z,1594840725.207 [DAT](INFO): commRate: 800
2020-07-15T19:18:45.610Z,1594840725.610 [DAT](INFO): entering command mode
2020-07-15T19:18:46.088Z,1594840726.088 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:46.424Z,1594840726.424 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:46.821Z,1594840726.821 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0000.00,000.00
2020-07-15T19:18:46.837Z,1594840726.837 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:47.225Z,1594840727.225 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:47.629Z,1594840727.629 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:48.041Z,1594840728.041 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:48.438Z,1594840728.438 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:48.849Z,1594840728.849 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:49.246Z,1594840729.246 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:49.649Z,1594840729.649 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:50.053Z,1594840730.053 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:50.465Z,1594840730.465 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:50.872Z,1594840730.872 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:51.266Z,1594840731.266 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:51.670Z,1594840731.670 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:52.073Z,1594840732.073 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:52.502Z,1594840732.502 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:52.877Z,1594840732.877 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:53.285Z,1594840733.285 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:53.694Z,1594840733.694 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:54.098Z,1594840734.098 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:54.525Z,1594840734.525 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:54.901Z,1594840734.901 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:55.306Z,1594840735.306 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:55.713Z,1594840735.713 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:56.109Z,1594840736.109 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:56.527Z,1594840736.527 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:56.907Z,1594840736.907 [NAL9602](INFO): Powering up NAL9602
2020-07-15T19:18:56.922Z,1594840736.922 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:57.332Z,1594840737.332 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:57.736Z,1594840737.736 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:58.130Z,1594840738.130 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:58.555Z,1594840738.555 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:58.945Z,1594840738.945 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:59.347Z,1594840739.347 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:18:59.745Z,1594840739.745 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:19:00.153Z,1594840740.153 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:19:00.574Z,1594840740.574 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:19:00.979Z,1594840740.979 [DAT](DEBUG): checking for command mode acknowledgment
2020-07-15T19:19:00.979Z,1594840740.979 [DAT](FAULT): failed to enter command mode
2020-07-15T19:19:01.362Z,1594840741.362 [DAT](INFO): entering command mode
2020-07-15T19:19:01.766Z,1594840741.766 [DAT](INFO): setting verbose to 3
2020-07-15T19:19:02.178Z,1594840742.178 [DAT](INFO): set verbose to 3
2020-07-15T19:19:02.178Z,1594840742.178 [DAT](INFO): setting DatVerbose to 27440
2020-07-15T19:19:02.594Z,1594840742.594 [DAT](INFO): set DatVerbose to 27440
2020-07-15T19:19:02.594Z,1594840742.594 [DAT](INFO): setting transmit power to 8
2020-07-15T19:19:02.978Z,1594840742.978 [DAT](INFO): set transmit power to 8
2020-07-15T19:19:02.979Z,1594840742.979 [DAT](INFO): setting local address to 8
2020-07-15T19:19:03.382Z,1594840743.382 [DAT](INFO): set local address to 8
2020-07-15T19:19:07.811Z,1594840747.811 [NAL9602](INFO): NAL9602 initialized
2020-07-15T19:19:30.076Z,1594840770.076 [SBIT](IMPORTANT): Beginning Startup BIT
2020-07-15T19:19:30.080Z,1594840770.080 [CBIT](IMPORTANT): Beginning ground fault scan
2020-07-15T19:19:41.130Z,1594840781.130 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.003459
CHAN A1 (24V): -0.001652
CHAN A2 (12V): -0.000514
CHAN A3 (5V): 0.000846
CHAN B0 (3.3V): 0.000024
CHAN B1 (3.15aV): 0.000232
CHAN B2 (3.15bV): 0.000109
CHAN B3 (GND): 0.000114
OPEN: 0.002693
Full Scale Calc: 4.765 mA, -1.589 mA
2020-07-15T19:19:54.541Z,1594840794.541 [DVL_micro](ERROR): Failed to parse:
:WI,-00600,+00000,+00000,+00000,I
2020-07-15T19:20:18.094Z,1594840818.094 [DVL_micro](ERROR): Failed to parse:
0.35,+0001.62,+0000.23,+0000.13
2020-07-15T19:20:23.380Z,1594840823.380 [SBIT](IMPORTANT): SBIT PASSED
2020-07-15T19:20:23.380Z,1594840823.380 [SBIT](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2020-07-15T19:20:23.761Z,1594840823.761 [MissionManager](IMPORTANT): Started mission Startup
2020-07-15T19:20:23.761Z,1594840823.761 [Startup] Running Loop=1
2020-07-15T19:20:23.762Z,1594840823.762 [Startup](DEBUG): Aggregate::initialize Startup
2020-07-15T19:20:23.762Z,1594840823.762 [Startup:A.GoToSurface] Running Loop=1
2020-07-15T19:20:23.762Z,1594840823.762 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-07-15T19:20:23.762Z,1594840823.762 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-07-15T19:20:23.763Z,1594840823.763 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-07-15T19:20:23.763Z,1594840823.763 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-07-15T19:20:23.764Z,1594840823.764 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-07-15T19:20:23.764Z,1594840823.764 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-07-15T19:20:23.765Z,1594840823.765 [Startup:StartupSatComms] Running Loop=1
2020-07-15T19:20:23.766Z,1594840823.766 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2020-07-15T19:20:23.766Z,1594840823.766 [Startup:StartupSatComms:A] Running Loop=1
2020-07-15T19:20:24.194Z,1594840824.194 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2020-07-15T19:20:46.361Z,1594840846.361 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T19:21:15.866Z,1594840875.866 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:21:15.866Z,1594840875.866 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35,0000.0,1489.0,000
2020-07-15T19:21:23.970Z,1594840883.970 [Startup:StartupSatComms:A](INFO): Timed out from 2020-07-15T19:20:23.8Z
2020-07-15T19:21:23.970Z,1594840883.970 [Startup:StartupSatComms:A] Stopped
2020-07-15T19:21:23.970Z,1594840883.970 [Startup:StartupSatComms:B] Running Loop=1
2020-07-15T19:21:24.376Z,1594840884.376 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-07-15T19:21:30.462Z,1594840890.462 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2020-07-15T19:21:30.462Z,1594840890.462 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2020-07-15T19:21:30.485Z,1594840890.485 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2020-07-15T19:21:30.854Z,1594840890.854 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2020-07-15T19:21:30.854Z,1594840890.854 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2020-07-15T19:21:34.911Z,1594840894.911 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004738
2020-07-15T19:21:42.221Z,1594840902.221 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20200715T145630/Courier0064.lzma
2020-07-15T19:21:43.223Z,1594840903.223 [DataOverHttps](INFO): Moved sent file to Logs/20200715T145630/Courier0064.lzma.bak
2020-07-15T19:21:43.223Z,1594840903.223 [DataOverHttps](INFO): SBD MOMSN=12442262
2020-07-15T19:21:59.029Z,1594840919.029 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20200715T191818/Courier0000.lzma
2020-07-15T19:22:00.030Z,1594840920.030 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0000.lzma.bak
2020-07-15T19:22:00.031Z,1594840920.031 [DataOverHttps](INFO): SBD MOMSN=12442264
2020-07-15T19:22:12.006Z,1594840932.006 [DVL_micro](ERROR): Failed to parse:
00,+0000,+00000,I
2020-07-15T19:22:16.168Z,1594840936.168 [DataOverHttps](INFO): Sending 1559 bytes from file Logs/20200715T145630/Express0062.lzma
2020-07-15T19:22:17.167Z,1594840937.167 [DataOverHttps](INFO): Moved sent file to Logs/20200715T145630/Express0062.lzma.bak
2020-07-15T19:22:17.167Z,1594840937.167 [DataOverHttps](INFO): SBD MOMSN=12442267
2020-07-15T19:22:24.158Z,1594840944.158 [Startup:StartupSatComms:B](INFO): Timed out from 2020-07-15T19:21:23.0Z
2020-07-15T19:22:24.158Z,1594840944.158 [Startup:StartupSatComms:B] Stopped
2020-07-15T19:22:24.159Z,1594840944.159 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2020-07-15T19:22:24.159Z,1594840944.159 [Startup:StartupSatComms] Stopped
2020-07-15T19:22:24.159Z,1594840944.159 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2020-07-15T19:22:24.159Z,1594840944.159 [Startup](INFO): Completed Startup
2020-07-15T19:22:24.160Z,1594840944.160 [MissionManager](INFO): Startup is completed.
2020-07-15T19:22:24.160Z,1594840944.160 [MissionManager](INFO): Uninitializing Mission Startup
2020-07-15T19:22:24.160Z,1594840944.160 [Startup] Stopped
2020-07-15T19:22:24.160Z,1594840944.160 [Startup](DEBUG): Aggregate::uninitialize Startup
2020-07-15T19:22:24.160Z,1594840944.160 [Startup:A.GoToSurface] Stopped
2020-07-15T19:22:24.160Z,1594840944.160 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-07-15T19:22:24.555Z,1594840944.555 [MissionManager](IMPORTANT): Started mission Default
2020-07-15T19:22:24.555Z,1594840944.555 [Default] Running Loop=1
2020-07-15T19:22:24.555Z,1594840944.555 [Default](DEBUG): Aggregate::initialize Default
2020-07-15T19:22:24.555Z,1594840944.555 [Default:B.GoToSurface] Running Loop=1
2020-07-15T19:22:24.555Z,1594840944.555 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-07-15T19:22:24.555Z,1594840944.555 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-07-15T19:22:24.556Z,1594840944.556 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-07-15T19:22:24.556Z,1594840944.556 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-07-15T19:22:24.556Z,1594840944.556 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-07-15T19:22:24.557Z,1594840944.557 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-07-15T19:22:24.557Z,1594840944.557 [Default:A.Wait] Running Loop=1
2020-07-15T19:22:24.557Z,1594840944.557 [Default:A.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:22:33.016Z,1594840953.016 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20200715T145630/Express0065.lzma
2020-07-15T19:22:34.019Z,1594840954.019 [DataOverHttps](INFO): Moved sent file to Logs/20200715T145630/Express0065.lzma.bak
2020-07-15T19:22:34.019Z,1594840954.019 [DataOverHttps](INFO): SBD MOMSN=12442294
2020-07-15T19:22:37.927Z,1594840957.927 [Default:A.Wait](INFO): Done Waiting.
2020-07-15T19:22:37.927Z,1594840957.927 [Default:A.Wait] Stopped
2020-07-15T19:22:37.927Z,1594840957.927 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T19:22:38.295Z,1594840958.295 [Default:CheckIn] Running Loop=1
2020-07-15T19:22:38.296Z,1594840958.296 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T19:22:38.296Z,1594840958.296 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T19:22:38.696Z,1594840958.696 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-07-15T19:23:13.423Z,1594840993.423 [DVL_micro](ERROR): Failed to parse:
:BI,+00000,+00000,+00000,+00000,I
2020-07-15T19:23:43.321Z,1594841023.321 [DVL_micro](ERROR): Failed to parse:
:R35,+0000.42,+0000.23,+0000.13
2020-07-15T19:24:09.564Z,1594841049.564 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:24:09.565Z,1594841049.565 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,489.0,000
2020-07-15T19:24:10.779Z,1594841050.779 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T19:24:17.645Z,1594841057.645 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191928.00,A,3648.16397,N,12147.27907,W,0.117,231.91,150720,,,A*71
2020-07-15T19:24:17.648Z,1594841057.648 [NAL9602](INFO): GPS fix at 20200715T191928: (36.802733, -121.787984)
2020-07-15T19:24:17.716Z,1594841057.716 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T19:24:17.716Z,1594841057.716 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T19:24:18.108Z,1594841058.108 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-07-15T19:24:19.193Z,1594841059.193 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20200715T191818/Courier0004.lzma
2020-07-15T19:24:20.066Z,1594841060.066 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0004.lzma.bak
2020-07-15T19:24:20.067Z,1594841060.067 [DataOverHttps](INFO): SBD MOMSN=12442296
2020-07-15T19:24:39.398Z,1594841079.398 [DataOverHttps](INFO): Sending 733 bytes from file Logs/20200715T191818/Express0001.lzma
2020-07-15T19:24:40.398Z,1594841080.398 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0001.lzma.bak
2020-07-15T19:24:40.399Z,1594841080.399 [DataOverHttps](INFO): SBD MOMSN=12442299
2020-07-15T19:24:49.806Z,1594841089.806 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T19:24:51.972Z,1594841091.972 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2020-07-15T19:24:56.753Z,1594841096.753 [DataOverHttps](INFO): Sending 322 bytes from file Logs/20200715T191818/Express0005.lzma
2020-07-15T19:24:57.129Z,1594841097.129 [BPC1](ERROR): Battery stick #6 (s/n: 00CA) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2020-07-15T19:24:57.130Z,1594841097.130 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 6.
2020-07-15T19:24:57.137Z,1594841097.137 [BPC1](INFO): Received data from all battery sticks.
2020-07-15T19:24:57.480Z,1594841097.480 [DVL_micro](ERROR): Failed to parse:
0000000000,35.0,+17.0,0000.0,1489.0,000
2020-07-15T19:24:57.754Z,1594841097.754 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0005.lzma.bak
2020-07-15T19:24:57.755Z,1594841097.755 [DataOverHttps](INFO): SBD MOMSN=12442314
2020-07-15T19:24:59.151Z,1594841099.151 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T19:24:59.151Z,1594841099.151 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T19:24:59.151Z,1594841099.151 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:25:25.363Z,1594841125.363 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2020-07-15T19:25:51.229Z,1594841151.229 [DVL_micro](ERROR): Failed to parse:
:0,+00000,+00000,+00000,I
2020-07-15T19:26:44.944Z,1594841204.944 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+17.0,0000.0,1489.0,000
2020-07-15T19:27:10.810Z,1594841230.810 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:27:10.810Z,1594841230.810 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.34,+0001.59,+00010.78
2020-07-15T19:27:28.585Z,1594841248.585 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:27:28.585Z,1594841248.585 [DVL_micro](ERROR): Failed to parse:
:TS,000000035.0,+17.0,000.0,000
2020-07-15T19:27:58.477Z,1594841278.477 [DVL_micro](ERROR): only read 2 of 4 data items
2020-07-15T19:27:58.477Z,1594841278.477 [DVL_micro](ERROR): Failed to parse:
:RD,+00001.54,+00000.13
2020-07-15T19:28:38.077Z,1594841318.077 [DVL_micro](ERROR): Failed to parse:00.34,+0010.67,+0000.34,+0010.70
2020-07-15T19:29:00.288Z,1594841340.288 [DVL_micro](ERROR): Failed to parse:
:000000000,35.0,+17.0,0000.0,1489.0,000
2020-07-15T19:29:20.085Z,1594841360.085 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T19:29:59.725Z,1594841399.725 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T19:29:59.725Z,1594841399.725 [Default:CheckIn:C.Wait] Stopped
2020-07-15T19:29:59.725Z,1594841399.725 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T19:29:59.725Z,1594841399.725 [Default:CheckIn:D] Running Loop=1
2020-07-15T19:30:00.118Z,1594841400.118 [Default:CheckIn:D] Stopped
2020-07-15T19:30:00.118Z,1594841400.118 [Default:CheckIn:E] Running Loop=1
2020-07-15T19:30:00.510Z,1594841400.510 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.592721 min 
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn:E] Stopped
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn] Stopped
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn](INFO): Running loop #2
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn] Running Loop=2
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T19:30:00.511Z,1594841400.511 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T19:30:02.509Z,1594841402.509 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192514.00,A,3648.16518,N,12147.28157,W,0.078,280.65,150720,,,A*7B
2020-07-15T19:30:02.512Z,1594841402.512 [NAL9602](INFO): GPS fix at 20200715T192514: (36.802753, -121.788026)
2020-07-15T19:30:02.541Z,1594841402.541 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T19:30:02.541Z,1594841402.541 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T19:30:10.109Z,1594841410.109 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20200715T191818/Courier0007.lzma
2020-07-15T19:30:11.110Z,1594841411.110 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0007.lzma.bak
2020-07-15T19:30:11.111Z,1594841411.111 [DataOverHttps](INFO): SBD MOMSN=12442327
2020-07-15T19:30:19.881Z,1594841419.881 [DVL_micro](ERROR): only read 1 of 4 data items
2020-07-15T19:30:19.881Z,1594841419.881 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,,+0000.23,
2020-07-15T19:30:27.685Z,1594841427.685 [DataOverHttps](INFO): Sending 160 bytes from file Logs/20200715T191818/Express0008.lzma
2020-07-15T19:30:28.687Z,1594841428.687 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0008.lzma.bak
2020-07-15T19:30:28.687Z,1594841428.687 [DataOverHttps](INFO): SBD MOMSN=12442330
2020-07-15T19:30:30.009Z,1594841430.009 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T19:30:30.009Z,1594841430.009 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T19:30:30.009Z,1594841430.009 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:30:33.202Z,1594841433.202 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-07-15T19:30:33.277Z,1594841433.277 [NAL9602](FAULT): received: 
+CSQ:0

OK
2020-07-15T19:30:33.277Z,1594841433.277 [NAL9602] Data Fault, FailCount= 1
2020-07-15T19:30:33.277Z,1594841433.277 [NAL9602](ERROR): Data Fault
2020-07-15T19:30:33.361Z,1594841433.361 [CBIT](ERROR): Data Fault in component: NAL9602
2020-07-15T19:30:33.620Z,1594841433.620 [NAL9602](INFO): Powering down
2020-07-15T19:30:34.498Z,1594841434.498 [CBIT](INFO): Clearing failed state for component NAL9602
2020-07-15T19:30:34.498Z,1594841434.498 [NAL9602] No Fault, FailCount= 1
2020-07-15T19:31:03.908Z,1594841463.908 [NAL9602](INFO): Powering up NAL9602
2020-07-15T19:31:14.819Z,1594841474.819 [NAL9602](INFO): NAL9602 initialized
2020-07-15T19:31:17.652Z,1594841477.652 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:31:17.653Z,1594841477.653 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,+00000.23,+0000.13
2020-07-15T19:31:45.926Z,1594841505.926 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T19:31:47.552Z,1594841507.552 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:31:47.553Z,1594841507.553 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,+00000.23,+0000.13
2020-07-15T19:32:27.546Z,1594841547.546 [DVL_micro](ERROR): Failed to parse:
0000000000,35.0,+17.1,0000.0,1489.0,000
2020-07-15T19:33:13.196Z,1594841593.196 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:33:13.196Z,1594841593.196 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,+00000.23,+0000.13
2020-07-15T19:34:17.033Z,1594841657.033 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:34:17.033Z,1594841657.033 [DVL_micro](ERROR): Failed to parse:
:BI,-04899,+00055,00000,A
2020-07-15T19:34:21.068Z,1594841661.068 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:34:21.068Z,1594841661.068 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2020-07-15T19:35:30.571Z,1594841730.571 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T19:35:30.571Z,1594841730.571 [Default:CheckIn:C.Wait] Stopped
2020-07-15T19:35:30.571Z,1594841730.571 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T19:35:30.571Z,1594841730.571 [Default:CheckIn:D] Running Loop=1
2020-07-15T19:35:30.991Z,1594841730.991 [Default:CheckIn:D] Stopped
2020-07-15T19:35:30.991Z,1594841730.991 [Default:CheckIn:E] Running Loop=1
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.107267 min 
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn:E] Stopped
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn] Stopped
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn](INFO): Running loop #3
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn] Running Loop=3
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T19:35:31.402Z,1594841731.402 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T19:35:35.812Z,1594841735.812 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T19:36:21.453Z,1594841781.453 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193132.00,A,3648.16487,N,12147.29043,W,0.467,154.90,150720,,,A*72
2020-07-15T19:36:21.455Z,1594841781.455 [NAL9602](INFO): GPS fix at 20200715T193132: (36.802748, -121.788174)
2020-07-15T19:36:21.480Z,1594841781.480 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T19:36:21.480Z,1594841781.480 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T19:36:29.008Z,1594841789.008 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200715T191818/Courier0010.lzma
2020-07-15T19:36:30.010Z,1594841790.010 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0010.lzma.bak
2020-07-15T19:36:30.011Z,1594841790.011 [DataOverHttps](INFO): SBD MOMSN=12442333
2020-07-15T19:36:46.213Z,1594841806.213 [DataOverHttps](INFO): Sending 236 bytes from file Logs/20200715T191818/Express0011.lzma
2020-07-15T19:36:47.214Z,1594841807.214 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0011.lzma.bak
2020-07-15T19:36:47.215Z,1594841807.215 [DataOverHttps](INFO): SBD MOMSN=12442336
2020-07-15T19:36:48.553Z,1594841808.553 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T19:36:48.553Z,1594841808.553 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T19:36:48.553Z,1594841808.553 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:36:53.770Z,1594841813.770 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T19:38:33.301Z,1594841913.301 [CommandLine](IMPORTANT): got command strobe off
2020-07-15T19:38:33.301Z,1594841913.301 [CommandLine](IMPORTANT): Deactivating strobe
2020-07-15T19:39:20.428Z,1594841960.428 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:39:20.428Z,1594841960.428 [DVL_micro](ERROR): Failed to parse:
:BI,+00250,+01129,-00076,+00BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2020-07-15T19:39:53.556Z,1594841993.556 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:39:53.556Z,1594841993.556 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.1,0000.0,00
2020-07-15T19:40:34.364Z,1594842034.364 [DVL_micro](ERROR): only read 0 of 4 data items
2020-07-15T19:40:34.364Z,1594842034.364 [DVL_micro](ERROR): Failed to parse:
:RD,,+9999.99,+9999.99,+9999.99
2020-07-15T19:41:48.303Z,1594842108.303 [DVL_micro](ERROR): only read 2 of 4 data items
2020-07-15T19:41:48.303Z,1594842108.303 [DVL_micro](ERROR): Failed to parse:
:RD,+99999.99,+9999.999
2020-07-15T19:41:49.126Z,1594842109.126 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T19:41:49.126Z,1594842109.126 [Default:CheckIn:C.Wait] Stopped
2020-07-15T19:41:49.126Z,1594842109.126 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T19:41:49.126Z,1594842109.126 [Default:CheckIn:D] Running Loop=1
2020-07-15T19:41:49.530Z,1594842109.530 [Default:CheckIn:D] Stopped
2020-07-15T19:41:49.530Z,1594842109.530 [Default:CheckIn:E] Running Loop=1
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 19.416250 min 
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn:E] Stopped
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn] Stopped
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn](INFO): Running loop #4
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn] Running Loop=4
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T19:41:49.943Z,1594842109.943 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T19:41:51.949Z,1594842111.949 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193703.00,A,3648.16517,N,12147.28242,W,0.194,0.00,150720,,,A*7C
2020-07-15T19:41:51.951Z,1594842111.951 [NAL9602](INFO): GPS fix at 20200715T193703: (36.802753, -121.788040)
2020-07-15T19:41:51.975Z,1594842111.975 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T19:41:51.975Z,1594842111.975 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T19:41:59.292Z,1594842119.292 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0013.lzma
2020-07-15T19:42:00.294Z,1594842120.294 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0013.lzma.bak
2020-07-15T19:42:00.295Z,1594842120.295 [DataOverHttps](INFO): SBD MOMSN=12442348
2020-07-15T19:42:16.333Z,1594842136.333 [DataOverHttps](INFO): Sending 170 bytes from file Logs/20200715T191818/Express0014.lzma
2020-07-15T19:42:17.334Z,1594842137.334 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0014.lzma.bak
2020-07-15T19:42:17.335Z,1594842137.335 [DataOverHttps](INFO): SBD MOMSN=12442351
2020-07-15T19:42:18.657Z,1594842138.657 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T19:42:18.657Z,1594842138.657 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T19:42:18.657Z,1594842138.657 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:42:46.867Z,1594842166.867 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+17.2,0000.0,1489.0,000
2020-07-15T19:45:17.177Z,1594842317.177 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.3,0000.0,1489.0,000
2020-07-15T19:45:47.864Z,1594842347.864 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:45:47.864Z,1594842347.864 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000007.4,0000.0,1489.0,000
2020-07-15T19:46:20.994Z,1594842380.994 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:46:20.994Z,1594842380.994 [DVL_micro](ERROR): Failed to parse:
:BI,-00472,+01464,+00177,
2020-07-15T19:46:53.734Z,1594842413.734 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T19:47:17.233Z,1594842437.233 [DVL_micro](ERROR): DVL uart error: serial timeout
2020-07-15T19:47:17.233Z,1594842437.233 [DVL_micro] Communications Fault, FailCount= 1
2020-07-15T19:47:17.233Z,1594842437.233 [DVL_micro](ERROR): Communications Fault
2020-07-15T19:47:17.233Z,1594842437.233 [DVL_micro](ERROR): Failed to parse:
2020-07-15T19:47:17.329Z,1594842437.329 [CBIT](ERROR): Communications Fault in component: DVL_micro
2020-07-15T19:47:17.629Z,1594842437.629 [DVL_micro](INFO): Powering down
2020-07-15T19:47:18.430Z,1594842438.430 [CBIT](INFO): Clearing failed state for component DVL_micro
2020-07-15T19:47:18.430Z,1594842438.430 [DVL_micro] No Fault, FailCount= 1
2020-07-15T19:47:19.215Z,1594842439.215 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T19:47:19.215Z,1594842439.215 [Default:CheckIn:C.Wait] Stopped
2020-07-15T19:47:19.215Z,1594842439.215 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T19:47:19.215Z,1594842439.215 [Default:CheckIn:D] Running Loop=1
2020-07-15T19:47:19.622Z,1594842439.622 [Default:CheckIn:D] Stopped
2020-07-15T19:47:19.622Z,1594842439.622 [Default:CheckIn:E] Running Loop=1
2020-07-15T19:47:20.034Z,1594842440.034 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.917782 min 
2020-07-15T19:47:20.034Z,1594842440.034 [Default:CheckIn:E] Stopped
2020-07-15T19:47:20.035Z,1594842440.035 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T19:47:20.035Z,1594842440.035 [Default:CheckIn] Stopped
2020-07-15T19:47:20.035Z,1594842440.035 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T19:47:20.035Z,1594842440.035 [Default:CheckIn](INFO): Running loop #5
2020-07-15T19:47:20.035Z,1594842440.035 [Default:CheckIn] Running Loop=5
2020-07-15T19:47:20.035Z,1594842440.035 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T19:47:20.035Z,1594842440.035 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T19:47:22.018Z,1594842442.018 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194233.00,A,3648.16548,N,12147.28050,W,0.350,0.00,150720,,,A*7C
2020-07-15T19:47:22.020Z,1594842442.020 [NAL9602](INFO): GPS fix at 20200715T194233: (36.802758, -121.788008)
2020-07-15T19:47:22.044Z,1594842442.044 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T19:47:22.045Z,1594842442.045 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T19:47:28.956Z,1594842448.956 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0016.lzma
2020-07-15T19:47:29.958Z,1594842449.958 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0016.lzma.bak
2020-07-15T19:47:29.959Z,1594842449.959 [DataOverHttps](INFO): SBD MOMSN=12442356
2020-07-15T19:47:36.186Z,1594842456.186 [DVL_micro](FAULT): Failed to initialize within timeout.
2020-07-15T19:47:36.186Z,1594842456.186 [DVL_micro] Communications Fault, FailCount= 2
2020-07-15T19:47:36.186Z,1594842456.186 [DVL_micro](ERROR): Communications Fault
2020-07-15T19:47:36.292Z,1594842456.292 [CBIT](ERROR): Communications Fault in component: DVL_micro
2020-07-15T19:47:36.665Z,1594842456.665 [DVL_micro](INFO): Powering down
2020-07-15T19:47:37.445Z,1594842457.445 [CBIT](INFO): Clearing failed state for component DVL_micro
2020-07-15T19:47:37.445Z,1594842457.445 [DVL_micro] No Fault, FailCount= 2
2020-07-15T19:47:45.973Z,1594842465.973 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20200715T191818/Express0017.lzma
2020-07-15T19:47:46.974Z,1594842466.974 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0017.lzma.bak
2020-07-15T19:47:46.975Z,1594842466.975 [DataOverHttps](INFO): SBD MOMSN=12442359
2020-07-15T19:47:48.337Z,1594842468.337 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T19:47:48.337Z,1594842468.337 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T19:47:48.337Z,1594842468.337 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:47:53.966Z,1594842473.966 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T19:48:18.611Z,1594842498.611 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:48:18.611Z,1594842498.611 [DVL_micro](ERROR): Failed to parse:
:BI,-0008,+00200,+00000,I
2020-07-15T19:48:32.750Z,1594842512.750 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2020-07-15T19:48:32.750Z,1594842512.750 [DropWeight] Hardware Fault, FailCount= 1
2020-07-15T19:48:32.750Z,1594842512.750 [DropWeight](ERROR): Hardware Fault
2020-07-15T19:48:32.839Z,1594842512.839 [CommandLine](FAULT): Scheduling is paused
2020-07-15T19:48:32.840Z,1594842512.840 [CBIT](INFO): Critical error at 20200715T194832
2020-07-15T19:48:32.840Z,1594842512.840 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2020-07-15T19:48:32.847Z,1594842512.847 [CBIT](ERROR): Hardware Fault in component: DropWeight
2020-07-15T19:48:32.847Z,1594842512.847 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2020-07-15T19:48:33.191Z,1594842513.191 [CBIT](INFO): Critical error at 20200715T194832
2020-07-15T19:49:40.224Z,1594842580.224 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.99,+9999.99
2020-07-15T19:50:21.024Z,1594842621.024 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:50:21.024Z,1594842621.024 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35,0000.0,1489.0I,+00201,+00033,-00199,+00000,A
2020-07-15T19:51:01.826Z,1594842661.826 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:51:01.826Z,1594842661.826 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.999
2020-07-15T19:52:10.504Z,1594842730.504 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:52:10.504Z,1594842730.504 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+0.0,1489.0,000
2020-07-15T19:52:15.756Z,1594842735.756 [DVL_micro](ERROR): Failed to parse:
:WI,+00160,+00295,-00207A
2020-07-15T19:52:48.884Z,1594842768.884 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:52:48.884Z,1594842768.884 [DVL_micro](ERROR): Failed to parse:
:TS,000000000.0,+17.6,489.0,000
2020-07-15T19:52:48.958Z,1594842768.958 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T19:52:48.958Z,1594842768.958 [Default:CheckIn:C.Wait] Stopped
2020-07-15T19:52:48.958Z,1594842768.958 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T19:52:48.958Z,1594842768.958 [Default:CheckIn:D] Running Loop=1
2020-07-15T19:52:49.329Z,1594842769.329 [Default:CheckIn:D] Stopped
2020-07-15T19:52:49.329Z,1594842769.329 [Default:CheckIn:E] Running Loop=1
2020-07-15T19:52:49.720Z,1594842769.720 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 30.412905 min 
2020-07-15T19:52:49.720Z,1594842769.720 [Default:CheckIn:E] Stopped
2020-07-15T19:52:49.721Z,1594842769.721 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T19:52:49.721Z,1594842769.721 [Default:CheckIn] Stopped
2020-07-15T19:52:49.721Z,1594842769.721 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T19:52:49.721Z,1594842769.721 [Default:CheckIn](INFO): Running loop #6
2020-07-15T19:52:49.721Z,1594842769.721 [Default:CheckIn] Running Loop=6
2020-07-15T19:52:49.721Z,1594842769.721 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T19:52:49.721Z,1594842769.721 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T19:52:51.716Z,1594842771.716 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194803.00,A,3648.16412,N,12147.28461,W,0.156,0.00,150720,,,A*79
2020-07-15T19:52:51.726Z,1594842771.726 [NAL9602](INFO): GPS fix at 20200715T194803: (36.802735, -121.788077)
2020-07-15T19:52:51.795Z,1594842771.795 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T19:52:51.795Z,1594842771.795 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T19:52:58.880Z,1594842778.880 [DataOverHttps](INFO): Sending 178 bytes from file Logs/20200715T191818/Courier0019.lzma
2020-07-15T19:52:59.883Z,1594842779.883 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0019.lzma.bak
2020-07-15T19:52:59.883Z,1594842779.883 [DataOverHttps](INFO): SBD MOMSN=12442371
2020-07-15T19:53:16.085Z,1594842796.085 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20200715T191818/Express0020.lzma
2020-07-15T19:53:17.070Z,1594842797.070 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0020.lzma.bak
2020-07-15T19:53:17.071Z,1594842797.071 [DataOverHttps](INFO): SBD MOMSN=12442376
2020-07-15T19:53:18.453Z,1594842798.453 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T19:53:18.453Z,1594842798.453 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T19:53:18.453Z,1594842798.453 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:53:55.190Z,1594842835.190 [DVL_micro](ERROR): Failed to parse:
:B,+00008,00000,I
2020-07-15T19:54:38.421Z,1594842878.421 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:54:38.421Z,1594842878.421 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+1.0,1489.0I,-00118,+0019,+00000-00118,+0015,+00000,00000000.0000.00,+00000000.00,9999.99,000.00
2020-07-15T19:55:09.122Z,1594842909.122 [DVL_micro](ERROR): Failed to parse:000000.00,+00000000.00,+00000000.00,9999.99,000.00
2020-07-15T19:55:42.248Z,1594842942.248 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:55:42.249Z,1594842942.249 [DVL_micro](ERROR): Failed to parse:
:TS,000000,37,0000.0,1489:WI,+0007,-00098,+00000,A
2020-07-15T19:56:23.055Z,1594842983.055 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T19:56:23.055Z,1594842983.055 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2020-07-15T19:56:44.060Z,1594843004.060 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T19:56:44.060Z,1594843004.060 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T19:56:56.192Z,1594843016.192 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:56:56.192Z,1594843016.192 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.8,0000.0,1489.WI,-0004,-00097,+0:BI,-00046,00097,+000000.0000.00,+099,000.00
2020-07-15T19:57:29.302Z,1594843049.302 [DVL_micro](ERROR): Failed to parse:
:WI,+00184,+01420,+00099,+00000,A
2020-07-15T19:57:53.950Z,1594843073.950 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T19:58:04.855Z,1594843084.855 [DVL_micro](ERROR): Failed to parse:
:WI+01316,+00212,+00000,A
2020-07-15T19:58:19.029Z,1594843099.029 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T19:58:19.029Z,1594843099.029 [Default:CheckIn:C.Wait] Stopped
2020-07-15T19:58:19.029Z,1594843099.029 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T19:58:19.029Z,1594843099.029 [Default:CheckIn:D] Running Loop=1
2020-07-15T19:58:19.430Z,1594843099.430 [Default:CheckIn:D] Stopped
2020-07-15T19:58:19.430Z,1594843099.430 [Default:CheckIn:E] Running Loop=1
2020-07-15T19:58:19.845Z,1594843099.845 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.914587 min 
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn:E] Stopped
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn] Stopped
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn](INFO): Running loop #7
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn] Running Loop=7
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T19:58:19.846Z,1594843099.846 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T19:58:21.823Z,1594843101.823 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195333.00,A,3648.16558,N,12147.28074,W,0.253,0.00,150720,,,A*79
2020-07-15T19:58:21.826Z,1594843101.826 [NAL9602](INFO): GPS fix at 20200715T195333: (36.802760, -121.788012)
2020-07-15T19:58:21.850Z,1594843101.850 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T19:58:21.850Z,1594843101.850 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T19:58:27.938Z,1594843107.938 [DVL_micro](ERROR): Failed to parse:
:7,+00257,00000,I
2020-07-15T19:58:28.912Z,1594843108.912 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20200715T191818/Courier0022.lzma
2020-07-15T19:58:29.914Z,1594843109.914 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0022.lzma.bak
2020-07-15T19:58:29.915Z,1594843109.915 [DataOverHttps](INFO): SBD MOMSN=12442385
2020-07-15T19:58:45.873Z,1594843125.873 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20200715T191818/Express0023.lzma
2020-07-15T19:58:46.874Z,1594843126.875 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0023.lzma.bak
2020-07-15T19:58:46.875Z,1594843126.875 [DataOverHttps](INFO): SBD MOMSN=12442393
2020-07-15T19:58:48.190Z,1594843128.190 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T19:58:48.190Z,1594843128.190 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T19:58:48.190Z,1594843128.190 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T19:58:54.198Z,1594843134.198 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T19:59:01.069Z,1594843141.069 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:59:01.070Z,1594843141.070 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,+1.0,1489.0,000
2020-07-15T19:59:34.196Z,1594843174.196 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T19:59:34.196Z,1594843174.196 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.8,0000.0000
2020-07-15T20:01:05.906Z,1594843265.906 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:01:05.906Z,1594843265.906 [DVL_micro](ERROR): Failed to parse:
:BI,+00331,00052,+00000,I
2020-07-15T20:01:46.708Z,1594843306.708 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:01:46.708Z,1594843306.708 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,00.0,1489.0,000
2020-07-15T20:02:12.168Z,1594843332.168 [DVL_micro](ERROR): only read 2 of 4 data items
2020-07-15T20:02:12.168Z,1594843332.168 [DVL_micro](ERROR): Failed to parse:
:RD,+99999.99,+9999.999
2020-07-15T20:02:54.589Z,1594843374.589 [DVL_micro](ERROR): Failed to parse:
0.28,+0002.55,+0000.24,+0000.13
2020-07-15T20:03:28.516Z,1594843408.516 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:03:28.516Z,1594843408.516 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35.0,+17.5,009.0,000
2020-07-15T20:03:32.996Z,1594843412.996 [CBIT](INFO): Clearing failed state for component DropWeight
2020-07-15T20:03:32.996Z,1594843412.996 [DropWeight] No Fault, FailCount= 1
2020-07-15T20:03:47.344Z,1594843427.344 [CommandLine](IMPORTANT): got command failComponent
2020-07-15T20:03:47.345Z,1594843427.345 [CommandLine](IMPORTANT): Failed components:
2020-07-15T20:03:47.345Z,1594843427.345 [CommandLine](IMPORTANT): No failed Components.
2020-07-15T20:03:48.733Z,1594843428.733 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T20:03:48.733Z,1594843428.733 [Default:CheckIn:C.Wait] Stopped
2020-07-15T20:03:48.733Z,1594843428.733 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T20:03:48.734Z,1594843428.734 [Default:CheckIn:D] Running Loop=1
2020-07-15T20:03:49.149Z,1594843429.149 [Default:CheckIn:D] Stopped
2020-07-15T20:03:49.149Z,1594843429.149 [Default:CheckIn:E] Running Loop=1
2020-07-15T20:03:49.553Z,1594843429.553 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.409904 min 
2020-07-15T20:03:49.553Z,1594843429.553 [Default:CheckIn:E] Stopped
2020-07-15T20:03:49.554Z,1594843429.554 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T20:03:49.554Z,1594843429.554 [Default:CheckIn] Stopped
2020-07-15T20:03:49.554Z,1594843429.554 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T20:03:49.554Z,1594843429.554 [Default:CheckIn](INFO): Running loop #8
2020-07-15T20:03:49.554Z,1594843429.554 [Default:CheckIn] Running Loop=8
2020-07-15T20:03:49.554Z,1594843429.554 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T20:03:49.554Z,1594843429.554 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T20:03:50.331Z,1594843430.331 [DVL_micro](ERROR): only read 2 of 4 data items
2020-07-15T20:03:50.332Z,1594843430.332 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.344,+0000.23,+

2020-07-15T20:03:51.544Z,1594843431.544 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195903.00,A,3648.16243,N,12147.28406,W,0.156,158.26,150720,,,A*72
2020-07-15T20:03:51.547Z,1594843431.547 [NAL9602](INFO): GPS fix at 20200715T195903: (36.802707, -121.788068)
2020-07-15T20:03:51.595Z,1594843431.595 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T20:03:51.595Z,1594843431.595 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T20:03:58.608Z,1594843438.608 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200715T191818/Courier0025.lzma
2020-07-15T20:03:59.610Z,1594843439.610 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0025.lzma.bak
2020-07-15T20:03:59.611Z,1594843439.611 [DataOverHttps](INFO): SBD MOMSN=12442397
2020-07-15T20:04:00.041Z,1594843440.041 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:04:00.042Z,1594843440.042 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:04:08.026Z,1594843448.026 [DataOverHttps](IMPORTANT): SBD MTMSN=20200715T195919
2020-07-15T20:04:15.677Z,1594843455.677 [DataOverHttps](INFO): Sending 185 bytes from file Logs/20200715T191818/Express0026.lzma
2020-07-15T20:04:15.679Z,1594843455.679 [DataOverHttps](INFO): Received command:run Maintenance/tank_ballast_and_trim.xml
2020-07-15T20:04:15.734Z,1594843455.734 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tank_ballast_and_trim.xml
2020-07-15T20:04:15.734Z,1594843455.734 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tank_ballast_and_trim.xml
2020-07-15T20:04:15.903Z,1594843455.903 [MissionManager](INFO): DefineArg ballast_and_trim.MissionTimeout = 120.000000 min
2020-07-15T20:04:15.906Z,1594843455.906 [MissionManager](INFO): DefineArg ballast_and_trim.SkipComms = 0 bool
2020-07-15T20:04:15.909Z,1594843455.909 [MissionManager](INFO): DefineArg ballast_and_trim.Depth1 = 7.000000 m
2020-07-15T20:04:15.912Z,1594843455.912 [MissionManager](INFO): DefineArg ballast_and_trim.Depth2 = nan m
2020-07-15T20:04:15.915Z,1594843455.915 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 0.100000 m
2020-07-15T20:04:15.918Z,1594843455.918 [MissionManager](INFO): DefineArg ballast_and_trim.SurfaceThreshold = 2.500000 m
2020-07-15T20:04:15.921Z,1594843455.921 [MissionManager](INFO): DefineArg ballast_and_trim.MaxWaitOnSurface = 20.000000 min
2020-07-15T20:04:15.924Z,1594843455.924 [MissionManager](INFO): DefineArg ballast_and_trim.SettleTime = 10.000000 min
2020-07-15T20:04:15.927Z,1594843455.927 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationTimeout = 45.000000 min
2020-07-15T20:04:15.930Z,1594843455.930 [MissionManager](INFO): DefineArg ballast_and_trim.MinEstimationTime = 10.000000 min
2020-07-15T20:04:15.933Z,1594843455.933 [MissionManager](INFO): DefineArg ballast_and_trim.MassEstimationErrorBound = 0.250000 mm
2020-07-15T20:04:15.936Z,1594843455.936 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyEstimationErrorBound = 15.000000 cc
2020-07-15T20:04:15.939Z,1594843455.939 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationConfidence = 99.900000 %
2020-07-15T20:04:15.942Z,1594843455.942 [MissionManager](INFO): DefineArg ballast_and_trim.WaitToFloat = 5.000000 min
2020-07-15T20:04:15.942Z,1594843455.942 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2020-07-15T20:04:16.186Z,1594843456.186 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:04:16.186Z,1594843456.186 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.3,0000.0,1489:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:04:16.463Z,1594843456.463 [MissionManager](INFO): DefineArg ballast_and_trim:Science.SampleISUS = 0 bool
2020-07-15T20:04:16.466Z,1594843456.466 [MissionManager](INFO): DefineArg ballast_and_trim:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2020-07-15T20:04:16.469Z,1594843456.469 [MissionManager](INFO): DefineArg ballast_and_trim:Science.SampleISUSminPitch = -60.000000 arcdeg
2020-07-15T20:04:16.472Z,1594843456.472 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectChlActive = 0 bool
2020-07-15T20:04:16.475Z,1594843456.475 [MissionManager](INFO): DefineArg ballast_and_trim:Science.TimeWindowPeakReport = nan min
2020-07-15T20:04:16.502Z,1594843456.502 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestChlPeakReportActive = 0 bool
2020-07-15T20:04:16.504Z,1594843456.504 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PatchTracking = 0 bool
2020-07-15T20:04:16.520Z,1594843456.520 [MissionManager](INFO): DefineArg ballast_and_trim:Science.FilterWidthHorizontal = 3.000000 count
2020-07-15T20:04:16.523Z,1594843456.523 [MissionManager](INFO): DefineArg ballast_and_trim:Science.NumProfilesSlidingwindow = 100.000000 count
2020-07-15T20:04:16.527Z,1594843456.527 [MissionManager](INFO): DefineArg ballast_and_trim:Science.OffPeakFractionHorizontal = 80.000000 %
2020-07-15T20:04:16.541Z,1594843456.541 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectNO3Active = 0 bool
2020-07-15T20:04:16.544Z,1594843456.544 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectOilActive = 0 bool
2020-07-15T20:04:16.551Z,1594843456.551 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectFDOMActive = 0 bool
2020-07-15T20:04:16.565Z,1594843456.565 [MissionManager](INFO): DefineArg ballast_and_trim:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2020-07-15T20:04:16.568Z,1594843456.568 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledAanderaaO2 = 0.000000 bool
2020-07-15T20:04:16.624Z,1594843456.624 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledNeilBrown = 0.000000 bool
2020-07-15T20:04:16.632Z,1594843456.632 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledSeabird = 1.000000 bool
2020-07-15T20:04:16.660Z,1594843456.660 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledTurbulence_NPS = 0.000000 bool
2020-07-15T20:04:16.664Z,1594843456.664 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsBB2FL = 1.000000 bool
2020-07-15T20:04:16.720Z,1594843456.720 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool
2020-07-15T20:04:16.724Z,1594843456.724 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsUBAT = 0.000000 bool
2020-07-15T20:04:16.744Z,1594843456.744 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledISUS = 0.000000 bool
2020-07-15T20:04:16.755Z,1594843456.755 [MissionManager](INFO): DefineArg ballast_and_trim:Science.LowPassWindowLength = 20.000000 count
2020-07-15T20:04:16.766Z,1594843456.766 [MissionManager](INFO): DefineArg ballast_and_trim:Science.MedianFilterLen = 5.000000 count
2020-07-15T20:04:16.785Z,1594843456.785 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakChlShallowBound = nan m
2020-07-15T20:04:16.788Z,1594843456.788 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakChlDeepBound = nan m
2020-07-15T20:04:16.799Z,1594843456.799 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakShallowBound = nan m
2020-07-15T20:04:16.806Z,1594843456.806 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDeepBound = nan m
2020-07-15T20:04:16.825Z,1594843456.825 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChl = 0.000000 ug/l
2020-07-15T20:04:16.828Z,1594843456.828 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlDepth = 0.000000 m
2020-07-15T20:04:16.861Z,1594843456.861 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlTemperature = 0.000000 degC
2020-07-15T20:04:16.880Z,1594843456.880 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLatitude = nan arcdeg
2020-07-15T20:04:16.883Z,1594843456.883 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLongitude = nan arcdeg
2020-07-15T20:04:16.910Z,1594843456.910 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3 = 0.000000 umol/l
2020-07-15T20:04:16.921Z,1594843456.921 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Depth = 0.000000 m
2020-07-15T20:04:16.924Z,1594843456.924 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Latitude = nan arcdeg
2020-07-15T20:04:16.943Z,1594843456.943 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Longitude = nan arcdeg
2020-07-15T20:04:16.954Z,1594843456.954 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChl = 0.000000 m
2020-07-15T20:04:16.965Z,1594843456.965 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDepth = 0.000000 m
2020-07-15T20:04:16.968Z,1594843456.968 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLatitude = nan arcdeg
2020-07-15T20:04:17.033Z,1594843457.033 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLongitude = nan arcdeg
2020-07-15T20:04:17.036Z,1594843457.036 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDistance = nan m
2020-07-15T20:04:17.051Z,1594843457.051 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOil = 0.000000 kg/m3
2020-07-15T20:04:17.063Z,1594843457.063 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilDepth = 0.000000 m
2020-07-15T20:04:17.090Z,1594843457.090 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLatitude = nan arcdeg
2020-07-15T20:04:17.105Z,1594843457.105 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLongitude = nan arcdeg
2020-07-15T20:04:17.125Z,1594843457.125 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOM = 0.000000 ppb
2020-07-15T20:04:17.128Z,1594843457.128 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMDepth = 0.000000 m
2020-07-15T20:04:17.139Z,1594843457.139 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLatitude = nan arcdeg
2020-07-15T20:04:17.142Z,1594843457.142 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLongitude = nan arcdeg
2020-07-15T20:04:17.161Z,1594843457.161 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchFDOMDistance = nan m
2020-07-15T20:04:17.226Z,1594843457.226 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-07-15T20:04:17.250Z,1594843457.250 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2020-07-15T20:04:17.257Z,1594843457.257 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0026.lzma.bak
2020-07-15T20:04:17.257Z,1594843457.257 [DataOverHttps](INFO): SBD MOMSN=12442401
2020-07-15T20:04:17.293Z,1594843457.293 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-07-15T20:04:17.333Z,1594843457.333 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-07-15T20:04:17.367Z,1594843457.367 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2020-07-15T20:04:17.376Z,1594843457.376 [MissionManager](INFO): Inserting Stack: Missions/Insert/BallastAndTrim.xml
2020-07-15T20:04:17.769Z,1594843457.769 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepth = 25.000000 m
2020-07-15T20:04:17.772Z,1594843457.772 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSpeed = 0.000000 m/s
2020-07-15T20:04:17.831Z,1594843457.831 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthRate = 0.400000 m/s
2020-07-15T20:04:17.843Z,1594843457.843 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachPitchLimit = 20.000000 arcdeg
2020-07-15T20:04:17.872Z,1594843457.872 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSettleTimePreDive = 0.000000 min
2020-07-15T20:04:17.904Z,1594843457.904 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = 20.000000 min
2020-07-15T20:04:17.927Z,1594843457.927 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = 10.000000 min
2020-07-15T20:04:17.939Z,1594843457.939 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = 45.000000 min
2020-07-15T20:04:17.960Z,1594843457.960 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = 10.000000 min
2020-07-15T20:04:17.967Z,1594843457.967 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = 0.250000 mm
2020-07-15T20:04:17.975Z,1594843457.975 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = 15.000000 cc
2020-07-15T20:04:18.002Z,1594843458.002 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = 99.900000 %
2020-07-15T20:04:18.012Z,1594843458.012 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = 1.000000 m
2020-07-15T20:04:18.031Z,1594843458.031 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertKiDepthBuoy = 0.300000 1/s
2020-07-15T20:04:18.036Z,1594843458.036 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertMassDeadband = 0.250000 mm
2020-07-15T20:04:18.102Z,1594843458.102 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Construct.
2020-07-15T20:04:18.118Z,1594843458.118 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Construct Buoyancy.
2020-07-15T20:04:18.123Z,1594843458.123 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Construct.
2020-07-15T20:04:18.144Z,1594843458.144 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait](DEBUG): Construct Wait.
2020-07-15T20:04:18.164Z,1594843458.164 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Construct.
2020-07-15T20:04:18.175Z,1594843458.175 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Construct.
2020-07-15T20:04:18.234Z,1594843458.234 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2020-07-15T20:04:18.257Z,1594843458.257 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Construct.
2020-07-15T20:04:18.260Z,1594843458.260 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch](DEBUG): Construct.
2020-07-15T20:04:18.295Z,1594843458.295 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Construct Wait.
2020-07-15T20:04:18.314Z,1594843458.314 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](DEBUG): Construct BallastAndTrim.
2020-07-15T20:04:18.394Z,1594843458.394 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = reader:ballast_and_trim.DepthDeadband
2020-07-15T20:04:18.396Z,1594843458.396 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = reader:ballast_and_trim.MaxWaitOnSurface
2020-07-15T20:04:18.402Z,1594843458.402 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = reader:ballast_and_trim.SettleTime
2020-07-15T20:04:18.404Z,1594843458.404 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = reader:ballast_and_trim.EstimationTimeout
2020-07-15T20:04:18.414Z,1594843458.414 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = reader:ballast_and_trim.MinEstimationTime
2020-07-15T20:04:18.415Z,1594843458.415 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = reader:ballast_and_trim.MassEstimationErrorBound
2020-07-15T20:04:18.418Z,1594843458.418 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = reader:ballast_and_trim.BuoyEstimationErrorBound
2020-07-15T20:04:18.420Z,1594843458.420 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = reader:ballast_and_trim.EstimationConfidence
2020-07-15T20:04:18.453Z,1594843458.453 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Construct Buoyancy.
2020-07-15T20:04:18.456Z,1594843458.456 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Construct Wait.
2020-07-15T20:04:18.514Z,1594843458.514 [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="ballast_and_trim">

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

    <DefineArg Name="SkipComms"><Description>
        Skip communications at start of mission.
    </Description><False/></DefineArg>

    <DefineArg Name="Depth1"><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="Depth2"><Units:meter/><Value>NaN</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Description>
        How much vertical drift from the specified depth is allowed durnig the mission.
    </Description><Units:meter/><Value>0.1</Value></DefineArg>

    <DefineArg Name="SurfaceThreshold"><Description>
        Surface threshold depth.
    </Description><Units:meter/><Value>2.5</Value></DefineArg>

    <DefineArg Name="MaxWaitOnSurface"><Description>
        Maximum wait time for the vehicle to go under the surface (i.e., reach
        the surface threshold depth).
    </Description><Units:minute/><Value>20</Value></DefineArg>

    <DefineArg Name="SettleTime"><Description>
        How long to wait after reaching target depth before starting ballast and
        trim.
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="EstimationTimeout"><Description>
        Timeout for ballast and trim estimation.
    </Description><Units:minute/><Value>45</Value></DefineArg>

    <DefineArg Name="MinEstimationTime"><Description>
        Minimum time to run ballast and trim estimation before determining
        convergence (must be shorter than timeout).
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="MassEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:millimeter/><Value>0.25</Value></DefineArg>

    <DefineArg Name="BuoyEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:cubic_centimeter/><Value>15</Value></DefineArg>

    <DefineArg Name="EstimationConfidence"><Description>
        Confidence level that the estimator has reached the desired error range
        (larger values take longer to converge).
    </Description><Units:percent/><Value>99.9</Value></DefineArg>

    <DefineArg Name="WaitToFloat"><Units:minute/><Value>5</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

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

    <Aggregate Id="RunBallastAndTrim">

        <Sequence/>

        <Insert Filename="Insert/BallastAndTrim.xml">
            <RedefineArg Name="InsertDepthDeadband"><Arg Name="DepthDeadband"/></RedefineArg>
            <RedefineArg Name="InsertApproachDepthTimeout"><Arg Name="MaxWaitOnSurface"/></RedefineArg>
            <RedefineArg Name="InsertSettleTime"><Arg Name="SettleTime"/></RedefineArg>
            <RedefineArg Name="EstTimeout"><Arg Name="EstimationTimeout"/></RedefineArg>
            <RedefineArg Name="MinEstTime"><Arg Name="MinEstimationTime"/></RedefineArg>
            <RedefineArg Name="MassEstErrorBound"><Arg Name="MassEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="BuoyEstErrorBound"><Arg Name="BuoyEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="EstConfidence"><Arg Name="EstimationConfidence"/></RedefineArg>
        </Insert>
        
        <Aggregate Id="Depth1">

            <Sequence/>

            <Break>
                <IsNaN>
                    <Arg Name="Depth1"/>
                </IsNaN>
            </Break>

            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>
            
            <Call RefId="BallastAndTrim"/>

        </Aggregate>

        <Aggregate Id="Depth2">

            <Sequence/>

            <Break>
                <IsNaN>
                    <Arg Name="Depth2"/>
                </IsNaN>
            </Break>

            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>

            <Call RefId="BallastAndTrim"/>

        </Aggregate>

    </Aggregate>

    <Aggregate Id="Float_Up">

        <Description>
            Float to surface instead of driving.
        </Description>

        <Sequence/>

        <Break>
            <Universal:depth/>
            <Lt><Control:VerticalControl.surfaceThreshold/></Lt>
        </Break>

        <Guidance:Buoyancy>
            <Parallel/>
            <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyDefault/></Setting>
        </Guidance:Buoyancy>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="WaitToFloat"/></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2020-07-15T20:04:18.518Z,1594843458.518 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tank_ballast_and_trim.xml
2020-07-15T20:04:18.673Z,1594843458.673 [Default] Stopped
2020-07-15T20:04:18.673Z,1594843458.673 [Default](DEBUG): Aggregate::uninitialize Default
2020-07-15T20:04:18.673Z,1594843458.673 [Default:B.GoToSurface] Stopped
2020-07-15T20:04:18.673Z,1594843458.673 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-07-15T20:04:18.674Z,1594843458.674 [Default:CheckIn] Stopped
2020-07-15T20:04:18.674Z,1594843458.674 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T20:04:18.674Z,1594843458.674 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T20:04:18.674Z,1594843458.674 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2020-07-15T20:04:18.674Z,1594843458.674 [ballast_and_trim] Running Loop=1
2020-07-15T20:04:18.674Z,1594843458.674 [ballast_and_trim](DEBUG): Aggregate::initialize ballast_and_trim
2020-07-15T20:04:18.674Z,1594843458.674 [ballast_and_trim:Science] Running Loop=1
2020-07-15T20:04:18.674Z,1594843458.674 [ballast_and_trim:Science](DEBUG): Aggregate::initialize ballast_and_trim:Science
2020-07-15T20:04:18.674Z,1594843458.674 [ballast_and_trim:Science:A] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:B] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:C] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:D] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:E] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:F] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:G] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:H] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:Read_Oil] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:PeakDetectChl] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectChl
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2020-07-15T20:04:18.675Z,1594843458.675 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-07-15T20:04:18.678Z,1594843458.678 [ballast_and_trim:Science:HighestChlPeakReport] Running Loop=1
2020-07-15T20:04:18.678Z,1594843458.678 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestChlPeakReport
2020-07-15T20:04:18.678Z,1594843458.678 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2020-07-15T20:04:18.678Z,1594843458.678 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2020-07-15T20:04:18.678Z,1594843458.678 [ballast_and_trim:Science:PeakDetectNO3] Running Loop=1
2020-07-15T20:04:18.678Z,1594843458.678 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectNO3
2020-07-15T20:04:18.679Z,1594843458.679 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2020-07-15T20:04:18.679Z,1594843458.679 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-07-15T20:04:18.693Z,1594843458.693 [ballast_and_trim:Science:PeakDetectOil] Running Loop=1
2020-07-15T20:04:18.693Z,1594843458.693 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectOil
2020-07-15T20:04:18.693Z,1594843458.693 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2020-07-15T20:04:18.693Z,1594843458.693 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-07-15T20:04:18.695Z,1594843458.695 [ballast_and_trim:Science:PeakDetectFDOM] Running Loop=1
2020-07-15T20:04:18.695Z,1594843458.695 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectFDOM
2020-07-15T20:04:18.695Z,1594843458.695 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2020-07-15T20:04:18.695Z,1594843458.695 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2020-07-15T20:04:18.700Z,1594843458.700 [ballast_and_trim:RunBallastAndTrim] Running Loop=1
2020-07-15T20:04:18.700Z,1594843458.700 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim
2020-07-15T20:04:18.709Z,1594843458.709 [ballast_and_trim:RunBallastAndTrim:Depth1] Running Loop=1
2020-07-15T20:04:18.709Z,1594843458.709 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1
2020-07-15T20:04:18.709Z,1594843458.709 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Running Loop=1
2020-07-15T20:04:18.710Z,1594843458.710 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Stopped
2020-07-15T20:04:18.710Z,1594843458.710 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Running Loop=1
2020-07-15T20:04:18.710Z,1594843458.710 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2020-07-15T20:04:18.710Z,1594843458.710 [ballast_and_trim:Science] Running Loop=1
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectFDOM] Stopped
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectFDOM
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectOil] Stopped
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectOil
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2020-07-15T20:04:18.711Z,1594843458.711 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectNO3] Stopped
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectNO3
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:HighestChlPeakReport] Stopped
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestChlPeakReport
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectChl] Stopped
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectChl
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2020-07-15T20:04:18.712Z,1594843458.712 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2020-07-15T20:04:18.717Z,1594843458.717 [ballast_and_trim:Science:Read_Oil] Stopped
2020-07-15T20:04:18.717Z,1594843458.717 [ballast_and_trim:Science:H] Stopped
2020-07-15T20:04:18.717Z,1594843458.717 [ballast_and_trim:Science:G] Running Loop=1
2020-07-15T20:04:18.717Z,1594843458.717 [ballast_and_trim:Science:G](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2020-07-15T20:04:18.718Z,1594843458.718 [ballast_and_trim:Science:F] Stopped
2020-07-15T20:04:18.718Z,1594843458.718 [ballast_and_trim:Science:E] Stopped
2020-07-15T20:04:18.718Z,1594843458.718 [ballast_and_trim:Science:D] Running Loop=1
2020-07-15T20:04:18.718Z,1594843458.718 [ballast_and_trim:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_temperature
2020-07-15T20:04:18.719Z,1594843458.719 [ballast_and_trim:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_salinity
2020-07-15T20:04:18.719Z,1594843458.719 [ballast_and_trim:Science:C] Running Loop=1
2020-07-15T20:04:18.720Z,1594843458.720 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2020-07-15T20:04:18.720Z,1594843458.720 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2020-07-15T20:04:18.720Z,1594843458.720 [ballast_and_trim:Science:B] Stopped
2020-07-15T20:04:18.720Z,1594843458.720 [ballast_and_trim:Science:A] Stopped
2020-07-15T20:04:19.038Z,1594843459.038 [WetLabsBB2FL](INFO): Powering up
2020-07-15T20:04:19.053Z,1594843459.053 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Running Loop=1
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Running Loop=1
2020-07-15T20:04:19.054Z,1594843459.054 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:G] Running Loop=1
2020-07-15T20:04:19.056Z,1594843459.056 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:G](INFO): Going to target depth. Speed set to 0.000000 m/s 
2020-07-15T20:04:19.056Z,1594843459.056 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:G] Stopped
2020-07-15T20:04:19.056Z,1594843459.056 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Running Loop=1
2020-07-15T20:04:19.056Z,1594843459.056 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2020-07-15T20:04:19.056Z,1594843459.056 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2020-07-15T20:04:19.056Z,1594843459.056 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Running Loop=1
2020-07-15T20:04:19.061Z,1594843459.061 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2020-07-15T20:04:19.061Z,1594843459.061 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Running Loop=1
2020-07-15T20:04:19.061Z,1594843459.061 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Initialize.
2020-07-15T20:04:19.061Z,1594843459.061 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Running Loop=1
2020-07-15T20:04:19.061Z,1594843459.061 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2020-07-15T20:04:19.061Z,1594843459.061 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Running Loop=1
2020-07-15T20:04:19.061Z,1594843459.061 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Initialize.
2020-07-15T20:04:19.062Z,1594843459.062 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Running Loop=1
2020-07-15T20:04:19.062Z,1594843459.062 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2020-07-15T20:04:19.062Z,1594843459.062 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Running Loop=1
2020-07-15T20:04:19.062Z,1594843459.062 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Running Loop=1
2020-07-15T20:04:19.062Z,1594843459.062 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2020-07-15T20:04:19.062Z,1594843459.062 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2020-07-15T20:04:19.063Z,1594843459.063 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2020-07-15T20:04:19.063Z,1594843459.063 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2020-07-15T20:04:19.063Z,1594843459.063 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2020-07-15T20:04:19.454Z,1594843459.454 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Stopped
2020-07-15T20:04:19.454Z,1594843459.454 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2020-07-15T20:04:19.454Z,1594843459.454 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Stopped
2020-07-15T20:04:19.454Z,1594843459.454 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Running Loop=1
2020-07-15T20:04:19.454Z,1594843459.454 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Initialize.
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Running Loop=1
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Stopped
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Stopped
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Stopped
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Stopped
2020-07-15T20:04:19.455Z,1594843459.455 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2020-07-15T20:04:19.877Z,1594843459.877 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2020-07-15T20:04:19.878Z,1594843459.878 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2020-07-15T20:04:19.878Z,1594843459.878 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Stopped
2020-07-15T20:04:19.878Z,1594843459.878 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Running Loop=1
2020-07-15T20:04:19.878Z,1594843459.878 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Initialize.
2020-07-15T20:04:21.950Z,1594843461.950 [CTD_Seabird](ERROR): Failed to parse device response: <!--startlogging-->
2020-07-15T20:04:22.369Z,1594843462.369 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-07-15T20:04:22.445Z,1594843462.445 [NAL9602](FAULT): received: 
+CSQ:0

OK4, 2, 0, 0, 0

OK
2020-07-15T20:04:22.445Z,1594843462.445 [NAL9602] Data Fault, FailCount= 1
2020-07-15T20:04:22.445Z,1594843462.445 [NAL9602](ERROR): Data Fault
2020-07-15T20:04:22.725Z,1594843462.725 [CBIT](ERROR): Data Fault in component: NAL9602
2020-07-15T20:04:22.758Z,1594843462.758 [NAL9602](INFO): Powering down
2020-07-15T20:04:23.721Z,1594843463.721 [CBIT](INFO): Clearing failed state for component NAL9602
2020-07-15T20:04:23.721Z,1594843463.721 [NAL9602] No Fault, FailCount= 1
2020-07-15T20:04:23.959Z,1594843463.959 [CTD_Seabird](ERROR): Salinity reading out of range: 27.383574 psu
2020-07-15T20:04:31.864Z,1594843471.864 [DVL_micro](ERROR): Failed to parse:
:R34,+0000.42,+0000.23,+0000.13
2020-07-15T20:04:53.122Z,1594843493.122 [NAL9602](INFO): Powering up NAL9602
2020-07-15T20:05:00.628Z,1594843500.628 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20200715T191818/Courier0028.lzma
2020-07-15T20:05:01.636Z,1594843501.636 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0028.lzma.bak
2020-07-15T20:05:01.637Z,1594843501.637 [DataOverHttps](INFO): SBD MOMSN=12442408
2020-07-15T20:05:04.002Z,1594843504.002 [NAL9602](INFO): NAL9602 initialized
2020-07-15T20:05:34.802Z,1594843534.802 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T20:06:21.426Z,1594843581.426 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:06:21.426Z,1594843581.426 [DVL_micro](ERROR): Failed to parse:
:BI,+0000,+00000,+00000,I
2020-07-15T20:06:34.209Z,1594843594.209 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-07-15T20:06:37.222Z,1594843597.222 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239677
2020-07-15T20:07:08.577Z,1594843628.577 [Radio_Surface](INFO): Powering down
2020-07-15T20:07:09.349Z,1594843629.349 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-07-15T20:07:10.353Z,1594843630.353 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2020-07-15T20:07:45.050Z,1594843665.050 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:07:45.050Z,1594843665.050 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.2,009.0,000
2020-07-15T20:08:15.344Z,1594843695.344 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:08:15.344Z,1594843695.344 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.2,0000.0,00
2020-07-15T20:08:19.068Z,1594843699.068 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,000.00
2020-07-15T20:08:31.215Z,1594843711.215 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Stopped
2020-07-15T20:08:31.215Z,1594843711.215 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2020-07-15T20:08:31.215Z,1594843711.215 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Stopped
2020-07-15T20:08:31.215Z,1594843711.215 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2020-07-15T20:08:31.215Z,1594843711.215 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Stopped
2020-07-15T20:08:31.215Z,1594843711.215 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Uninitialize.
2020-07-15T20:08:31.216Z,1594843711.216 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2020-07-15T20:08:31.216Z,1594843711.216 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Stopped
2020-07-15T20:08:31.216Z,1594843711.216 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2020-07-15T20:08:31.216Z,1594843711.216 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Stopped
2020-07-15T20:08:31.216Z,1594843711.216 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth] Running Loop=1
2020-07-15T20:08:31.216Z,1594843711.216 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2020-07-15T20:08:31.216Z,1594843711.216 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Running Loop=1
2020-07-15T20:08:31.217Z,1594843711.217 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Initialize.
2020-07-15T20:08:31.217Z,1594843711.217 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Running Loop=1
2020-07-15T20:08:31.217Z,1594843711.217 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch](DEBUG): Initialize.
2020-07-15T20:08:31.217Z,1594843711.217 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C] Running Loop=1
2020-07-15T20:08:31.618Z,1594843711.618 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C](INFO): Waiting for the vehicle to settle. Depth = 7.023047 m 
2020-07-15T20:08:31.619Z,1594843711.619 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C] Stopped
2020-07-15T20:08:31.619Z,1594843711.619 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait] Running Loop=1
2020-07-15T20:08:31.619Z,1594843711.619 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Initialize Wait Component.
2020-07-15T20:08:31.619Z,1594843711.619 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Running Loop=1
2020-07-15T20:08:31.619Z,1594843711.619 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Running Loop=1
2020-07-15T20:08:56.098Z,1594843736.098 [CTD_Seabird](ERROR): Failed to parse device response: 7.63.65
2020-07-15T20:09:22.720Z,1594843762.720 [DVL_micro](ERROR): Failed to parse:
:SA,-03.92,+00.56,051.3
2020-07-15T20:09:31.053Z,1594843771.053 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:09:31.053Z,1594843771.053 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.,1489.0,0+00000,+00000,+00000,+00000,I
2020-07-15T20:09:34.746Z,1594843774.746 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:09:34.746Z,1594843774.746 [DVL_micro](ERROR): Failed to parse:
:BI,00001,+00000,+00000,A
2020-07-15T20:09:44.669Z,1594843784.669 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:09:44.669Z,1594843784.669 [DVL_micro](ERROR): Failed to parse:
:BI,-00005,00005,+000D,+0000000000000.00,+00000001.50,0RD,+9999.99,+0001.74,+0001.80,+0001.77
2020-07-15T20:10:20.876Z,1594843820.876 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:10:20.877Z,1594843820.877 [DVL_micro](ERROR): Failed to parse:
:BI,-00095,-0085,+00000,A
2020-07-15T20:10:58.694Z,1594843858.694 [DVL_micro](ERROR): Failed to parse:
:BI,+00122,-00142,+00044,+00000,A
2020-07-15T20:11:12.663Z,1594843872.663 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:11:12.663Z,1594843872.663 [DVL_micro](ERROR): Failed to parse:
:BI,+00110,-00220,+0001+00000000.00,+000,+00000000.00,0000.20,000.00
2020-07-15T20:11:52.463Z,1594843912.463 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,000.00
2020-07-15T20:12:00.148Z,1594843920.148 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:12:00.149Z,1594843920.149 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,00.0,1489.0,000
2020-07-15T20:13:01.783Z,1594843981.783 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:13:20.076Z,1594844000.076 [DVL_micro](ERROR): Failed to parse:
:WI+00000,+0000,I
2020-07-15T20:13:31.680Z,1594844011.680 [DVL_micro](ERROR): Failed to parse:00.35,+00003.68,+0003.72
2020-07-15T20:13:49.931Z,1594844029.931 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:13:49.931Z,1594844029.931 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.1,0000.0,148

2020-07-15T20:14:13.826Z,1594844053.826 [DVL_micro](ERROR): Failed to parse:
:BD,+000,+0000000000000.00,0000.50,000.00
2020-07-15T20:15:31.324Z,1594844131.324 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:15:31.325Z,1594844131.325 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.1,0000.0,1489.0,000
2020-07-15T20:16:25.222Z,1594844185.222 [DVL_micro](ERROR): Failed to parse:00000000,+17.1,089.0,000
2020-07-15T20:16:41.080Z,1594844201.080 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:17:03.064Z,1594844223.064 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:17:03.064Z,1594844223.064 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.1,0000.0,14
2020-07-15T20:17:48.848Z,1594844268.848 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:17:48.848Z,1594844268.848 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.1,009.0,000
2020-07-15T20:18:32.243Z,1594844312.243 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](INFO): Done Waiting.
2020-07-15T20:18:32.243Z,1594844312.243 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait] Stopped
2020-07-15T20:18:32.243Z,1594844312.243 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T20:18:32.243Z,1594844312.243 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E] Running Loop=1
2020-07-15T20:18:32.669Z,1594844312.669 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E](INFO): Running ballast and trim. Depth = 7.029098 m 
2020-07-15T20:18:32.669Z,1594844312.669 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E] Stopped
2020-07-15T20:18:32.669Z,1594844312.669 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.] Running Loop=1
2020-07-15T20:18:32.669Z,1594844312.669 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](INFO): Initializing BallastAndTrim.
2020-07-15T20:19:02.534Z,1594844342.534 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:19:02.534Z,1594844342.534 [DVL_micro](ERROR): Failed to parse:
:TS,000000005.0,+17.1,0000.0,1489.0,000
2020-07-15T20:19:28.070Z,1594844368.070 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:19:28.070Z,1594844368.070 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489.0,000
2020-07-15T20:21:11.931Z,1594844471.931 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:21:11.931Z,1594844471.931 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,+0000.58,+0003.90,
2020-07-15T20:21:21.669Z,1594844481.669 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:22:27.215Z,1594844547.215 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:24:11.126Z,1594844651.126 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2020-07-15T20:24:58.559Z,1594844698.559 [DVL_micro](ERROR): Failed to parse:
:BD,+000,+00000000.00,+00000000.00,0000.20,000.00
2020-07-15T20:25:20.804Z,1594844720.804 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2020-07-15T20:26:06.552Z,1594844766.552 [DVL_micro](ERROR): only read 0 of 4 data items
2020-07-15T20:26:06.552Z,1594844766.552 [DVL_micro](ERROR): Failed to parse:
:RD,,+0003.27,+0003.32,+0003.28
2020-07-15T20:26:36.462Z,1594844796.462 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:26:36.463Z,1594844796.463 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.1,0000.0000
2020-07-15T20:27:00.356Z,1594844820.356 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:27:00.357Z,1594844820.357 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35,0000.0,1489.0,000
2020-07-15T20:27:14.266Z,1594844834.266 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:27:14.266Z,1594844834.266 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489.0,000
2020-07-15T20:27:37.820Z,1594844857.820 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:28:04.061Z,1594844884.061 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:28:25.978Z,1594844905.978 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:28:25.978Z,1594844905.978 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.1,0000.0,1489.0,000
2020-07-15T20:29:35.292Z,1594844975.292 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:29:35.292Z,1594844975.292 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.1,0000.0000
2020-07-15T20:30:19.442Z,1594845019.442 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:30:19.442Z,1594845019.442 [DVL_micro](ERROR): Failed to parse:
:BI,-00023,+0026,+00000,A
2020-07-15T20:31:21.253Z,1594845081.253 [DVL_micro](ERROR): DVL uart error: serial timeout
2020-07-15T20:31:21.253Z,1594845081.253 [DVL_micro] Communications Fault, FailCount= 1
2020-07-15T20:31:21.253Z,1594845081.253 [DVL_micro](ERROR): Communications Fault
2020-07-15T20:31:21.253Z,1594845081.253 [DVL_micro](ERROR): Failed to parse:
2020-07-15T20:31:21.361Z,1594845081.361 [CBIT](ERROR): Communications Fault in component: DVL_micro
2020-07-15T20:31:21.633Z,1594845081.633 [DVL_micro](INFO): Powering down
2020-07-15T20:31:22.489Z,1594845082.489 [CBIT](INFO): Clearing failed state for component DVL_micro
2020-07-15T20:31:22.489Z,1594845082.489 [DVL_micro] No Fault, FailCount= 1
2020-07-15T20:34:17.889Z,1594845257.889 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:34:17.889Z,1594845257.889 [DVL_micro](ERROR): Failed to parse:
:RD,+00000.47,+0003.62,+0003.65
2020-07-15T20:34:39.849Z,1594845279.849 [DVL_micro](ERROR): DVL uart error: serial timeout
2020-07-15T20:34:39.849Z,1594845279.849 [DVL_micro] Communications Fault, FailCount= 1
2020-07-15T20:34:39.849Z,1594845279.849 [DVL_micro](ERROR): Communications Fault
2020-07-15T20:34:39.849Z,1594845279.849 [DVL_micro](ERROR): Failed to parse:
2020-07-15T20:34:39.923Z,1594845279.923 [CBIT](ERROR): Communications Fault in component: DVL_micro
2020-07-15T20:34:40.249Z,1594845280.249 [DVL_micro](INFO): Powering down
2020-07-15T20:34:41.161Z,1594845281.161 [CBIT](INFO): Clearing failed state for component DVL_micro
2020-07-15T20:34:41.161Z,1594845281.161 [DVL_micro] No Fault, FailCount= 1
2020-07-15T20:35:41.079Z,1594845341.079 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2020-07-15T20:36:34.707Z,1594845394.707 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:36:34.707Z,1594845394.707 [DVL_micro](ERROR): Failed to parse:
:BI,+00017,00146,+00000,A
2020-07-15T20:36:38.818Z,1594845398.818 [DVL_micro](ERROR): Failed to parse:
:T00000000,.0,0000.0,1489.0,000
2020-07-15T20:37:04.692Z,1594845424.692 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:37:04.692Z,1594845424.692 [DVL_micro](ERROR): Failed to parse:
:BI,+00000,-02120,-0000,A
2020-07-15T20:37:32.569Z,1594845452.569 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:38:38.004Z,1594845518.004 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:38:38.004Z,1594845518.004 [DVL_micro](ERROR): Failed to parse:
:TS,000000000.0,+17.1,0000.0,1489.0,000
2020-07-15T20:39:18.105Z,1594845558.105 [DVL_micro](ERROR): only read 1 of 4 data items
2020-07-15T20:39:18.105Z,1594845558.105 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,,+0004.03,+0004.07
2020-07-15T20:40:21.791Z,1594845621.791 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T20:41:01.315Z,1594845661.315 [DVL_micro](ERROR): only read 1 of 4 data items
2020-07-15T20:41:01.315Z,1594845661.315 [DVL_micro](ERROR): Failed to parse:
:BI,-00193+00050,+00000,A
2020-07-15T20:41:03.332Z,1594845663.332 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:41:03.333Z,1594845663.333 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,+00003.32,+0003.32
2020-07-15T20:42:11.264Z,1594845731.264 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:42:11.265Z,1594845731.265 [DVL_micro](ERROR): Failed to parse:
:TS,000000000.0,+17.0,0000.0,1489.0,000
2020-07-15T20:42:26.903Z,1594845746.903 [DVL_micro](ERROR): Failed to parse:
:SA,-00.45,+00.73,030.6
2020-07-15T20:42:52.755Z,1594845772.755 [DVL_micro](ERROR): Failed to parse:
:SA,+00.87,+00.68,033.4
2020-07-15T20:43:11.048Z,1594845791.048 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:43:11.049Z,1594845791.049 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35,0000.0,1489.0,000
2020-07-15T20:45:06.532Z,1594845906.532 [DVL_micro](ERROR): Failed to parse:
:W,+000,I
2020-07-15T20:45:30.187Z,1594845930.187 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2020-07-15T20:46:08.262Z,1594845968.262 [DVL_micro](ERROR): Failed to parse:
32,-00629,-00054,+00000,A
2020-07-15T20:47:09.992Z,1594846029.992 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:47:09.992Z,1594846029.992 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.35,+0003.423,+0003.45
2020-07-15T20:48:07.673Z,1594846087.673 [DVL_micro](ERROR): Failed to parse:
:000000000,35.0,+1.0,1489.0,000
2020-07-15T20:48:29.645Z,1594846109.645 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:48:29.645Z,1594846109.645 [DVL_micro](ERROR): Failed to parse:
:RD,+00000.42,+0004.03,+0004.05
2020-07-15T20:48:51.527Z,1594846131.527 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T20:48:51.527Z,1594846131.527 [DVL_micro](ERROR): Failed to parse:
:BI,-00676,+0008,+00000,A
2020-07-15T20:51:50.736Z,1594846310.736 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:51:50.736Z,1594846310.736 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0,1489.0,,+00000,+00000,+00000,+000I,+00367,00191,+00000,A0000000.0000,0000.30

2020-07-15T20:52:01.762Z,1594846321.762 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2020-07-15T20:52:10.636Z,1594846330.636 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:52:10.636Z,1594846330.636 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0000
2020-07-15T20:52:43.626Z,1594846363.626 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](IMPORTANT): BallastAndTrim completed. Estimation time: 34.18 minutes.
2020-07-15T20:52:43.627Z,1594846363.627 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](IMPORTANT): Estimated buoyancyNeutral: 236.209915 +/- 5.655735 cc (conf. level 99.90%, sigma: 12.710861 cc).
2020-07-15T20:52:43.628Z,1594846363.628 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](IMPORTANT): Estimated massDefault: 4.768366 +/- 0.249974 mm (conf. level 99.90%, sigma: 0.561798 mm).
2020-07-15T20:52:43.629Z,1594846363.629 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](IMPORTANT): Changing persisted config values to: 236.209915 cc buoyancy neutral and 4.768366 mm mass default
2020-07-15T20:52:43.630Z,1594846363.630 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](FAULT): Not allowing to overwrite existing Data/persisted.cfg after unclean shutdown.
2020-07-15T20:52:43.630Z,1594846363.630 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](FAULT): Not allowing to overwrite existing Data/persisted.cfg after unclean shutdown.
2020-07-15T20:52:43.630Z,1594846363.630 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2020-07-15T20:52:43.630Z,1594846363.630 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.] Stopped
2020-07-15T20:52:43.630Z,1594846363.630 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](INFO): Uninitializing BallastAndTrim.
2020-07-15T20:52:43.631Z,1594846363.631 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2020-07-15T20:52:43.631Z,1594846363.631 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth] Stopped
2020-07-15T20:52:43.631Z,1594846363.631 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2020-07-15T20:52:43.631Z,1594846363.631 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Stopped
2020-07-15T20:52:43.632Z,1594846363.632 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Uninitialize.
2020-07-15T20:52:43.632Z,1594846363.632 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Stopped
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Stopped
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Stopped
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Stopped
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Stopped
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Stopped
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Stopped
2020-07-15T20:52:43.633Z,1594846363.633 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Stopped
2020-07-15T20:52:44.068Z,1594846364.068 [ballast_and_trim:RunBallastAndTrim:Depth1:B](INFO): Completed ballast_and_trim:RunBallastAndTrim:Depth1:B
2020-07-15T20:52:44.068Z,1594846364.068 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Stopped
2020-07-15T20:52:44.068Z,1594846364.068 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2020-07-15T20:52:44.069Z,1594846364.069 [ballast_and_trim:RunBallastAndTrim:Depth1](INFO): Completed ballast_and_trim:RunBallastAndTrim:Depth1
2020-07-15T20:52:44.069Z,1594846364.069 [ballast_and_trim:RunBallastAndTrim:Depth1] Stopped
2020-07-15T20:52:44.069Z,1594846364.069 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1
2020-07-15T20:52:44.069Z,1594846364.069 [ballast_and_trim:RunBallastAndTrim:Depth2] Running Loop=1
2020-07-15T20:52:44.069Z,1594846364.069 [ballast_and_trim:RunBallastAndTrim:Depth2](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth2
2020-07-15T20:52:44.069Z,1594846364.069 [ballast_and_trim:RunBallastAndTrim:Depth2:A] Running Loop=1
2020-07-15T20:52:44.463Z,1594846364.463 [ballast_and_trim:RunBallastAndTrim:Depth2] Stopped
2020-07-15T20:52:44.463Z,1594846364.463 [ballast_and_trim:RunBallastAndTrim:Depth2](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth2
2020-07-15T20:52:44.463Z,1594846364.463 [ballast_and_trim:RunBallastAndTrim:Depth2:A] Stopped
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:RunBallastAndTrim](INFO): Completed ballast_and_trim:RunBallastAndTrim
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:RunBallastAndTrim] Stopped
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:Float_Up] Running Loop=1
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:Float_Up](DEBUG): Aggregate::initialize ballast_and_trim:Float_Up
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:Float_Up:A.Buoyancy] Running Loop=1
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Initialize Buoyancy Component.
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:Float_Up:B.Wait] Running Loop=1
2020-07-15T20:52:44.464Z,1594846364.464 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Initialize Wait Component.
2020-07-15T20:52:44.834Z,1594846364.834 [ballast_and_trim:Float_Up:A.Buoyancy] Running Loop=1
2020-07-15T20:52:48.476Z,1594846368.476 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:52:48.476Z,1594846368.476 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35,0000.0,1489.0,000
2020-07-15T20:52:52.122Z,1594846372.122 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:52:52.122Z,1594846372.122 [DVL_micro](ERROR): Failed to parse:
:TS,000000005.0,+17.0,0000.0,1489.0,000
2020-07-15T20:54:07.668Z,1594846447.668 [DVL_micro](ERROR): Failed to parse:
:B,+00000,+0000,I
2020-07-15T20:54:38.411Z,1594846478.411 [ballast_and_trim:Float_Up] Stopped
2020-07-15T20:54:38.412Z,1594846478.412 [ballast_and_trim:Float_Up](DEBUG): Aggregate::uninitialize ballast_and_trim:Float_Up
2020-07-15T20:54:38.412Z,1594846478.412 [ballast_and_trim:Float_Up:A.Buoyancy] Stopped
2020-07-15T20:54:38.412Z,1594846478.412 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2020-07-15T20:54:38.412Z,1594846478.412 [ballast_and_trim:Float_Up:B.Wait] Stopped
2020-07-15T20:54:38.412Z,1594846478.412 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T20:54:38.413Z,1594846478.413 [ballast_and_trim](INFO): Completed ballast_and_trim
2020-07-15T20:54:38.413Z,1594846478.413 [MissionManager](INFO): ballast_and_trim is completed.
2020-07-15T20:54:38.414Z,1594846478.414 [MissionManager](INFO): Uninitializing Mission ballast_and_trim
2020-07-15T20:54:38.414Z,1594846478.414 [ballast_and_trim] Stopped
2020-07-15T20:54:38.414Z,1594846478.414 [ballast_and_trim](DEBUG): Aggregate::uninitialize ballast_and_trim
2020-07-15T20:54:38.414Z,1594846478.414 [ballast_and_trim:Science] Stopped
2020-07-15T20:54:38.414Z,1594846478.414 [ballast_and_trim:Science](DEBUG): Aggregate::uninitialize ballast_and_trim:Science
2020-07-15T20:54:38.414Z,1594846478.414 [ballast_and_trim:Science:C] Stopped
2020-07-15T20:54:38.414Z,1594846478.414 [ballast_and_trim:Science:D] Stopped
2020-07-15T20:54:38.414Z,1594846478.414 [ballast_and_trim:Science:G] Stopped
2020-07-15T20:54:38.545Z,1594846478.545 [WetLabsBB2FL](INFO): Powering down
2020-07-15T20:54:38.794Z,1594846478.794 [MissionManager](IMPORTANT): Started mission Default
2020-07-15T20:54:38.794Z,1594846478.794 [Default] Running Loop=1
2020-07-15T20:54:38.795Z,1594846478.795 [Default](DEBUG): Aggregate::initialize Default
2020-07-15T20:54:38.795Z,1594846478.795 [Default:B.GoToSurface] Running Loop=1
2020-07-15T20:54:38.795Z,1594846478.795 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-07-15T20:54:38.795Z,1594846478.795 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-07-15T20:54:38.795Z,1594846478.795 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-07-15T20:54:38.796Z,1594846478.796 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-07-15T20:54:38.796Z,1594846478.796 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-07-15T20:54:38.796Z,1594846478.796 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-07-15T20:54:38.797Z,1594846478.797 [Default:A.Wait] Running Loop=1
2020-07-15T20:54:38.797Z,1594846478.797 [Default:A.Wait](DEBUG): Initialize Wait Component.
2020-07-15T20:54:38.857Z,1594846478.857 [Radio_Surface](INFO): Powering up
2020-07-15T20:54:44.229Z,1594846484.229 [DataOverHttps](INFO): Radio surface powered ON.
2020-07-15T20:54:52.118Z,1594846492.118 [Default:A.Wait](INFO): Done Waiting.
2020-07-15T20:54:52.119Z,1594846492.119 [Default:A.Wait] Stopped
2020-07-15T20:54:52.119Z,1594846492.119 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T20:54:52.588Z,1594846492.588 [Default:CheckIn] Running Loop=1
2020-07-15T20:54:52.588Z,1594846492.588 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T20:54:52.589Z,1594846492.589 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T20:54:56.534Z,1594846496.534 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T20:55:14.349Z,1594846514.349 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-07-15T20:55:39.763Z,1594846539.763 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:55:39.763Z,1594846539.763 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,489.0,000
2020-07-15T20:55:49.489Z,1594846549.489 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-07-15T20:55:57.985Z,1594846557.985 [BPC1](ERROR): Battery stick #6 (s/n: 00CA) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2020-07-15T20:55:57.986Z,1594846557.986 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 6.
2020-07-15T20:55:57.988Z,1594846557.988 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2020-07-15T20:56:07.642Z,1594846567.642 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.34,+0010.47,+0000.34,+0010.62
2020-07-15T20:56:24.630Z,1594846584.630 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-07-15T20:56:59.769Z,1594846619.769 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-07-15T20:57:34.909Z,1594846654.909 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2020-07-15T20:57:47.434Z,1594846667.434 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003686
2020-07-15T20:58:18.941Z,1594846698.941 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:58:18.941Z,1594846698.941 [DVL_micro](ERROR): Failed to parse:
:TS,000000005.0,+17.0,0000.0,1489.0,,+00209,-00169,-00068,+00000,A
2020-07-15T20:58:51.662Z,1594846731.662 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205403.00,A,3648.17179,N,12147.29680,W,1.147,336.54,150720,,,A*7D
2020-07-15T20:58:51.665Z,1594846731.665 [NAL9602](INFO): GPS fix at 20200715T205403: (36.802863, -121.788280)
2020-07-15T20:58:51.716Z,1594846731.716 [UniversalFixResidualReporter](INFO): Fix residual: 23.6 %DT, over the last 1185.6 m. Residual distance 280.3 m at bearing -119.3 degrees. Fix at (36.8029, -121.7883) with 25.7 m made good.
2020-07-15T20:58:51.716Z,1594846731.716 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T20:58:51.721Z,1594846731.721 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T20:58:57.809Z,1594846737.809 [DataOverHttps](INFO): Sending 217 bytes from file Logs/20200715T191818/Courier0031.lzma
2020-07-15T20:58:58.811Z,1594846738.811 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0031.lzma.bak
2020-07-15T20:58:58.811Z,1594846738.811 [DataOverHttps](INFO): SBD MOMSN=12442451
2020-07-15T20:59:12.283Z,1594846752.283 [DVL_micro](ERROR): Failed to parse:
:BI,-00596,+00057,+00216,+00000,A
2020-07-15T20:59:14.797Z,1594846754.797 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20200715T191818/Express0029.lzma
2020-07-15T20:59:15.798Z,1594846755.798 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0029.lzma.bak
2020-07-15T20:59:15.799Z,1594846755.799 [DataOverHttps](INFO): SBD MOMSN=12442454
2020-07-15T20:59:23.990Z,1594846763.990 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T20:59:31.803Z,1594846771.803 [DataOverHttps](INFO): Sending 928 bytes from file Logs/20200715T191818/Express0032.lzma
2020-07-15T20:59:32.802Z,1594846772.802 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0032.lzma.bak
2020-07-15T20:59:32.803Z,1594846772.803 [DataOverHttps](INFO): SBD MOMSN=12442458
2020-07-15T20:59:34.112Z,1594846774.112 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T20:59:34.113Z,1594846774.113 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T20:59:34.113Z,1594846774.113 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T20:59:36.508Z,1594846776.508 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T20:59:36.509Z,1594846776.509 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489.0,000
2020-07-15T21:00:57.722Z,1594846857.722 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:00:57.722Z,1594846857.722 [DVL_micro](ERROR): Failed to parse:
:BI,+00116,+00000,+00000,+000D,+00000000.00,+000,+00000000.20,000.+0000.32,+0010.47,+0000.34,+0010.73
2020-07-15T21:01:21.955Z,1594846881.955 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,0.00,0000.20,000.00
2020-07-15T21:02:13.665Z,1594846933.665 [DVL_micro](ERROR): Failed to parse:
:WI,-01720,+00000,+00000,+00000,I
2020-07-15T21:02:39.520Z,1594846959.520 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:02:39.520Z,1594846959.520 [DVL_micro](ERROR): Failed to parse:
:BI,-00086,+0587,+00000,A
2020-07-15T21:03:33.253Z,1594847013.253 [DVL_micro](ERROR): Failed to parse:
:WI,-01880,+00000,+00000,+00000,I
2020-07-15T21:03:59.112Z,1594847039.112 [DVL_micro](ERROR): Failed to parse:587,+0179,+00000,00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2020-07-15T21:04:24.964Z,1594847064.964 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:04:24.969Z,1594847064.969 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,489.0,000
2020-07-15T21:04:34.713Z,1594847074.713 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:04:34.713Z,1594847074.713 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:04:34.713Z,1594847074.713 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:04:34.713Z,1594847074.713 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:04:35.097Z,1594847075.097 [Default:CheckIn:D] Stopped
2020-07-15T21:04:35.097Z,1594847075.097 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:04:35.495Z,1594847075.495 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.938378 min 
2020-07-15T21:04:35.495Z,1594847075.495 [Default:CheckIn:E] Stopped
2020-07-15T21:04:35.496Z,1594847075.496 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:04:35.496Z,1594847075.496 [Default:CheckIn] Stopped
2020-07-15T21:04:35.496Z,1594847075.496 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:04:35.496Z,1594847075.496 [Default:CheckIn](INFO): Running loop #2
2020-07-15T21:04:35.496Z,1594847075.496 [Default:CheckIn] Running Loop=2
2020-07-15T21:04:35.496Z,1594847075.496 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:04:35.496Z,1594847075.496 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:04:37.492Z,1594847077.492 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205949.00,A,3648.15793,N,12147.28353,W,0.292,336.54,150720,,,A*7E
2020-07-15T21:04:37.494Z,1594847077.494 [NAL9602](INFO): GPS fix at 20200715T205949: (36.802632, -121.788059)
2020-07-15T21:04:37.535Z,1594847077.535 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:04:37.535Z,1594847077.535 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:04:44.756Z,1594847084.756 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0034.lzma
2020-07-15T21:04:45.759Z,1594847085.759 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0034.lzma.bak
2020-07-15T21:04:45.759Z,1594847085.759 [DataOverHttps](INFO): SBD MOMSN=12442479
2020-07-15T21:04:48.832Z,1594847088.832 [DVL_micro](ERROR): Failed to parse:
:WI,+00212,+00000,+00000,+00000,I
2020-07-15T21:05:02.080Z,1594847102.080 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20200715T191818/Express0035.lzma
2020-07-15T21:05:03.083Z,1594847103.083 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0035.lzma.bak
2020-07-15T21:05:03.083Z,1594847103.083 [DataOverHttps](INFO): SBD MOMSN=12442482
2020-07-15T21:05:04.621Z,1594847104.621 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:05:04.621Z,1594847104.621 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:05:04.622Z,1594847104.622 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:05:17.515Z,1594847117.515 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:05:17.516Z,1594847117.516 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:05:42.191Z,1594847142.191 [DVL_micro](ERROR): Failed to parse:
:WI,-00053,+00000,+00000,+00000,I
2020-07-15T21:06:08.429Z,1594847168.429 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:06:08.429Z,1594847168.429 [DVL_micro](ERROR): Failed to parse:
:BI,+0596,-00033,+0:BD,+00000000.00,+00000000.00,+00000000.00,0000.20,000.00
2020-07-15T21:07:00.127Z,1594847220.127 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:07:00.127Z,1594847220.127 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+17.0,00000,000
2020-07-15T21:07:25.989Z,1594847245.989 [DVL_micro](ERROR): Failed to parse:
:WI,+00092,+00000,+00000,+00000,I
2020-07-15T21:07:43.362Z,1594847263.362 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:07:43.362Z,1594847263.362 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:08:25.379Z,1594847305.379 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:08:25.379Z,1594847305.379 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:08:48.001Z,1594847328.001 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:08:48.001Z,1594847328.001 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:09:37.289Z,1594847377.289 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 372
2020-07-15T21:09:37.291Z,1594847377.291 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.0000.00,0000.20,000.00
2020-07-15T21:09:40.115Z,1594847380.115 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T21:10:05.197Z,1594847405.197 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:10:05.197Z,1594847405.197 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:10:05.197Z,1594847405.197 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:10:05.198Z,1594847405.198 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:10:05.602Z,1594847405.602 [Default:CheckIn:D] Stopped
2020-07-15T21:10:05.602Z,1594847405.602 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:10:05.994Z,1594847405.994 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 15.446782 min 
2020-07-15T21:10:05.994Z,1594847405.994 [Default:CheckIn:E] Stopped
2020-07-15T21:10:05.994Z,1594847405.994 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:10:05.994Z,1594847405.994 [Default:CheckIn] Stopped
2020-07-15T21:10:05.994Z,1594847405.994 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:10:05.995Z,1594847405.995 [Default:CheckIn](INFO): Running loop #3
2020-07-15T21:10:05.995Z,1594847405.995 [Default:CheckIn] Running Loop=3
2020-07-15T21:10:05.995Z,1594847405.995 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:10:05.995Z,1594847405.995 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:10:07.993Z,1594847407.993 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210519.00,A,3648.15971,N,12147.27360,W,2.158,104.06,150720,,,A*7D
2020-07-15T21:10:07.995Z,1594847407.995 [NAL9602](INFO): GPS fix at 20200715T210519: (36.802662, -121.787893)
2020-07-15T21:10:08.025Z,1594847408.025 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:10:08.025Z,1594847408.025 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:10:15.232Z,1594847415.232 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0037.lzma
2020-07-15T21:10:16.234Z,1594847416.234 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0037.lzma.bak
2020-07-15T21:10:16.235Z,1594847416.235 [DataOverHttps](INFO): SBD MOMSN=12442485
2020-07-15T21:10:32.385Z,1594847432.385 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20200715T191818/Express0038.lzma
2020-07-15T21:10:33.386Z,1594847433.386 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0038.lzma.bak
2020-07-15T21:10:33.387Z,1594847433.387 [DataOverHttps](INFO): SBD MOMSN=12442488
2020-07-15T21:10:34.713Z,1594847434.713 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:10:34.713Z,1594847434.713 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:10:34.714Z,1594847434.714 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:10:40.307Z,1594847440.307 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T21:11:22.736Z,1594847482.736 [DVL_micro](ERROR): only read 2 of 4 data items
2020-07-15T21:11:22.736Z,1594847482.736 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.320,+0000..74
2020-07-15T21:11:50.228Z,1594847510.228 [DVL_micro](ERROR): Failed to parse:
:SA,-04.40,+00.62,054.2
2020-07-15T21:13:06.150Z,1594847586.150 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:13:06.150Z,1594847586.150 [DVL_micro](ERROR): Failed to parse:
:TS,000000,35,0000.0,1489.0,000
2020-07-15T21:13:59.888Z,1594847639.888 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:13:59.888Z,1594847639.888 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+00000.34,+0010.70
2020-07-15T21:14:25.743Z,1594847665.743 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:14:25.743Z,1594847665.743 [DVL_micro](ERROR): Failed to parse:
:BI,+00701,-00670,-00263,+00BD,+0000000000000.00,0.00,0000.20,000.00
2020-07-15T21:15:17.463Z,1594847717.463 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:15:17.463Z,1594847717.463 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0,1489:WI,+00599,+0000,+00000,I
2020-07-15T21:15:35.273Z,1594847735.273 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:15:35.274Z,1594847735.274 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:15:35.274Z,1594847735.274 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:15:35.274Z,1594847735.274 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:15:35.676Z,1594847735.676 [Default:CheckIn:D] Stopped
2020-07-15T21:15:35.676Z,1594847735.676 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.948016 min 
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn:E] Stopped
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn] Stopped
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn](INFO): Running loop #4
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn] Running Loop=4
2020-07-15T21:15:36.067Z,1594847736.067 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:15:36.068Z,1594847736.068 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:15:38.065Z,1594847738.065 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211049.00,A,3648.16267,N,12147.28254,W,0.330,104.06,150720,,,A*74
2020-07-15T21:15:38.067Z,1594847738.067 [NAL9602](INFO): GPS fix at 20200715T211049: (36.802711, -121.788042)
2020-07-15T21:15:38.093Z,1594847738.093 [UniversalFixResidualReporter](INFO): Fix residual: 11.1 %DT, over the last 546.2 m. Residual distance 60.4 m at bearing 149.6 degrees. Fix at (36.8027, -121.7880) with 14.4 m made good.
2020-07-15T21:15:38.094Z,1594847738.094 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:15:38.094Z,1594847738.094 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:15:43.312Z,1594847743.312 [DVL_micro](ERROR): Failed to parse:
:T00000000,.0,0000.0000
2020-07-15T21:15:45.252Z,1594847745.252 [DataOverHttps](INFO): Sending 83 bytes from file Logs/20200715T191818/Courier0040.lzma
2020-07-15T21:15:46.254Z,1594847746.254 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0040.lzma.bak
2020-07-15T21:15:46.255Z,1594847746.255 [DataOverHttps](INFO): SBD MOMSN=12442503
2020-07-15T21:16:02.417Z,1594847762.417 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20200715T191818/Express0041.lzma
2020-07-15T21:16:03.419Z,1594847763.419 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0041.lzma.bak
2020-07-15T21:16:03.419Z,1594847763.419 [DataOverHttps](INFO): SBD MOMSN=12442506
2020-07-15T21:16:04.754Z,1594847764.754 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:16:04.754Z,1594847764.754 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:16:04.754Z,1594847764.754 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:16:08.763Z,1594847768.763 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-07-15T21:16:08.841Z,1594847768.841 [NAL9602](FAULT): received: 
+CSQ:0

OK4, 2, 0, 0, 0

OK
2020-07-15T21:16:08.841Z,1594847768.841 [NAL9602] Data Fault, FailCount= 1
2020-07-15T21:16:08.841Z,1594847768.841 [NAL9602](ERROR): Data Fault
2020-07-15T21:16:08.945Z,1594847768.945 [CBIT](ERROR): Data Fault in component: NAL9602
2020-07-15T21:16:09.179Z,1594847769.179 [NAL9602](INFO): Powering down
2020-07-15T21:16:10.002Z,1594847770.002 [CBIT](INFO): Clearing failed state for component NAL9602
2020-07-15T21:16:10.002Z,1594847770.002 [NAL9602] No Fault, FailCount= 1
2020-07-15T21:16:39.466Z,1594847799.466 [NAL9602](INFO): Powering up NAL9602
2020-07-15T21:16:50.369Z,1594847810.369 [NAL9602](INFO): NAL9602 initialized
2020-07-15T21:17:21.478Z,1594847841.478 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T21:17:28.758Z,1594847848.758 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:17:28.758Z,1594847848.758 [DVL_micro](ERROR): Failed to parse:
:BI,-00451,-00553,+0000,A
2020-07-15T21:18:20.468Z,1594847900.468 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:18:20.468Z,1594847900.468 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489.0,000
2020-07-15T21:19:12.174Z,1594847952.174 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:19:12.174Z,1594847952.174 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0,10
2020-07-15T21:20:33.390Z,1594848033.390 [DVL_micro](ERROR): Failed to parse:
:.32,+00100.34,+0010.78
2020-07-15T21:21:05.336Z,1594848065.336 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:21:05.336Z,1594848065.336 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:21:05.337Z,1594848065.337 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:21:05.337Z,1594848065.337 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:21:05.737Z,1594848065.737 [Default:CheckIn:D] Stopped
2020-07-15T21:21:05.737Z,1594848065.737 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:21:06.125Z,1594848066.125 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.449040 min 
2020-07-15T21:21:06.125Z,1594848066.125 [Default:CheckIn:E] Stopped
2020-07-15T21:21:06.125Z,1594848066.125 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:21:06.125Z,1594848066.125 [Default:CheckIn] Stopped
2020-07-15T21:21:06.125Z,1594848066.125 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:21:06.125Z,1594848066.125 [Default:CheckIn](INFO): Running loop #5
2020-07-15T21:21:06.126Z,1594848066.126 [Default:CheckIn] Running Loop=5
2020-07-15T21:21:06.126Z,1594848066.126 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:21:06.126Z,1594848066.126 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:21:09.743Z,1594848069.743 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T21:21:23.484Z,1594848083.484 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:21:23.484Z,1594848083.484 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+0010.54,+00010.69
2020-07-15T21:21:43.676Z,1594848103.676 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211655.00,A,3648.16231,N,12147.28667,W,0.292,10.30,150720,,,A*40
2020-07-15T21:21:43.678Z,1594848103.678 [NAL9602](INFO): GPS fix at 20200715T211655: (36.802705, -121.788111)
2020-07-15T21:21:43.703Z,1594848103.703 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:21:43.703Z,1594848103.703 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:21:50.752Z,1594848110.752 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0043.lzma
2020-07-15T21:21:51.755Z,1594848111.755 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0043.lzma.bak
2020-07-15T21:21:51.755Z,1594848111.755 [DataOverHttps](INFO): SBD MOMSN=12442510
2020-07-15T21:22:07.765Z,1594848127.765 [DataOverHttps](INFO): Sending 245 bytes from file Logs/20200715T191818/Express0044.lzma
2020-07-15T21:22:08.767Z,1594848128.767 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0044.lzma.bak
2020-07-15T21:22:08.767Z,1594848128.767 [DataOverHttps](INFO): SBD MOMSN=12442517
2020-07-15T21:22:10.087Z,1594848130.087 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:22:10.087Z,1594848130.087 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:22:10.087Z,1594848130.087 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:22:10.869Z,1594848130.869 [DVL_micro](ERROR): Failed to parse:
:SA,-04.40,+00.62,056.5
2020-07-15T21:22:16.106Z,1594848136.106 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T21:22:35.096Z,1594848155.096 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:22:35.096Z,1594848155.096 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+17.0,009.0,000
2020-07-15T21:23:00.956Z,1594848180.956 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:23:00.956Z,1594848180.956 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+17.0,00000,000
2020-07-15T21:23:52.666Z,1594848232.666 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:23:52.666Z,1594848232.666 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0,1489.WI,-00760+00000,+00000,I
2020-07-15T21:24:18.520Z,1594848258.520 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:24:18.533Z,1594848258.533 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.0,0000.0,1489.0,000
2020-07-15T21:25:38.107Z,1594848338.107 [DVL_micro](ERROR): only read 2 of 4 data items
2020-07-15T21:25:38.107Z,1594848338.107 [DVL_micro](ERROR): Failed to parse:
:RD,+00010.54,+0000..78
2020-07-15T21:26:55.676Z,1594848415.676 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:26:55.676Z,1594848415.676 [DVL_micro](ERROR): Failed to parse:
:TS,000000000.0,+17.0,0000.,000
2020-07-15T21:27:10.662Z,1594848430.662 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:27:10.662Z,1594848430.662 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:27:10.662Z,1594848430.662 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:27:10.662Z,1594848430.662 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:27:11.047Z,1594848431.047 [Default:CheckIn:D] Stopped
2020-07-15T21:27:11.047Z,1594848431.047 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.537526 min 
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn:E] Stopped
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn] Stopped
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn](INFO): Running loop #6
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn] Running Loop=6
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:27:11.470Z,1594848431.470 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:27:13.455Z,1594848433.455 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212225.00,A,3648.16267,N,12147.28108,W,0.661,206.92,150720,,,A*78
2020-07-15T21:27:13.458Z,1594848433.458 [NAL9602](INFO): GPS fix at 20200715T212225: (36.802711, -121.788018)
2020-07-15T21:27:13.512Z,1594848433.512 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:27:13.512Z,1594848433.512 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:27:21.516Z,1594848441.516 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0046.lzma
2020-07-15T21:27:22.519Z,1594848442.519 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0046.lzma.bak
2020-07-15T21:27:22.519Z,1594848442.519 [DataOverHttps](INFO): SBD MOMSN=12442527
2020-07-15T21:27:38.764Z,1594848458.764 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20200715T191818/Express0047.lzma
2020-07-15T21:27:39.766Z,1594848459.766 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0047.lzma.bak
2020-07-15T21:27:39.767Z,1594848459.767 [DataOverHttps](INFO): SBD MOMSN=12442530
2020-07-15T21:27:41.355Z,1594848461.355 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:27:41.355Z,1594848461.355 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:27:41.355Z,1594848461.355 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:27:47.390Z,1594848467.390 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:27:47.390Z,1594848467.390 [DVL_micro](ERROR): Failed to parse:
:BI,-00284,-00539,-00035A
2020-07-15T21:28:13.245Z,1594848493.245 [DVL_micro](ERROR): Failed to parse:
:WI,-00331,+00000,+00000,+00000,I
2020-07-15T21:28:39.105Z,1594848519.105 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:28:39.106Z,1594848519.106 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,489.0,000
2020-07-15T21:29:30.814Z,1594848570.814 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:29:30.814Z,1594848570.814 [DVL_micro](ERROR): Failed to parse:
:BI,+00050,+04298,+00903,+

2020-07-15T21:29:58.690Z,1594848598.690 [DVL_micro](ERROR): Failed to parse:
:BD,+0000000000000.00,+.00,000000
2020-07-15T21:30:24.541Z,1594848624.541 [DVL_micro](ERROR): Failed to parse:
:BD,+0000000000000.00,+00000000.00,0000.20,000.00
2020-07-15T21:30:50.405Z,1594848650.405 [DVL_micro](ERROR): only read 2 of 4 data items
2020-07-15T21:30:50.405Z,1594848650.405 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+0010.55,,+0010.74
2020-07-15T21:31:16.256Z,1594848676.256 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:31:16.256Z,1594848676.256 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,009.0,000
2020-07-15T21:31:42.108Z,1594848702.108 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.0000.00,+.00,0000.20,000.00
2020-07-15T21:31:48.976Z,1594848708.976 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:31:48.977Z,1594848708.977 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:32:07.968Z,1594848727.968 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:32:07.969Z,1594848727.969 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000+17.0,000.0,000
2020-07-15T21:32:16.051Z,1594848736.051 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T21:32:41.928Z,1594848761.928 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:32:41.928Z,1594848761.928 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:32:41.928Z,1594848761.928 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:32:41.928Z,1594848761.928 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:32:42.344Z,1594848762.344 [Default:CheckIn:D] Stopped
2020-07-15T21:32:42.344Z,1594848762.344 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:32:42.738Z,1594848762.738 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.059159 min 
2020-07-15T21:32:42.738Z,1594848762.738 [Default:CheckIn:E] Stopped
2020-07-15T21:32:42.738Z,1594848762.738 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:32:42.738Z,1594848762.738 [Default:CheckIn] Stopped
2020-07-15T21:32:42.738Z,1594848762.738 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:32:42.738Z,1594848762.738 [Default:CheckIn](INFO): Running loop #7
2020-07-15T21:32:42.738Z,1594848762.738 [Default:CheckIn] Running Loop=7
2020-07-15T21:32:42.739Z,1594848762.739 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:32:42.739Z,1594848762.739 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:32:44.728Z,1594848764.728 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212756.00,A,3648.16306,N,12147.27989,W,0.156,160.77,150720,,,A*7A
2020-07-15T21:32:44.730Z,1594848764.730 [NAL9602](INFO): GPS fix at 20200715T212756: (36.802718, -121.787998)
2020-07-15T21:32:44.772Z,1594848764.772 [UniversalFixResidualReporter](INFO): Fix residual: 69.7 %DT, over the last 823.8 m. Residual distance 574.5 m at bearing 79.6 degrees. Fix at (36.8027, -121.7880) with 1.9 m made good.
2020-07-15T21:32:44.772Z,1594848764.772 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:32:44.772Z,1594848764.772 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:32:51.872Z,1594848771.872 [DataOverHttps](INFO): Sending 81 bytes from file Logs/20200715T191818/Courier0049.lzma
2020-07-15T21:32:52.887Z,1594848772.887 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0049.lzma.bak
2020-07-15T21:32:52.887Z,1594848772.887 [DataOverHttps](INFO): SBD MOMSN=12442535
2020-07-15T21:33:09.137Z,1594848789.137 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20200715T191818/Express0050.lzma
2020-07-15T21:33:10.139Z,1594848790.139 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0050.lzma.bak
2020-07-15T21:33:10.139Z,1594848790.139 [DataOverHttps](INFO): SBD MOMSN=12442543
2020-07-15T21:33:11.448Z,1594848791.448 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:33:11.448Z,1594848791.448 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:33:11.449Z,1594848791.449 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:33:17.044Z,1594848797.044 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T21:33:27.560Z,1594848807.560 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:33:27.561Z,1594848807.561 [DVL_micro](ERROR): Failed to parse:
:RD,+0000.32,+0010.52,+00010.80
2020-07-15T21:34:19.267Z,1594848859.267 [DVL_micro](ERROR): Failed to parse:
:T00000000,35.0000.0,1489.0,000
2020-07-15T21:35:36.832Z,1594848936.832 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:35:36.832Z,1594848936.832 [DVL_micro](ERROR): Failed to parse::TS,000000005.0,+17.01489.0,000
2020-07-15T21:36:04.321Z,1594848964.321 [DVL_micro](ERROR): Failed to parse:
:BI,-00301,-00575,-00075,+00000,A
2020-07-15T21:37:20.260Z,1594849040.260 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:37:20.260Z,1594849040.260 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0000
2020-07-15T21:38:11.988Z,1594849091.988 [DVL_micro](ERROR): Failed to parse:
:000000000,35.0,+17.0,0000.0,1489.0,000
2020-07-15T21:38:12.030Z,1594849092.030 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:38:12.031Z,1594849092.031 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:38:12.031Z,1594849092.031 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:38:12.031Z,1594849092.031 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:38:12.401Z,1594849092.401 [Default:CheckIn:D] Stopped
2020-07-15T21:38:12.401Z,1594849092.401 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:38:12.825Z,1594849092.825 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.560111 min 
2020-07-15T21:38:12.825Z,1594849092.825 [Default:CheckIn:E] Stopped
2020-07-15T21:38:12.826Z,1594849092.826 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:38:12.826Z,1594849092.826 [Default:CheckIn] Stopped
2020-07-15T21:38:12.826Z,1594849092.826 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:38:12.826Z,1594849092.826 [Default:CheckIn](INFO): Running loop #8
2020-07-15T21:38:12.826Z,1594849092.826 [Default:CheckIn] Running Loop=8
2020-07-15T21:38:12.826Z,1594849092.826 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:38:12.826Z,1594849092.826 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:38:14.799Z,1594849094.799 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213326.00,A,3648.16522,N,12147.28097,W,0.156,160.77,150720,,,A*71
2020-07-15T21:38:14.801Z,1594849094.801 [NAL9602](INFO): GPS fix at 20200715T213326: (36.802754, -121.788016)
2020-07-15T21:38:14.846Z,1594849094.846 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:38:14.846Z,1594849094.846 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:38:17.651Z,1594849097.651 [DVL_micro](ERROR): Failed to parse:
:R32,+0010.54,+0000.34,+0010.70
2020-07-15T21:38:22.172Z,1594849102.172 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0052.lzma
2020-07-15T21:38:23.175Z,1594849103.175 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0052.lzma.bak
2020-07-15T21:38:23.175Z,1594849103.175 [DataOverHttps](INFO): SBD MOMSN=12442547
2020-07-15T21:38:39.732Z,1594849119.732 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20200715T191818/Express0053.lzma
2020-07-15T21:38:40.735Z,1594849120.735 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0053.lzma.bak
2020-07-15T21:38:40.735Z,1594849120.735 [DataOverHttps](INFO): SBD MOMSN=12442550
2020-07-15T21:38:42.300Z,1594849122.300 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:38:42.300Z,1594849122.300 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:38:42.300Z,1594849122.300 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:38:45.514Z,1594849125.514 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-07-15T21:38:45.597Z,1594849125.597 [NAL9602](FAULT): received: 
+CSQ:0

OK4, 2, 0, 0, 0

OK
2020-07-15T21:38:45.597Z,1594849125.597 [NAL9602] Data Fault, FailCount= 1
2020-07-15T21:38:45.597Z,1594849125.597 [NAL9602](ERROR): Data Fault
2020-07-15T21:38:45.701Z,1594849125.701 [CBIT](ERROR): Data Fault in component: NAL9602
2020-07-15T21:38:45.902Z,1594849125.902 [NAL9602](INFO): Powering down
2020-07-15T21:38:46.787Z,1594849126.787 [CBIT](INFO): Clearing failed state for component NAL9602
2020-07-15T21:38:46.788Z,1594849126.788 [NAL9602] No Fault, FailCount= 1
2020-07-15T21:39:05.704Z,1594849145.704 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:39:05.705Z,1594849145.705 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.0,0000.0,1489.0,000
2020-07-15T21:39:16.206Z,1594849156.206 [NAL9602](INFO): Powering up NAL9602
2020-07-15T21:39:27.114Z,1594849167.114 [NAL9602](INFO): NAL9602 initialized
2020-07-15T21:39:58.218Z,1594849198.218 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T21:40:49.124Z,1594849249.124 [DVL_micro](ERROR): only read 0 of 4 data items
2020-07-15T21:40:49.124Z,1594849249.124 [DVL_micro](ERROR): Failed to parse:
:BI-00688,-00365,+00000,A
2020-07-15T21:43:42.875Z,1594849422.875 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:43:42.875Z,1594849422.875 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:43:42.875Z,1594849422.875 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:43:42.876Z,1594849422.876 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:43:43.284Z,1594849423.284 [Default:CheckIn:D] Stopped
2020-07-15T21:43:43.284Z,1594849423.284 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:43:43.672Z,1594849423.672 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.074813 min 
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn:E] Stopped
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn] Stopped
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn](INFO): Running loop #9
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn] Running Loop=9
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:43:43.673Z,1594849423.673 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:43:45.678Z,1594849425.678 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213856.00,A,3648.16099,N,12147.28506,W,0.078,239.66,150720,,,A*77
2020-07-15T21:43:45.681Z,1594849425.681 [NAL9602](INFO): GPS fix at 20200715T213856: (36.802683, -121.788084)
2020-07-15T21:43:45.706Z,1594849425.706 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:43:45.706Z,1594849425.706 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:43:47.691Z,1594849427.691 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T21:43:53.548Z,1594849433.548 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20200715T191818/Courier0055.lzma
2020-07-15T21:43:54.551Z,1594849434.551 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0055.lzma.bak
2020-07-15T21:43:54.551Z,1594849434.551 [DataOverHttps](INFO): SBD MOMSN=12442564
2020-07-15T21:44:10.845Z,1594849450.845 [DataOverHttps](INFO): Sending 170 bytes from file Logs/20200715T191818/Express0056.lzma
2020-07-15T21:44:11.847Z,1594849451.847 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0056.lzma.bak
2020-07-15T21:44:11.847Z,1594849451.847 [DataOverHttps](INFO): SBD MOMSN=12442567
2020-07-15T21:44:13.185Z,1594849453.185 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:44:13.185Z,1594849453.185 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:44:13.186Z,1594849453.186 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:44:18.394Z,1594849458.394 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T21:45:09.702Z,1594849509.702 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:45:09.702Z,1594849509.702 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0,148

2020-07-15T21:45:35.560Z,1594849535.560 [DVL_micro](ERROR): Failed to parse:
:WI,+01484,+00000,+00000,+00000,I
2020-07-15T21:46:27.271Z,1594849587.271 [DVL_micro](ERROR): Failed to parse:
:BI,+00665,-00260,+00110,+00000,A
2020-07-15T21:46:53.132Z,1594849613.132 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:46:53.132Z,1594849613.132 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,00000,000
2020-07-15T21:47:20.634Z,1594849640.634 [DVL_micro](ERROR): Failed to parse:
:WI,-01496,+00000,+00000,+00000,I
2020-07-15T21:47:44.839Z,1594849664.839 [DVL_micro](ERROR): Failed to parse:
:BI,+00378,-00532,-00108,+00000,A
2020-07-15T21:49:13.753Z,1594849753.753 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:49:13.753Z,1594849753.753 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:49:13.753Z,1594849753.753 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:49:13.754Z,1594849753.754 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:49:14.171Z,1594849754.171 [Default:CheckIn:D] Stopped
2020-07-15T21:49:14.171Z,1594849754.171 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:49:14.549Z,1594849754.549 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.589604 min 
2020-07-15T21:49:14.549Z,1594849754.549 [Default:CheckIn:E] Stopped
2020-07-15T21:49:14.549Z,1594849754.549 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:49:14.550Z,1594849754.550 [Default:CheckIn] Stopped
2020-07-15T21:49:14.550Z,1594849754.550 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:49:14.550Z,1594849754.550 [Default:CheckIn](INFO): Running loop #10
2020-07-15T21:49:14.550Z,1594849754.550 [Default:CheckIn] Running Loop=10
2020-07-15T21:49:14.550Z,1594849754.550 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:49:14.550Z,1594849754.550 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:49:16.555Z,1594849756.555 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214428.00,A,3648.16345,N,12147.28248,W,0.136,306.70,150720,,,A*7B
2020-07-15T21:49:16.557Z,1594849756.557 [NAL9602](INFO): GPS fix at 20200715T214428: (36.802724, -121.788041)
2020-07-15T21:49:16.581Z,1594849756.581 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:49:16.581Z,1594849756.581 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:49:24.312Z,1594849764.312 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0058.lzma
2020-07-15T21:49:25.314Z,1594849765.314 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0058.lzma.bak
2020-07-15T21:49:25.315Z,1594849765.315 [DataOverHttps](INFO): SBD MOMSN=12442571
2020-07-15T21:49:35.949Z,1594849775.949 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:49:35.949Z,1594849775.949 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:49:41.521Z,1594849781.521 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20200715T191818/Express0059.lzma
2020-07-15T21:49:42.523Z,1594849782.523 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0059.lzma.bak
2020-07-15T21:49:42.523Z,1594849782.523 [DataOverHttps](INFO): SBD MOMSN=12442575
2020-07-15T21:49:44.077Z,1594849784.077 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:49:44.077Z,1594849784.077 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:49:44.077Z,1594849784.077 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:49:56.141Z,1594849796.141 [DVL_micro](ERROR): Failed to parse:
:WI,+00923,+0000,+00000,I
2020-07-15T21:50:07.047Z,1594849807.047 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:50:07.047Z,1594849807.047 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:50:21.994Z,1594849821.994 [DVL_micro](ERROR): Failed to parse:
0000000000,35.0,+17.0,0000.0,1489.0,000
2020-07-15T21:50:23.248Z,1594849823.248 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:50:23.248Z,1594849823.248 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:51:14.520Z,1594849874.520 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:51:14.520Z,1594849874.520 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:51:31.496Z,1594849891.496 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:51:31.496Z,1594849891.496 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:51:39.564Z,1594849899.564 [DVL_micro](ERROR): only read 3 of 4 data items
2020-07-15T21:51:39.564Z,1594849899.564 [DVL_micro](ERROR): Failed to parse:
:BI,02629,-00466,+00000,A
2020-07-15T21:52:13.108Z,1594849933.108 [NAL9602](INFO): SBD MO Status=2, MOMSN=634, MT Status=2, MTMSN=0
2020-07-15T21:52:13.125Z,1594849933.125 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-07-15T21:53:50.864Z,1594850030.864 [DVL_micro](ERROR): Failed to parse:
:WI,+00106,+01889,+00763,+00000,A
2020-07-15T21:54:18.354Z,1594850058.354 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.0,0000.0,1489.0,000
2020-07-15T21:54:19.147Z,1594850059.147 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T21:54:42.580Z,1594850082.580 [DVL_micro](ERROR): Failed to parse:
:T00000000,35.0,+17.0,0000.0,1489.0,000
2020-07-15T21:54:44.629Z,1594850084.629 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T21:54:44.629Z,1594850084.629 [Default:CheckIn:C.Wait] Stopped
2020-07-15T21:54:44.629Z,1594850084.629 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T21:54:44.630Z,1594850084.630 [Default:CheckIn:D] Running Loop=1
2020-07-15T21:54:45.034Z,1594850085.034 [Default:CheckIn:D] Stopped
2020-07-15T21:54:45.034Z,1594850085.034 [Default:CheckIn:E] Running Loop=1
2020-07-15T21:54:45.441Z,1594850085.441 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.103988 min 
2020-07-15T21:54:45.441Z,1594850085.441 [Default:CheckIn:E] Stopped
2020-07-15T21:54:45.442Z,1594850085.442 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T21:54:45.442Z,1594850085.442 [Default:CheckIn] Stopped
2020-07-15T21:54:45.442Z,1594850085.442 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T21:54:45.442Z,1594850085.442 [Default:CheckIn](INFO): Running loop #11
2020-07-15T21:54:45.442Z,1594850085.442 [Default:CheckIn] Running Loop=11
2020-07-15T21:54:45.442Z,1594850085.442 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T21:54:45.442Z,1594850085.442 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T21:54:47.428Z,1594850087.428 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214959.00,A,3648.16315,N,12147.28083,W,0.525,306.70,150720,,,A*76
2020-07-15T21:54:47.430Z,1594850087.430 [NAL9602](INFO): GPS fix at 20200715T214959: (36.802719, -121.788014)
2020-07-15T21:54:47.476Z,1594850087.476 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T21:54:47.476Z,1594850087.476 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T21:54:55.152Z,1594850095.152 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0061.lzma
2020-07-15T21:54:56.155Z,1594850096.155 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0061.lzma.bak
2020-07-15T21:54:56.155Z,1594850096.155 [DataOverHttps](INFO): SBD MOMSN=12442586
2020-07-15T21:55:12.309Z,1594850112.309 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20200715T191818/Express0062.lzma
2020-07-15T21:55:13.311Z,1594850113.311 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0062.lzma.bak
2020-07-15T21:55:13.311Z,1594850113.311 [DataOverHttps](INFO): SBD MOMSN=12442589
2020-07-15T21:55:14.521Z,1594850114.521 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T21:55:14.521Z,1594850114.521 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T21:55:14.521Z,1594850114.521 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T21:55:20.168Z,1594850120.168 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T21:55:29.861Z,1594850129.861 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:55:29.861Z,1594850129.861 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+16.,1489.0,000
2020-07-15T21:56:07.837Z,1594850167.837 [DVL_micro](ERROR): Failed to parse:
:WI,+00000,+00000,+00000,+00000,I
2020-07-15T21:56:27.627Z,1594850187.627 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:56:27.627Z,1594850187.627 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+160,1489.0,0+00000,+00000,+00000,+00000,I
2020-07-15T21:56:36.105Z,1594850196.105 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:56:36.105Z,1594850196.105 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+0.0,1489:WI,+00000,+00000,+00000,+00000,I
2020-07-15T21:58:02.603Z,1594850282.603 [DAT](INFO): unknown deviceResponse_: Acoustic Wakeup

2020-07-15T21:58:03.029Z,1594850283.029 [DAT](INFO): commRate: 800
2020-07-15T21:58:38.947Z,1594850318.947 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T21:58:38.947Z,1594850318.947 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,00.0,1489.WI,+00149,-00101,-00288,+00000,A
2020-07-15T21:59:35.094Z,1594850375.094 [DVL_micro](ERROR): Failed to parse:000000000017.1,000.0,000
2020-07-15T22:00:15.135Z,1594850415.135 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T22:00:15.136Z,1594850415.136 [Default:CheckIn:C.Wait] Stopped
2020-07-15T22:00:15.136Z,1594850415.136 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T22:00:15.136Z,1594850415.136 [Default:CheckIn:D] Running Loop=1
2020-07-15T22:00:15.558Z,1594850415.558 [Default:CheckIn:D] Stopped
2020-07-15T22:00:15.558Z,1594850415.558 [Default:CheckIn:E] Running Loop=1
2020-07-15T22:00:15.929Z,1594850415.929 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.612724 min 
2020-07-15T22:00:15.929Z,1594850415.929 [Default:CheckIn:E] Stopped
2020-07-15T22:00:15.929Z,1594850415.929 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T22:00:15.929Z,1594850415.929 [Default:CheckIn] Stopped
2020-07-15T22:00:15.930Z,1594850415.930 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T22:00:15.930Z,1594850415.930 [Default:CheckIn](INFO): Running loop #12
2020-07-15T22:00:15.930Z,1594850415.930 [Default:CheckIn] Running Loop=12
2020-07-15T22:00:15.930Z,1594850415.930 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T22:00:15.930Z,1594850415.930 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T22:00:17.923Z,1594850417.923 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215529.00,A,3648.16361,N,12147.28340,W,0.544,229.64,150720,,,A*7D
2020-07-15T22:00:17.925Z,1594850417.925 [NAL9602](INFO): GPS fix at 20200715T215529: (36.802727, -121.788057)
2020-07-15T22:00:17.969Z,1594850417.969 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T22:00:17.970Z,1594850417.970 [Default:CheckIn:Read_Iridium] Running Loop=1
2020-07-15T22:00:25.300Z,1594850425.300 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20200715T191818/Courier0064.lzma
2020-07-15T22:00:26.303Z,1594850426.303 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Courier0064.lzma.bak
2020-07-15T22:00:26.303Z,1594850426.303 [DataOverHttps](INFO): SBD MOMSN=12442593
2020-07-15T22:00:33.680Z,1594850433.680 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T22:00:33.680Z,1594850433.680 [DVL_micro](ERROR): Failed to parse:
:TS,000000000.0,+17.1,0000.0,1489.0,000
2020-07-15T22:00:42.652Z,1594850442.652 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20200715T191818/Express0065.lzma
2020-07-15T22:00:43.655Z,1594850443.655 [DataOverHttps](INFO): Moved sent file to Logs/20200715T191818/Express0065.lzma.bak
2020-07-15T22:00:43.655Z,1594850443.655 [DataOverHttps](INFO): SBD MOMSN=12442596
2020-07-15T22:00:45.021Z,1594850445.021 [Default:CheckIn:Read_Iridium] Stopped
2020-07-15T22:00:45.021Z,1594850445.021 [Default:CheckIn:C.Wait] Running Loop=1
2020-07-15T22:00:45.021Z,1594850445.021 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-07-15T22:00:48.646Z,1594850448.646 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2020-07-15T22:00:48.721Z,1594850448.721 [NAL9602](FAULT): received: 
+CSQ:0

OK4, 2, 0, 0, 0

OK
2020-07-15T22:00:48.721Z,1594850448.721 [NAL9602] Data Fault, FailCount= 1
2020-07-15T22:00:48.721Z,1594850448.721 [NAL9602](ERROR): Data Fault
2020-07-15T22:00:48.834Z,1594850448.834 [CBIT](ERROR): Data Fault in component: NAL9602
2020-07-15T22:00:49.026Z,1594850449.026 [NAL9602](INFO): Powering down
2020-07-15T22:00:49.899Z,1594850449.899 [CBIT](INFO): Clearing failed state for component NAL9602
2020-07-15T22:00:49.899Z,1594850449.899 [NAL9602] No Fault, FailCount= 1
2020-07-15T22:01:14.486Z,1594850474.486 [DVL_micro](ERROR): Failed to parse:
:BD,+0000000000000.00,0.00,999.00
2020-07-15T22:01:19.340Z,1594850479.340 [NAL9602](INFO): Powering up NAL9602
2020-07-15T22:01:30.232Z,1594850490.232 [NAL9602](INFO): NAL9602 initialized
2020-07-15T22:02:01.342Z,1594850521.342 [NAL9602](INFO): Not Powering down - fast GPS
2020-07-15T22:04:33.255Z,1594850673.255 [DVL_micro](ERROR): Failed to parse:
:R99,+99999.99,+9999.99
2020-07-15T22:05:03.951Z,1594850703.951 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T22:05:03.951Z,1594850703.951 [DVL_micro](ERROR): Failed to parse::TS,00000000000000,35.0,+17.3,0000.0,1489:WI,+01689,-00005,+00027,+00000,A
2020-07-15T22:05:45.601Z,1594850745.601 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2020-07-15T22:05:45.601Z,1594850745.601 [Default:CheckIn:C.Wait] Stopped
2020-07-15T22:05:45.601Z,1594850745.601 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-07-15T22:05:45.602Z,1594850745.602 [Default:CheckIn:D] Running Loop=1
2020-07-15T22:05:45.996Z,1594850745.996 [Default:CheckIn:D] Stopped
2020-07-15T22:05:45.997Z,1594850745.997 [Default:CheckIn:E] Running Loop=1
2020-07-15T22:05:46.457Z,1594850746.457 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 71.120028 min 
2020-07-15T22:05:46.457Z,1594850746.457 [Default:CheckIn:E] Stopped
2020-07-15T22:05:46.457Z,1594850746.457 [Default:CheckIn](INFO): Completed Default:CheckIn
2020-07-15T22:05:46.458Z,1594850746.458 [Default:CheckIn] Stopped
2020-07-15T22:05:46.458Z,1594850746.458 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T22:05:46.458Z,1594850746.458 [Default:CheckIn](INFO): Running loop #13
2020-07-15T22:05:46.458Z,1594850746.458 [Default:CheckIn] Running Loop=13
2020-07-15T22:05:46.458Z,1594850746.458 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2020-07-15T22:05:46.458Z,1594850746.458 [Default:CheckIn:Read_GPS] Running Loop=1
2020-07-15T22:05:47.180Z,1594850747.180 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2020-07-15T22:05:47.180Z,1594850747.180 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+170,1489.0,,+00973,00020,+00000,A
2020-07-15T22:05:50.411Z,1594850750.411 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2020-07-15T22:06:53.452Z,1594850813.452 [DVL_micro](ERROR): Failed to parse:
:SA,-00.97,+12.93,157.2
2020-07-15T22:07:14.725Z,1594850834.725 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.735535
2020-07-15T22:07:24.138Z,1594850844.138 [DVL_micro](ERROR): Failed to parse:
:T00000000,.4,0000.,000
2020-07-15T22:07:24.543Z,1594850844.543 [CommandLine](IMPORTANT): got command failComponent
2020-07-15T22:07:24.543Z,1594850844.543 [CommandLine](IMPORTANT): Failed components:
2020-07-15T22:07:24.544Z,1594850844.544 [CommandLine](IMPORTANT): No failed Components.
2020-07-15T22:07:25.642Z,1594850845.642 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004089
2020-07-15T22:07:27.143Z,1594850847.143 [CommandLine](IMPORTANT): got command quit
2020-07-15T22:07:28.149Z,1594850848.149 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2020-07-15T22:07:28.151Z,1594850848.151 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:28.151Z,1594850848.151 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.189Z,1594850848.189 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2020-07-15T22:07:28.189Z,1594850848.189 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.189Z,1594850848.189 [CommandLine](INFO): Join timeout helper Thread ID is 1442
2020-07-15T22:07:28.190Z,1594850848.190 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2020-07-15T22:07:28.190Z,1594850848.190 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.191Z,1594850848.191 [NavChartDb](INFO): Join timeout helper Thread ID is 1443
2020-07-15T22:07:28.349Z,1594850848.349 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:28.349Z,1594850848.349 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.361Z,1594850848.361 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2020-07-15T22:07:28.361Z,1594850848.361 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.361Z,1594850848.361 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1444
2020-07-15T22:07:28.385Z,1594850848.385 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:28.385Z,1594850848.385 [WetLabsBB2FL](INFO): Powering down
2020-07-15T22:07:28.386Z,1594850848.386 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.401Z,1594850848.401 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2020-07-15T22:07:28.401Z,1594850848.401 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.401Z,1594850848.401 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1445
2020-07-15T22:07:28.769Z,1594850848.769 [CTD_Seabird](INFO): Powering down
2020-07-15T22:07:28.781Z,1594850848.781 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:28.781Z,1594850848.781 [CTD_Seabird](INFO): Powering down
2020-07-15T22:07:28.793Z,1594850848.793 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.805Z,1594850848.805 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2020-07-15T22:07:28.806Z,1594850848.806 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:28.807Z,1594850848.807 [Radio_Surface](INFO): Join timeout helper Thread ID is 1446
2020-07-15T22:07:29.141Z,1594850849.141 [Radio_Surface](INFO): Powering down
2020-07-15T22:07:29.142Z,1594850849.142 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:29.142Z,1594850849.142 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:29.146Z,1594850849.146 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2020-07-15T22:07:29.146Z,1594850849.146 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:29.146Z,1594850849.146 [DataOverHttps](INFO): Join timeout helper Thread ID is 1447
2020-07-15T22:07:29.653Z,1594850849.653 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:29.653Z,1594850849.653 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:29.669Z,1594850849.669 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2020-07-15T22:07:29.670Z,1594850849.670 [logger ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:29.670Z,1594850849.670 [logger](INFO): Join timeout helper Thread ID is 1448
2020-07-15T22:07:29.713Z,1594850849.713 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:29.713Z,1594850849.713 [logger ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:29.729Z,1594850849.729 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2020-07-15T22:07:29.729Z,1594850849.729 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:29.730Z,1594850849.730 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2020-07-15T22:07:29.730Z,1594850849.730 [controlThread ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:29.730Z,1594850849.730 [controlThread](INFO): Join timeout helper Thread ID is 1449
2020-07-15T22:07:29.777Z,1594850849.777 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2020-07-15T22:07:29.777Z,1594850849.777 [controlThread](DEBUG): Uninitializing ControlThread
2020-07-15T22:07:29.778Z,1594850849.778 [AHRS_M2](INFO): Powering down
2020-07-15T22:07:29.921Z,1594850849.921 [DVL_micro](INFO): Powering down
2020-07-15T22:07:29.922Z,1594850849.922 [NAL9602](INFO): Powering down
2020-07-15T22:07:29.923Z,1594850849.923 [DAT](INFO): Powering down
2020-07-15T22:07:30.042Z,1594850850.042 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2020-07-15T22:07:30.043Z,1594850850.043 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2020-07-15T22:07:30.043Z,1594850850.043 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2020-07-15T22:07:30.044Z,1594850850.044 [MissionManager](INFO): Uninitializing Mission Default
2020-07-15T22:07:30.044Z,1594850850.044 [Default] Stopped
2020-07-15T22:07:30.044Z,1594850850.044 [Default](DEBUG): Aggregate::uninitialize Default
2020-07-15T22:07:30.044Z,1594850850.044 [Default:B.GoToSurface] Stopped
2020-07-15T22:07:30.044Z,1594850850.044 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-07-15T22:07:30.044Z,1594850850.044 [Default:CheckIn] Stopped
2020-07-15T22:07:30.044Z,1594850850.044 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2020-07-15T22:07:30.044Z,1594850850.044 [Default:CheckIn:Read_GPS] Stopped
2020-07-15T22:07:30.047Z,1594850850.047 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2020-07-15T22:07:30.047Z,1594850850.047 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2020-07-15T22:07:30.047Z,1594850850.047 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2020-07-15T22:07:30.048Z,1594850850.048 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2020-07-15T22:07:30.048Z,1594850850.048 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2020-07-15T22:07:30.048Z,1594850850.048 [BuoyancyServo](INFO): Powering down
2020-07-15T22:07:30.061Z,1594850850.061 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2020-07-15T22:07:30.061Z,1594850850.061 [ElevatorServo](INFO): Powering down
2020-07-15T22:07:30.062Z,1594850850.062 [MassServo](DEBUG): Uninitialize Mass Servo.
2020-07-15T22:07:30.062Z,1594850850.062 [MassServo](INFO): Powering down
2020-07-15T22:07:30.063Z,1594850850.063 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2020-07-15T22:07:30.063Z,1594850850.063 [RudderServo](INFO): Powering down
2020-07-15T22:07:30.064Z,1594850850.064 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2020-07-15T22:07:30.064Z,1594850850.064 [ThrusterServo](INFO): Powering down
2020-07-15T22:07:30.064Z,1594850850.064 [SBIT](DEBUG): Uninitialize SBIT Component.
2020-07-15T22:07:30.065Z,1594850850.065 [IBIT](DEBUG): Uninitialize IBIT Component.
2020-07-15T22:07:30.065Z,1594850850.065 [CBIT](DEBUG): Uninitialize CBIT Component.
2020-07-15T22:07:30.065Z,1594850850.065 [CBIT](DEBUG): Powering off loads.
2020-07-15T22:07:30.077Z,1594850850.077 [CBIT](DEBUG): Disabling WDT.
2020-07-15T22:07:30.089Z,1594850850.089 [CBIT](DEBUG): Opening all GF detection circuits.
2020-07-15T22:07:30.089Z,1594850850.089 [controlThread ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:30.182Z,1594850850.182 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:30.190Z,1594850850.190 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:30.249Z,1594850850.249 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:30.252Z,1594850850.252 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:30.278Z,1594850850.278 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2020-07-15T22:07:30.349Z,1594850850.349 [logger ThreadHandler](INFO): Thread cancelled.