2019-09-23T19:48:06.245Z,1569268086.245 [Supervisor](DEBUG): Initializing supervisor.
2019-09-23T19:48:06.248Z,1569268086.248 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-09-23T19:48:06.248Z,1569268086.248 [SyncHandler](INFO): Protected caller Thread ID is 807
2019-09-23T19:48:06.249Z,1569268086.249 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-09-23T19:48:06.250Z,1569268086.250 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-09-23T19:48:06.250Z,1569268086.250 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 808
2019-09-23T19:48:06.253Z,1569268086.253 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-09-23T19:48:06.264Z,1569268086.264 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-09-23T19:48:06.265Z,1569268086.265 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-09-23T19:48:06.265Z,1569268086.265 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 809
2019-09-23T19:48:06.266Z,1569268086.266 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-09-23T19:48:06.267Z,1569268086.267 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-09-23T19:48:06.267Z,1569268086.267 [logger ThreadHandler](INFO): Protected caller Thread ID is 810
2019-09-23T19:48:06.269Z,1569268086.269 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-09-23T19:48:06.269Z,1569268086.269 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-09-23T19:48:06.273Z,1569268086.273 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-09-23T19:48:06.368Z,1569268086.368 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-09-23T19:48:06.370Z,1569268086.370 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-09-23T19:48:06.922Z,1569268086.922 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-09-23T19:48:06.924Z,1569268086.924 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-09-23T19:48:07.021Z,1569268087.021 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-09-23T19:48:07.023Z,1569268087.023 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-09-23T19:48:07.124Z,1569268087.124 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-09-23T19:48:07.126Z,1569268087.126 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-09-23T19:48:07.206Z,1569268087.206 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-09-23T19:48:07.342Z,1569268087.342 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-09-23T19:48:07.343Z,1569268087.343 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-09-23T19:48:07.633Z,1569268087.633 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-09-23T19:48:07.634Z,1569268087.634 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-09-23T19:48:08.084Z,1569268088.084 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-09-23T19:48:08.085Z,1569268088.085 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-09-23T19:48:08.229Z,1569268088.229 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-09-23T19:48:08.231Z,1569268088.231 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-09-23T19:48:08.428Z,1569268088.428 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-09-23T19:48:08.428Z,1569268088.428 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-09-23T19:48:08.876Z,1569268088.876 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-09-23T19:48:08.878Z,1569268088.878 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-09-23T19:48:09.088Z,1569268089.088 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-09-23T19:48:09.090Z,1569268089.090 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-09-23T19:48:09.289Z,1569268089.289 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-09-23T19:48:09.291Z,1569268089.291 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-09-23T19:48:09.682Z,1569268089.682 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-09-23T19:48:10.317Z,1569268090.317 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-09-23T19:48:11.031Z,1569268091.031 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-09-23T19:48:11.033Z,1569268091.033 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2019-09-23T19:48:11.036Z,1569268091.036 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2019-09-23T19:48:11.121Z,1569268091.121 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2019-09-23T19:48:11.276Z,1569268091.276 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2019-09-23T19:48:11.383Z,1569268091.383 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2019-09-23T19:48:11.469Z,1569268091.469 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2019-09-23T19:48:11.564Z,1569268091.564 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2019-09-23T19:48:11.755Z,1569268091.755 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2019-09-23T19:48:11.981Z,1569268091.981 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-09-23T19:48:11.982Z,1569268091.982 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2019-09-23T19:48:12.076Z,1569268092.076 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2019-09-23T19:48:12.173Z,1569268092.173 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2019-09-23T19:48:12.308Z,1569268092.308 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2019-09-23T19:48:12.407Z,1569268092.407 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-09-23T19:48:12.421Z,1569268092.421 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-09-23T19:48:12.509Z,1569268092.509 [VerticalControl](DEBUG): Construct VerticalControl.
2019-09-23T19:48:12.619Z,1569268092.619 [VerticalControl] Loaded
2019-09-23T19:48:12.619Z,1569268092.619 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-09-23T19:48:12.620Z,1569268092.620 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-09-23T19:48:12.687Z,1569268092.687 [HorizontalControl] Loaded
2019-09-23T19:48:12.687Z,1569268092.687 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-09-23T19:48:12.688Z,1569268092.688 [SpeedControl](DEBUG): Construct SpeedControl.
2019-09-23T19:48:12.694Z,1569268092.694 [SpeedControl] Loaded
2019-09-23T19:48:12.694Z,1569268092.694 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-09-23T19:48:12.695Z,1569268092.695 [LoopControl](DEBUG): Construct LoopControl.
2019-09-23T19:48:12.695Z,1569268092.695 [LoopControl] Loaded
2019-09-23T19:48:12.695Z,1569268092.695 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-09-23T19:48:12.696Z,1569268092.696 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-09-23T19:48:12.696Z,1569268092.696 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-09-23T19:48:12.751Z,1569268092.751 [DepthRateCalculator] Loaded
2019-09-23T19:48:12.751Z,1569268092.751 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-09-23T19:48:12.756Z,1569268092.756 [PitchRateCalculator] Loaded
2019-09-23T19:48:12.756Z,1569268092.756 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-09-23T19:48:12.772Z,1569268092.772 [SpeedCalculator] Loaded
2019-09-23T19:48:12.772Z,1569268092.772 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-09-23T19:48:12.793Z,1569268092.793 [TempGradientCalculator] Loaded
2019-09-23T19:48:12.793Z,1569268092.793 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-09-23T19:48:12.798Z,1569268092.798 [YawRateCalculator] Loaded
2019-09-23T19:48:12.798Z,1569268092.798 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-09-23T19:48:12.826Z,1569268092.826 [ElevatorOffsetCalculator] Loaded
2019-09-23T19:48:12.827Z,1569268092.827 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-09-23T19:48:12.827Z,1569268092.827 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-09-23T19:48:12.829Z,1569268092.829 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-09-23T19:48:12.877Z,1569268092.877 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-09-23T19:48:12.878Z,1569268092.878 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-09-23T19:48:12.988Z,1569268092.988 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-09-23T19:48:12.989Z,1569268092.989 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-09-23T19:48:13.317Z,1569268093.317 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-09-23T19:48:13.318Z,1569268093.318 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-09-23T19:48:13.440Z,1569268093.440 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-09-23T19:48:13.440Z,1569268093.440 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-09-23T19:48:13.941Z,1569268093.941 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-09-23T19:48:13.946Z,1569268093.946 [AHRS_M2](INFO): created writer for : platform_orientation
2019-09-23T19:48:13.948Z,1569268093.948 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-09-23T19:48:13.953Z,1569268093.953 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-09-23T19:48:13.953Z,1569268093.953 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-09-23T19:48:13.958Z,1569268093.958 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-09-23T19:48:13.959Z,1569268093.959 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-09-23T19:48:13.964Z,1569268093.964 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-09-23T19:48:14.140Z,1569268094.140 [AHRS_M2] Loaded
2019-09-23T19:48:14.141Z,1569268094.141 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-09-23T19:48:14.282Z,1569268094.282 [DataOverHttps] Loaded
2019-09-23T19:48:14.282Z,1569268094.282 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-09-23T19:48:14.283Z,1569268094.283 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408CA4E0
2019-09-23T19:48:14.284Z,1569268094.284 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 889
2019-09-23T19:48:14.297Z,1569268094.297 [Depth_Keller] Loaded
2019-09-23T19:48:14.297Z,1569268094.297 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-09-23T19:48:14.302Z,1569268094.302 [DropWeight] Loaded
2019-09-23T19:48:14.302Z,1569268094.302 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-09-23T19:48:14.397Z,1569268094.397 [NAL9602] Loaded
2019-09-23T19:48:14.398Z,1569268094.398 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-09-23T19:48:14.413Z,1569268094.413 [Onboard] Loaded
2019-09-23T19:48:14.413Z,1569268094.413 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-09-23T19:48:14.417Z,1569268094.417 [Radio_Surface] Loaded
2019-09-23T19:48:14.417Z,1569268094.417 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-09-23T19:48:14.418Z,1569268094.418 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408FA4E0
2019-09-23T19:48:14.418Z,1569268094.418 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 890
2019-09-23T19:48:14.462Z,1569268094.462 [RDI_Pathfinder] Loaded
2019-09-23T19:48:14.462Z,1569268094.462 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-09-23T19:48:14.585Z,1569268094.585 [DAT] Loaded
2019-09-23T19:48:14.586Z,1569268094.586 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-09-23T19:48:16.578Z,1569268096.578 [BPC1] Loaded
2019-09-23T19:48:16.578Z,1569268096.578 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-09-23T19:48:16.579Z,1569268096.579 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-09-23T19:48:16.579Z,1569268096.579 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-09-23T19:48:16.697Z,1569268096.697 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-09-23T19:48:16.698Z,1569268096.698 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-09-23T19:48:16.718Z,1569268096.718 [NavChart] Loaded
2019-09-23T19:48:16.718Z,1569268096.718 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-09-23T19:48:16.722Z,1569268096.722 [UniversalFixResidualReporter] Loaded
2019-09-23T19:48:16.723Z,1569268096.723 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-09-23T19:48:16.723Z,1569268096.723 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-09-23T19:48:16.724Z,1569268096.724 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-09-23T19:48:16.878Z,1569268096.878 [SBIT](DEBUG): Construct Startup Built In Test.
2019-09-23T19:48:16.889Z,1569268096.889 [SBIT] Loaded
2019-09-23T19:48:16.890Z,1569268096.890 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-09-23T19:48:16.890Z,1569268096.890 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-09-23T19:48:16.902Z,1569268096.902 [IBIT] Loaded
2019-09-23T19:48:16.902Z,1569268096.902 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-09-23T19:48:16.905Z,1569268096.905 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-09-23T19:48:17.043Z,1569268097.043 [CBIT] Loaded
2019-09-23T19:48:17.043Z,1569268097.043 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-09-23T19:48:17.043Z,1569268097.043 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-09-23T19:48:17.044Z,1569268097.044 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-09-23T19:48:17.168Z,1569268097.168 [BuoyancyServo] Loaded
2019-09-23T19:48:17.168Z,1569268097.168 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-09-23T19:48:17.180Z,1569268097.180 [ElevatorServo] Loaded
2019-09-23T19:48:17.180Z,1569268097.180 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-09-23T19:48:17.191Z,1569268097.191 [MassServo] Loaded
2019-09-23T19:48:17.191Z,1569268097.191 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-09-23T19:48:17.202Z,1569268097.202 [RudderServo] Loaded
2019-09-23T19:48:17.202Z,1569268097.202 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-09-23T19:48:17.213Z,1569268097.213 [ThrusterServo] Loaded
2019-09-23T19:48:17.213Z,1569268097.213 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-09-23T19:48:17.214Z,1569268097.214 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-09-23T19:48:17.214Z,1569268097.214 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-09-23T19:48:17.238Z,1569268097.238 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-09-23T19:48:17.240Z,1569268097.240 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-09-23T19:48:17.482Z,1569268097.482 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-09-23T19:48:17.487Z,1569268097.487 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-09-23T19:48:17.487Z,1569268097.487 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-09-23T19:48:17.492Z,1569268097.492 [CTD_Seabird](INFO): created writer for : depth
2019-09-23T19:48:17.493Z,1569268097.493 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-09-23T19:48:17.498Z,1569268097.498 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-09-23T19:48:17.498Z,1569268097.498 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-09-23T19:48:17.503Z,1569268097.503 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-09-23T19:48:17.504Z,1569268097.504 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-09-23T19:48:17.509Z,1569268097.509 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-09-23T19:48:17.510Z,1569268097.510 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-09-23T19:48:17.515Z,1569268097.515 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-09-23T19:48:17.515Z,1569268097.515 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-09-23T19:48:17.520Z,1569268097.520 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-09-23T19:48:17.548Z,1569268097.548 [CTD_Seabird] Loaded
2019-09-23T19:48:17.548Z,1569268097.548 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-09-23T19:48:17.549Z,1569268097.549 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A7F4E0
2019-09-23T19:48:17.549Z,1569268097.549 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 891
2019-09-23T19:48:17.556Z,1569268097.556 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470
2019-09-23T19:48:17.556Z,1569268097.556 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470
2019-09-23T19:48:17.561Z,1569268097.561 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650
2019-09-23T19:48:17.561Z,1569268097.561 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650
2019-09-23T19:48:17.565Z,1569268097.565 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl
2019-09-23T19:48:17.565Z,1569268097.565 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl
2019-09-23T19:48:17.570Z,1569268097.570 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm
2019-09-23T19:48:17.570Z,1569268097.570 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm
2019-09-23T19:48:17.574Z,1569268097.574 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm
2019-09-23T19:48:17.574Z,1569268097.574 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm
2019-09-23T19:48:17.579Z,1569268097.579 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm
2019-09-23T19:48:17.579Z,1569268097.579 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm
2019-09-23T19:48:17.583Z,1569268097.583 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm
2019-09-23T19:48:17.583Z,1569268097.583 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm
2019-09-23T19:48:17.587Z,1569268097.587 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.592Z,1569268097.592 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.592Z,1569268097.592 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.592Z,1569268097.592 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.596Z,1569268097.596 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.597Z,1569268097.597 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.601Z,1569268097.601 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.601Z,1569268097.601 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2019-09-23T19:48:17.605Z,1569268097.605 [WetLabsBB2FL] Loaded
2019-09-23T19:48:17.606Z,1569268097.606 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-09-23T19:48:17.607Z,1569268097.607 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40AAF4E0
2019-09-23T19:48:17.607Z,1569268097.607 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 892
2019-09-23T19:48:17.842Z,1569268097.842 [WetLabsUBAT..SerialDriver](INFO): Created logger
2019-09-23T19:48:17.843Z,1569268097.843 [WetLabsUBAT..SerialDriver](INFO): publishing on LCM channel WetLabsUBAT
2019-09-23T19:48:17.843Z,1569268097.843 [WetLabsUBAT..StreamSerialDriver](INFO): Created logger
2019-09-23T19:48:17.845Z,1569268097.845 [WetLabsUBAT](INFO): in readConfig
2019-09-23T19:48:17.848Z,1569268097.848 [WetLabsUBAT](INFO): readConfig(): serialNo_: UBAT0051, uartName_: /dev/ttyC1, optionalArgs_: -ldir /mnt/mmc/LRAUV/Logs/latest
2019-09-23T19:48:17.849Z,1569268097.849 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsUBAT.biolum_potential
2019-09-23T19:48:17.849Z,1569268097.849 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(): dataName: biolum_potential
2019-09-23T19:48:17.853Z,1569268097.853 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsUBAT.flow_rate
2019-09-23T19:48:17.854Z,1569268097.854 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(): dataName: flow_rate
2019-09-23T19:48:17.858Z,1569268097.858 [WetLabsUBAT] Loaded
2019-09-23T19:48:17.858Z,1569268097.858 [ComponentRegistry](DEBUG): Component "WetLabsUBAT" handled in its own thread.
2019-09-23T19:48:17.859Z,1569268097.859 [WetLabsUBAT ThreadHandler](DEBUG): Created PCaller Thread at 40ADF4E0
2019-09-23T19:48:17.860Z,1569268097.860 [WetLabsUBAT ThreadHandler](INFO): Protected caller Thread ID is 893
2019-09-23T19:48:17.860Z,1569268097.860 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-09-23T19:48:17.864Z,1569268097.864 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-09-23T19:48:17.865Z,1569268097.865 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-09-23T19:48:17.871Z,1569268097.871 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-09-23T19:48:17.872Z,1569268097.872 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B0F4E0
2019-09-23T19:48:17.873Z,1569268097.873 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 894
2019-09-23T19:48:17.877Z,1569268097.877 [Supervisor](INFO): Main Thread ID is 803
2019-09-23T19:48:17.877Z,1569268097.877 [Supervisor](DEBUG): Running supervisor.
2019-09-23T19:48:17.878Z,1569268097.878 [CommandLine ThreadHandler](INFO): Handler Thread ID is 895
2019-09-23T19:48:17.881Z,1569268097.881 [controlThread ThreadHandler](INFO): Handler Thread ID is 896
2019-09-23T19:48:17.881Z,1569268097.881 [controlThread](DEBUG): Initializing ControlThread
2019-09-23T19:48:17.882Z,1569268097.882 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-09-23T19:48:17.884Z,1569268097.884 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-09-23T19:48:17.884Z,1569268097.884 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-09-23T19:48:17.885Z,1569268097.885 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-09-23T19:48:17.885Z,1569268097.885 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-09-23T19:48:17.885Z,1569268097.885 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-09-23T19:48:17.886Z,1569268097.886 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-09-23T19:48:17.886Z,1569268097.886 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-09-23T19:48:17.887Z,1569268097.887 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-09-23T19:48:17.887Z,1569268097.887 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-09-23T19:48:17.894Z,1569268097.894 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-09-23T19:48:17.895Z,1569268097.895 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-09-23T19:48:17.895Z,1569268097.895 [SBIT](INFO): Initialize SBIT Component.
2019-09-23T19:48:17.895Z,1569268097.895 [SBIT](IMPORTANT): git: 2019-09-10-15-gf9f7781
2019-09-23T19:48:17.896Z,1569268097.896 [SBIT](INFO): git hash: f9f7781fb6d86741f33ee9b3258f94ce1a6d26dc
2019-09-23T19:48:17.896Z,1569268097.896 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-09-23T19:48:17.896Z,1569268097.896 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-09-23T19:48:17.897Z,1569268097.897 [SBIT](INFO): Beginning SBIT in 59.000000 seconds.
2019-09-23T19:48:17.898Z,1569268097.898 [IBIT](INFO): Initialize IBIT Component.
2019-09-23T19:48:17.898Z,1569268097.898 [CBIT](DEBUG): Initialize CBIT Component.
2019-09-23T19:48:17.900Z,1569268097.900 [logger ThreadHandler](INFO): Handler Thread ID is 897
2019-09-23T19:48:17.911Z,1569268097.911 [CBIT](DEBUG): Initialized mux pins.
2019-09-23T19:48:17.911Z,1569268097.911 [CBIT](DEBUG): Initializing the watchdog timer.
2019-09-23T19:48:17.920Z,1569268097.920 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 898
2019-09-23T19:48:17.921Z,1569268097.921 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-09-23T19:48:17.932Z,1569268097.932 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 899
2019-09-23T19:48:17.935Z,1569268097.935 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-09-23T19:48:17.935Z,1569268097.935 [CBIT](DEBUG): Initializing heartbeat.
2019-09-23T19:48:17.944Z,1569268097.944 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 900
2019-09-23T19:48:17.944Z,1569268097.944 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-09-23T19:48:17.948Z,1569268097.948 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-09-23T19:48:17.949Z,1569268097.949 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 902
2019-09-23T19:48:17.950Z,1569268097.950 [WetLabsBB2FL](INFO): Powering down
2019-09-23T19:48:17.980Z,1569268097.980 [WetLabsUBAT ThreadHandler](INFO): Handler Thread ID is 903
2019-09-23T19:48:17.992Z,1569268097.992 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 904
2019-09-23T19:48:18.001Z,1569268098.001 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-09-23T19:48:18.001Z,1569268098.001 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-09-23T19:48:18.002Z,1569268098.002 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-09-23T19:48:18.002Z,1569268098.002 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-09-23T19:48:18.002Z,1569268098.002 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-09-23T19:48:18.002Z,1569268098.002 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-09-23T19:48:18.002Z,1569268098.002 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-09-23T19:48:18.002Z,1569268098.002 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-09-23T19:48:18.003Z,1569268098.003 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-09-23T19:48:18.003Z,1569268098.003 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-09-23T19:48:18.003Z,1569268098.003 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-09-23T19:48:18.003Z,1569268098.003 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-09-23T19:48:18.003Z,1569268098.003 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-09-23T19:48:18.004Z,1569268098.004 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-09-23T19:48:18.004Z,1569268098.004 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-09-23T19:48:18.004Z,1569268098.004 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-09-23T19:48:18.007Z,1569268098.007 [CBIT](DEBUG): Deactivating GF circuits.
2019-09-23T19:48:18.007Z,1569268098.007 [CBIT](DEBUG): Deactivating emergency mode.
2019-09-23T19:48:18.043Z,1569268098.043 [CBIT](DEBUG): Backplane powered.
2019-09-23T19:48:18.046Z,1569268098.046 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-09-23T19:48:18.070Z,1569268098.070 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-09-23T19:48:18.097Z,1569268098.097 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-09-23T19:48:18.097Z,1569268098.097 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-09-23T19:48:18.154Z,1569268098.154 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-09-23T19:48:18.171Z,1569268098.171 [Default:A.Wait](DEBUG): Construct Wait.
2019-09-23T19:48:18.173Z,1569268098.173 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-09-23T19:48:18.192Z,1569268098.192 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-09-23T19:48:18.195Z,1569268098.195 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-09-23T19:48:18.228Z,1569268098.228 [Default:E.Execute](DEBUG): Construct Execute.
2019-09-23T19:48:18.245Z,1569268098.245 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-09-23T19:48:18.250Z,1569268098.250 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,RDI_Pathfinder,DAT,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-09-23T19:48:18.272Z,1569268098.272 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-09-23T19:48:18.335Z,1569268098.335 [Radio_Surface](INFO): Powering up
2019-09-23T19:48:18.428Z,1569268098.428 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar
2019-09-23T19:48:18.458Z,1569268098.458 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-09-23T19:48:18.458Z,1569268098.458 [DAT](INFO): Powering up
2019-09-23T19:48:18.459Z,1569268098.459 [DAT](DEBUG): Initializing DAT.
2019-09-23T19:48:18.479Z,1569268098.479 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-09-23T19:48:18.540Z,1569268098.540 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-09-23T19:48:18.589Z,1569268098.589 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-09-23T19:48:18.595Z,1569268098.595 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-09-23T19:48:18.597Z,1569268098.597 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-09-23T19:48:18.603Z,1569268098.603 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-09-23T19:48:18.605Z,1569268098.605 [MassServo](DEBUG): Initializing EZServoServo.
2019-09-23T19:48:18.612Z,1569268098.612 [MassServo](DEBUG): Initializing MassServo.
2019-09-23T19:48:18.612Z,1569268098.612 [RudderServo](DEBUG): Initializing EZServoServo.
2019-09-23T19:48:18.619Z,1569268098.619 [RudderServo](DEBUG): Initializing RudderServo.
2019-09-23T19:48:18.620Z,1569268098.620 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-09-23T19:48:18.627Z,1569268098.627 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-09-23T19:48:18.727Z,1569268098.727 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-09-23T19:48:32.021Z,1569268112.021 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-09-23T19:48:44.525Z,1569268124.525 [NAL9602](INFO): Powering up NAL9602
2019-09-23T19:48:55.429Z,1569268135.429 [NAL9602](INFO): NAL9602 initialized
2019-09-23T19:48:56.247Z,1569268136.247 [NAL9602](DEBUG): Fix Requested
2019-09-23T19:49:17.707Z,1569268157.707 [SBIT](IMPORTANT): Beginning Startup BIT
2019-09-23T19:49:17.712Z,1569268157.712 [CBIT](IMPORTANT): Beginning ground fault scan
2019-09-23T19:49:18.489Z,1569268158.489 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: CC 12.50ms MGP

user:1>, available: 
2019-09-23T19:49:18.489Z,1569268158.489 [DAT] Communications Fault, FailCount= 1
2019-09-23T19:49:18.489Z,1569268158.489 [DAT](ERROR): Communications Fault
2019-09-23T19:49:18.552Z,1569268158.552 [CBIT](ERROR): Communications Fault in component: DAT
2019-09-23T19:49:18.882Z,1569268158.882 [DAT](INFO): Powering down
2019-09-23T19:49:20.176Z,1569268160.176 [CBIT](INFO): Clearing failed state for component DAT
2019-09-23T19:49:20.176Z,1569268160.176 [DAT] No Fault, FailCount= 1
2019-09-23T19:49:22.245Z,1569268162.245 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-09-23T19:49:22.245Z,1569268162.245 [DAT](INFO): Powering up
2019-09-23T19:49:22.245Z,1569268162.245 [DAT](DEBUG): Initializing DAT.
2019-09-23T19:49:22.331Z,1569268162.331 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-09-23T19:49:28.760Z,1569268168.760 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.008241
CHAN A1 (24V): 0.006524
CHAN A2 (12V): -0.007541
CHAN A3 (5V): -0.003158
CHAN B0 (3.3V): -0.000675
CHAN B1 (3.15aV): -0.001359
CHAN B2 (3.15bV): 0.000490
CHAN B3 (GND): 0.001565
OPEN: -0.003940
Full Scale Calc: 4.765 mA, -1.589 mA
2019-09-23T19:49:36.460Z,1569268176.460 [DAT](INFO): setting local address to 4
2019-09-23T19:49:36.874Z,1569268176.874 [DAT](INFO): set local address to 4
2019-09-23T19:50:11.343Z,1569268211.343 [SBIT](IMPORTANT): SBIT PASSED
2019-09-23T19:50:11.391Z,1569268211.391 [CommandLine](IMPORTANT): got command configSet list
2019-09-23T19:50:11.391Z,1569268211.391 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-09-23T19:50:11.392Z,1569268211.392 [CommandLine](IMPORTANT): CBIT.gf24Offset=143 microampere;

2019-09-23T19:50:11.392Z,1569268211.392 [CommandLine](IMPORTANT): Express none RDI_Pathfinder.height_above_sea_floor;

2019-09-23T19:50:11.392Z,1569268211.392 [CommandLine](IMPORTANT): Express linearApproximation Tracking.range_to_contact 10.000000 meter;

2019-09-23T19:50:11.392Z,1569268211.392 [CommandLine](IMPORTANT): Express linearApproximation WetLabsUBAT.biolum_potential 10000000.000000 none;

2019-09-23T19:50:11.392Z,1569268211.392 [CommandLine](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 1.000000 liter_per_second;

2019-09-23T19:50:11.392Z,1569268211.392 [CommandLine](IMPORTANT): Express none height_above_sea_floor;

2019-09-23T19:50:11.393Z,1569268211.393 [CommandLine](IMPORTANT): Normal linearApproximation WetLabsUBAT.biolum_potential 1000000.000000 none;

2019-09-23T19:50:11.393Z,1569268211.393 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=80 cubic_centimeter;

2019-09-23T19:50:11.393Z,1569268211.393 [CommandLine](IMPORTANT): VerticalControl.massDefault=10 millimeter;

2019-09-23T19:50:11.737Z,1569268211.737 [MissionManager](IMPORTANT): Started mission Startup
2019-09-23T19:50:11.737Z,1569268211.737 [Startup] Running Loop=1
2019-09-23T19:50:11.737Z,1569268211.737 [Startup](DEBUG): Aggregate::initialize Startup
2019-09-23T19:50:11.737Z,1569268211.737 [Startup:A.GoToSurface] Running Loop=1
2019-09-23T19:50:11.737Z,1569268211.737 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-09-23T19:50:11.738Z,1569268211.738 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-09-23T19:50:11.738Z,1569268211.738 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-09-23T19:50:11.739Z,1569268211.739 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-09-23T19:50:11.739Z,1569268211.739 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-09-23T19:50:11.740Z,1569268211.740 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-09-23T19:50:11.741Z,1569268211.741 [Startup:StartupSatComms] Running Loop=1
2019-09-23T19:50:11.741Z,1569268211.741 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-09-23T19:50:11.741Z,1569268211.741 [Startup:StartupSatComms:A] Running Loop=1
2019-09-23T19:50:12.110Z,1569268212.110 [NAL9602](INFO): SBD MO Status=2, MOMSN=1432, MT Status=2, MTMSN=0
2019-09-23T19:50:12.110Z,1569268212.110 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T19:50:12.180Z,1569268212.180 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-09-23T19:50:37.983Z,1569268237.983 [NAL9602](INFO): SBD MO Status=2, MOMSN=1432, MT Status=2, MTMSN=0
2019-09-23T19:50:37.987Z,1569268237.987 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T19:50:47.009Z,1569268247.009 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004889
2019-09-23T19:51:06.277Z,1569268266.277 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T19:51:06.277Z,1569268266.277 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092319501755,35.0, -0.,1448.9,  0
2019-09-23T19:51:11.972Z,1569268271.972 [Startup:StartupSatComms:A](INFO): Timed out from 2019-09-23T19:50:11.7Z
2019-09-23T19:51:11.972Z,1569268271.972 [Startup:StartupSatComms:A] Stopped
2019-09-23T19:51:11.972Z,1569268271.972 [Startup:StartupSatComms:B] Running Loop=1
2019-09-23T19:51:12.334Z,1569268272.334 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-09-23T19:51:18.014Z,1569268278.014 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-09-23T19:51:18.014Z,1569268278.014 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-09-23T19:51:18.024Z,1569268278.024 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-09-23T19:51:18.396Z,1569268278.396 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-09-23T19:51:18.396Z,1569268278.396 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-09-23T19:51:22.681Z,1569268282.681 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190923T194037/Courier0004.lzma
2019-09-23T19:51:24.685Z,1569268284.685 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194037/Courier0004.lzma.bak
2019-09-23T19:51:24.685Z,1569268284.685 [DataOverHttps](INFO): SBD MOMSN=11804774
2019-09-23T19:51:47.105Z,1569268307.105 [DataOverHttps](INFO): Sending 812 bytes from file Logs/20190923T194037/Express0005.lzma
2019-09-23T19:51:49.132Z,1569268309.132 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194037/Express0005.lzma.bak
2019-09-23T19:51:49.132Z,1569268309.132 [DataOverHttps](INFO): SBD MOMSN=11804781
2019-09-23T19:52:10.169Z,1569268330.169 [DataOverHttps](INFO): Sending 985 bytes from file Logs/20190923T194806/Express0001.lzma
2019-09-23T19:52:12.173Z,1569268332.173 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0001.lzma.bak
2019-09-23T19:52:12.173Z,1569268332.173 [DataOverHttps](INFO): SBD MOMSN=11804794
2019-09-23T19:52:12.181Z,1569268332.181 [Startup:StartupSatComms:B](INFO): Timed out from 2019-09-23T19:51:11.0Z
2019-09-23T19:52:12.182Z,1569268332.182 [Startup:StartupSatComms:B] Stopped
2019-09-23T19:52:12.182Z,1569268332.182 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-09-23T19:52:12.182Z,1569268332.182 [Startup:StartupSatComms] Stopped
2019-09-23T19:52:12.182Z,1569268332.182 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-09-23T19:52:12.183Z,1569268332.183 [Startup](INFO): Completed Startup
2019-09-23T19:52:12.183Z,1569268332.183 [MissionManager](INFO): Startup is completed.
2019-09-23T19:52:12.187Z,1569268332.187 [MissionManager](INFO): Uninitializing Mission Startup
2019-09-23T19:52:12.187Z,1569268332.187 [Startup] Stopped
2019-09-23T19:52:12.188Z,1569268332.188 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-09-23T19:52:12.188Z,1569268332.188 [Startup:A.GoToSurface] Stopped
2019-09-23T19:52:12.188Z,1569268332.188 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-09-23T19:52:12.536Z,1569268332.536 [MissionManager](IMPORTANT): Started mission Default
2019-09-23T19:52:12.536Z,1569268332.536 [Default] Running Loop=1
2019-09-23T19:52:12.536Z,1569268332.536 [Default](DEBUG): Aggregate::initialize Default
2019-09-23T19:52:12.537Z,1569268332.537 [Default:B.GoToSurface] Running Loop=1
2019-09-23T19:52:12.537Z,1569268332.537 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-09-23T19:52:12.537Z,1569268332.537 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-09-23T19:52:12.537Z,1569268332.537 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-09-23T19:52:12.537Z,1569268332.537 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-09-23T19:52:12.538Z,1569268332.538 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-09-23T19:52:12.538Z,1569268332.538 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-09-23T19:52:12.538Z,1569268332.538 [Default:A.Wait] Running Loop=1
2019-09-23T19:52:12.538Z,1569268332.538 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-09-23T19:52:25.910Z,1569268345.910 [Default:A.Wait](INFO): Done Waiting.
2019-09-23T19:52:25.910Z,1569268345.910 [Default:A.Wait] Stopped
2019-09-23T19:52:25.910Z,1569268345.910 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T19:52:26.318Z,1569268346.318 [Default:CheckIn] Running Loop=1
2019-09-23T19:52:26.319Z,1569268346.319 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T19:52:26.319Z,1569268346.319 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T19:52:26.861Z,1569268346.861 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-09-23T19:53:58.353Z,1569268438.353 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T19:53:59.183Z,1569268439.183 [NAL9602](DEBUG): Fix Requested
2019-09-23T19:53:59.578Z,1569268439.578 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195205.00,A,3648.16113,N,12147.29377,W,0.622,0.00,230919,,,A*74
2019-09-23T19:53:59.591Z,1569268439.591 [NAL9602](INFO): GPS fix at 20190923T195205: (36.802686, -121.788229)
2019-09-23T19:53:59.615Z,1569268439.615 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T19:53:59.615Z,1569268439.615 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T19:54:00.022Z,1569268440.022 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-09-23T19:54:10.887Z,1569268450.887 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190923T194806/Courier0004.lzma
2019-09-23T19:54:12.896Z,1569268452.896 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0004.lzma.bak
2019-09-23T19:54:12.897Z,1569268452.897 [DataOverHttps](INFO): SBD MOMSN=11804820
2019-09-23T19:54:31.988Z,1569268471.988 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T19:54:37.216Z,1569268477.216 [DataOverHttps](INFO): Sending 301 bytes from file Logs/20190923T194806/Express0005.lzma
2019-09-23T19:54:39.221Z,1569268479.221 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0005.lzma.bak
2019-09-23T19:54:39.221Z,1569268479.221 [DataOverHttps](INFO): SBD MOMSN=11804823
2019-09-23T19:54:44.514Z,1569268484.514 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T19:54:44.514Z,1569268484.514 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T19:54:44.514Z,1569268484.514 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T19:55:08.348Z,1569268508.348 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T19:55:08.349Z,1569268508.349 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092319541955,35.0, 0.0,1448.9,  0
2019-09-23T19:55:49.179Z,1569268549.179 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-09-23T19:55:49.182Z,1569268549.182 [BPC1](INFO): Received data from all battery sticks.
2019-09-23T19:59:45.146Z,1569268785.146 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T19:59:45.146Z,1569268785.146 [Default:CheckIn:C.Wait] Stopped
2019-09-23T19:59:45.146Z,1569268785.146 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T19:59:45.146Z,1569268785.146 [Default:CheckIn:D] Running Loop=1
2019-09-23T19:59:45.551Z,1569268785.551 [Default:CheckIn:D] Stopped
2019-09-23T19:59:45.551Z,1569268785.551 [Default:CheckIn:E] Running Loop=1
2019-09-23T19:59:45.977Z,1569268785.977 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.550247 min 
2019-09-23T19:59:45.977Z,1569268785.977 [Default:CheckIn:E] Stopped
2019-09-23T19:59:45.977Z,1569268785.977 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T19:59:45.977Z,1569268785.977 [Default:CheckIn] Stopped
2019-09-23T19:59:45.977Z,1569268785.977 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T19:59:45.978Z,1569268785.978 [Default:CheckIn](INFO): Running loop #2
2019-09-23T19:59:45.978Z,1569268785.978 [Default:CheckIn] Running Loop=2
2019-09-23T19:59:45.978Z,1569268785.978 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T19:59:45.978Z,1569268785.978 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T19:59:47.522Z,1569268787.522 [NAL9602](DEBUG): Fix Requested
2019-09-23T19:59:47.918Z,1569268787.918 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195754.00,A,3648.16622,N,12147.28289,W,0.408,0.00,230919,,,A*7B
2019-09-23T19:59:47.920Z,1569268787.920 [NAL9602](INFO): GPS fix at 20190923T195754: (36.802770, -121.788048)
2019-09-23T19:59:47.981Z,1569268787.981 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T19:59:47.981Z,1569268787.981 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T19:59:50.946Z,1569268790.946 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190923T194806/Courier0007.lzma
2019-09-23T19:59:52.957Z,1569268792.957 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0007.lzma.bak
2019-09-23T19:59:52.957Z,1569268792.957 [DataOverHttps](INFO): SBD MOMSN=11804835
2019-09-23T20:00:14.791Z,1569268814.791 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20190923T194806/Express0008.lzma
2019-09-23T20:00:16.797Z,1569268816.797 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0008.lzma.bak
2019-09-23T20:00:16.797Z,1569268816.797 [DataOverHttps](INFO): SBD MOMSN=11804838
2019-09-23T20:00:18.629Z,1569268818.629 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-09-23T20:00:18.711Z,1569268818.711 [NAL9602](FAULT): received: 
+CSQ:0

OK32, 2, 0, 0, 0

OK
2019-09-23T20:00:18.711Z,1569268818.711 [NAL9602] Data Fault, FailCount= 1
2019-09-23T20:00:18.711Z,1569268818.711 [NAL9602](ERROR): Data Fault
2019-09-23T20:00:18.793Z,1569268818.793 [CBIT](ERROR): Data Fault in component: NAL9602
2019-09-23T20:00:19.029Z,1569268819.029 [NAL9602](INFO): Powering down
2019-09-23T20:00:19.903Z,1569268819.903 [CBIT](INFO): Clearing failed state for component NAL9602
2019-09-23T20:00:19.903Z,1569268819.903 [NAL9602] No Fault, FailCount= 1
2019-09-23T20:00:22.682Z,1569268822.682 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:00:22.682Z,1569268822.682 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:00:22.682Z,1569268822.682 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:00:28.343Z,1569268828.343 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T20:00:28.344Z,1569268828.344 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092319593955,35.0, -0.1,   0.0,1448:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-09-23T20:00:49.320Z,1569268849.320 [NAL9602](INFO): Powering up NAL9602
2019-09-23T20:01:00.248Z,1569268860.248 [NAL9602](INFO): NAL9602 initialized
2019-09-23T20:01:31.340Z,1569268891.340 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:05:23.310Z,1569269123.310 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:05:23.311Z,1569269123.311 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:05:23.311Z,1569269123.311 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:05:23.311Z,1569269123.311 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:05:23.674Z,1569269123.674 [Default:CheckIn:D] Stopped
2019-09-23T20:05:23.674Z,1569269123.674 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.185631 min 
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn:E] Stopped
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn] Stopped
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn](INFO): Running loop #3
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn] Running Loop=3
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:05:24.101Z,1569269124.101 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:05:25.671Z,1569269125.671 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:05:26.070Z,1569269126.070 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200331.00,A,3648.16034,N,12147.27111,W,0.330,0.00,230919,,,A*73
2019-09-23T20:05:26.072Z,1569269126.072 [NAL9602](INFO): GPS fix at 20190923T200331: (36.802672, -121.787852)
2019-09-23T20:05:26.166Z,1569269126.166 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:05:26.166Z,1569269126.166 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:05:27.392Z,1569269127.392 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T20:05:29.569Z,1569269129.569 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0010.lzma
2019-09-23T20:05:31.577Z,1569269131.577 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0010.lzma.bak
2019-09-23T20:05:31.577Z,1569269131.577 [DataOverHttps](INFO): SBD MOMSN=11804887
2019-09-23T20:05:52.963Z,1569269152.963 [DataOverHttps](INFO): Sending 160 bytes from file Logs/20190923T194806/Express0011.lzma
2019-09-23T20:05:54.969Z,1569269154.969 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0011.lzma.bak
2019-09-23T20:05:54.969Z,1569269154.969 [DataOverHttps](INFO): SBD MOMSN=11804890
2019-09-23T20:05:58.100Z,1569269158.100 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:06:00.597Z,1569269160.597 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:06:00.597Z,1569269160.597 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:06:00.597Z,1569269160.597 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:11:01.122Z,1569269461.122 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:11:01.122Z,1569269461.122 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:11:01.122Z,1569269461.122 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:11:01.122Z,1569269461.122 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:11:01.551Z,1569269461.551 [Default:CheckIn:D] Stopped
2019-09-23T20:11:01.552Z,1569269461.552 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:11:02.001Z,1569269462.001 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.816917 min 
2019-09-23T20:11:02.001Z,1569269462.001 [Default:CheckIn:E] Stopped
2019-09-23T20:11:02.001Z,1569269462.001 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:11:02.001Z,1569269462.001 [Default:CheckIn] Stopped
2019-09-23T20:11:02.001Z,1569269462.001 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:11:02.002Z,1569269462.002 [Default:CheckIn](INFO): Running loop #4
2019-09-23T20:11:02.002Z,1569269462.002 [Default:CheckIn] Running Loop=4
2019-09-23T20:11:02.002Z,1569269462.002 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:11:02.002Z,1569269462.002 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:11:03.543Z,1569269463.543 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:11:03.926Z,1569269463.926 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200910.00,A,3648.16616,N,12147.28225,W,0.525,269.22,230919,,,A*78
2019-09-23T20:11:03.928Z,1569269463.928 [NAL9602](INFO): GPS fix at 20190923T200910: (36.802769, -121.788038)
2019-09-23T20:11:03.998Z,1569269463.998 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:11:03.998Z,1569269463.998 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:11:07.162Z,1569269467.162 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T194806/Courier0013.lzma
2019-09-23T20:11:09.173Z,1569269469.173 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0013.lzma.bak
2019-09-23T20:11:09.173Z,1569269469.173 [DataOverHttps](INFO): SBD MOMSN=11804901
2019-09-23T20:11:33.512Z,1569269493.512 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190923T194806/Express0014.lzma
2019-09-23T20:11:35.517Z,1569269495.517 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0014.lzma.bak
2019-09-23T20:11:35.517Z,1569269495.517 [DataOverHttps](INFO): SBD MOMSN=11804904
2019-09-23T20:11:40.802Z,1569269500.802 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:11:40.802Z,1569269500.802 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:11:40.802Z,1569269500.802 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:15:20.950Z,1569269720.950 [NAL9602](INFO): SBD MO Status=2, MOMSN=1432, MT Status=2, MTMSN=0
2019-09-23T20:15:20.950Z,1569269720.950 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T20:15:32.266Z,1569269732.266 [NAL9602](INFO): SBD MO Status=0, MOMSN=1432, MT Status=0, MTMSN=0
2019-09-23T20:15:32.266Z,1569269732.266 [NAL9602](INFO): No messages in MT queue
2019-09-23T20:16:02.970Z,1569269762.970 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:16:41.406Z,1569269801.406 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:16:41.406Z,1569269801.406 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:16:41.406Z,1569269801.406 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:16:41.407Z,1569269801.407 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:16:41.778Z,1569269801.778 [Default:CheckIn:D] Stopped
2019-09-23T20:16:41.778Z,1569269801.778 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:16:42.221Z,1569269802.221 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.487364 min 
2019-09-23T20:16:42.221Z,1569269802.221 [Default:CheckIn:E] Stopped
2019-09-23T20:16:42.221Z,1569269802.221 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:16:42.221Z,1569269802.221 [Default:CheckIn] Stopped
2019-09-23T20:16:42.222Z,1569269802.222 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:16:42.222Z,1569269802.222 [Default:CheckIn](INFO): Running loop #5
2019-09-23T20:16:42.222Z,1569269802.222 [Default:CheckIn] Running Loop=5
2019-09-23T20:16:42.222Z,1569269802.222 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:16:42.222Z,1569269802.222 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:16:43.779Z,1569269803.779 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:16:44.174Z,1569269804.174 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201450.00,A,3648.16606,N,12147.28503,W,0.719,162.80,230919,,,A*7F
2019-09-23T20:16:44.176Z,1569269804.176 [NAL9602](INFO): GPS fix at 20190923T201450: (36.802768, -121.788084)
2019-09-23T20:16:44.228Z,1569269804.228 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:16:44.228Z,1569269804.228 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:16:47.251Z,1569269807.251 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T194806/Courier0016.lzma
2019-09-23T20:16:49.315Z,1569269809.315 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0016.lzma.bak
2019-09-23T20:16:49.315Z,1569269809.315 [DataOverHttps](INFO): SBD MOMSN=11804918
2019-09-23T20:16:57.966Z,1569269817.966 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-09-23T20:16:57.966Z,1569269817.966 [RDI_Pathfinder](ERROR): Failed to parse:
:RA   0.00,   0.00,   0.00,   0.00
2019-09-23T20:17:10.591Z,1569269830.591 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190923T194806/Express0017.lzma
2019-09-23T20:17:12.597Z,1569269832.597 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0017.lzma.bak
2019-09-23T20:17:12.597Z,1569269832.597 [DataOverHttps](INFO): SBD MOMSN=11804921
2019-09-23T20:17:18.546Z,1569269838.546 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:17:18.546Z,1569269838.546 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:17:18.546Z,1569269838.546 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:17:28.618Z,1569269848.618 [NAL9602](INFO): SBD MO Status=2, MOMSN=1433, MT Status=2, MTMSN=0
2019-09-23T20:17:28.618Z,1569269848.618 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T20:17:50.845Z,1569269870.845 [NAL9602](INFO): SBD MO Status=0, MOMSN=1433, MT Status=0, MTMSN=0
2019-09-23T20:17:50.846Z,1569269870.846 [NAL9602](INFO): No messages in MT queue
2019-09-23T20:18:21.537Z,1569269901.537 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:19:33.905Z,1569269973.905 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-09-23T20:19:33.905Z,1569269973.905 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.         +0.00,   0.00,1861.86
2019-09-23T20:20:09.437Z,1569270009.437 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T20:20:09.437Z,1569270009.437 [RDI_Pathfinder](ERROR): Failed to parse:
:TS0192055,35.0, -0.1,   0.0,1448.9,  0
2019-09-23T20:22:19.158Z,1569270139.158 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:22:19.158Z,1569270139.158 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:22:19.159Z,1569270139.159 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:22:19.159Z,1569270139.159 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:22:19.574Z,1569270139.574 [Default:CheckIn:D] Stopped
2019-09-23T20:22:19.574Z,1569270139.574 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 30.117299 min 
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn:E] Stopped
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn] Stopped
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn](INFO): Running loop #6
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn] Running Loop=6
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:22:19.946Z,1569270139.946 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:22:21.527Z,1569270141.527 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:22:21.934Z,1569270141.934 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202028.00,A,3648.16432,N,12147.28385,W,0.564,162.80,230919,,,A*72
2019-09-23T20:22:21.936Z,1569270141.936 [NAL9602](INFO): GPS fix at 20190923T202028: (36.802739, -121.788064)
2019-09-23T20:22:22.044Z,1569270142.044 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:22:22.044Z,1569270142.044 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:22:29.968Z,1569270149.968 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0019.lzma
2019-09-23T20:22:31.981Z,1569270151.981 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0019.lzma.bak
2019-09-23T20:22:31.981Z,1569270151.981 [DataOverHttps](INFO): SBD MOMSN=11804936
2019-09-23T20:23:07.027Z,1569270187.027 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190923T194806/Express0020.lzma
2019-09-23T20:23:09.035Z,1569270189.035 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0020.lzma.bak
2019-09-23T20:23:09.036Z,1569270189.036 [DataOverHttps](INFO): SBD MOMSN=11804949
2019-09-23T20:23:14.378Z,1569270194.378 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:23:14.378Z,1569270194.378 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:23:14.378Z,1569270194.378 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:24:45.662Z,1569270285.662 [NAL9602](INFO): SBD MO Status=0, MOMSN=1434, MT Status=0, MTMSN=0
2019-09-23T20:24:45.662Z,1569270285.662 [NAL9602](INFO): No messages in MT queue
2019-09-23T20:25:16.360Z,1569270316.360 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:28:14.978Z,1569270494.978 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:28:14.978Z,1569270494.978 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:28:14.978Z,1569270494.978 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:28:14.978Z,1569270494.978 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:28:15.370Z,1569270495.370 [Default:CheckIn:D] Stopped
2019-09-23T20:28:15.370Z,1569270495.370 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:28:15.758Z,1569270495.758 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 36.047225 min 
2019-09-23T20:28:15.758Z,1569270495.758 [Default:CheckIn:E] Stopped
2019-09-23T20:28:15.758Z,1569270495.759 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:28:15.759Z,1569270495.759 [Default:CheckIn] Stopped
2019-09-23T20:28:15.759Z,1569270495.759 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:28:15.759Z,1569270495.759 [Default:CheckIn](INFO): Running loop #7
2019-09-23T20:28:15.779Z,1569270495.779 [Default:CheckIn] Running Loop=7
2019-09-23T20:28:15.779Z,1569270495.779 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:28:15.779Z,1569270495.779 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:28:17.359Z,1569270497.359 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:28:17.754Z,1569270497.754 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202624.00,A,3648.16588,N,12147.28940,W,0.311,0.00,230919,,,A*72
2019-09-23T20:28:17.766Z,1569270497.766 [NAL9602](INFO): GPS fix at 20190923T202624: (36.802765, -121.788157)
2019-09-23T20:28:17.794Z,1569270497.794 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:28:17.794Z,1569270497.794 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:28:23.756Z,1569270503.756 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0022.lzma
2019-09-23T20:28:25.765Z,1569270505.765 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0022.lzma.bak
2019-09-23T20:28:25.765Z,1569270505.765 [DataOverHttps](INFO): SBD MOMSN=11804995
2019-09-23T20:28:51.462Z,1569270531.462 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T20:28:51.462Z,1569270531.462 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T20:28:55.655Z,1569270535.655 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190923T194806/Express0023.lzma
2019-09-23T20:28:57.661Z,1569270537.661 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0023.lzma.bak
2019-09-23T20:28:57.661Z,1569270537.661 [DataOverHttps](INFO): SBD MOMSN=11804998
2019-09-23T20:29:02.798Z,1569270542.798 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:29:02.798Z,1569270542.798 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:29:02.798Z,1569270542.798 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:29:42.366Z,1569270582.366 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T20:29:42.366Z,1569270582.366 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T20:30:36.102Z,1569270636.102 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T20:30:36.102Z,1569270636.102 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T20:33:19.736Z,1569270799.736 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T20:33:50.428Z,1569270830.428 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:34:03.398Z,1569270843.398 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:34:03.398Z,1569270843.398 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:34:03.398Z,1569270843.398 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:34:03.398Z,1569270843.398 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:34:03.805Z,1569270843.805 [Default:CheckIn:D] Stopped
2019-09-23T20:34:03.805Z,1569270843.805 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:34:04.218Z,1569270844.218 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.854472 min 
2019-09-23T20:34:04.218Z,1569270844.218 [Default:CheckIn:E] Stopped
2019-09-23T20:34:04.219Z,1569270844.219 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:34:04.219Z,1569270844.219 [Default:CheckIn] Stopped
2019-09-23T20:34:04.219Z,1569270844.219 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:34:04.219Z,1569270844.219 [Default:CheckIn](INFO): Running loop #8
2019-09-23T20:34:04.227Z,1569270844.227 [Default:CheckIn] Running Loop=8
2019-09-23T20:34:04.227Z,1569270844.227 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:34:04.227Z,1569270844.227 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:34:05.787Z,1569270845.787 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:34:06.182Z,1569270846.182 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203212.00,A,3648.16749,N,12147.27538,W,0.564,221.30,230919,,,A*77
2019-09-23T20:34:06.184Z,1569270846.184 [NAL9602](INFO): GPS fix at 20190923T203212: (36.802791, -121.787923)
2019-09-23T20:34:06.262Z,1569270846.262 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:34:06.262Z,1569270846.262 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:34:09.905Z,1569270849.905 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0025.lzma
2019-09-23T20:34:11.913Z,1569270851.913 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0025.lzma.bak
2019-09-23T20:34:11.913Z,1569270851.913 [DataOverHttps](INFO): SBD MOMSN=11805008
2019-09-23T20:34:33.407Z,1569270873.407 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190923T194806/Express0026.lzma
2019-09-23T20:34:35.413Z,1569270875.413 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0026.lzma.bak
2019-09-23T20:34:35.413Z,1569270875.413 [DataOverHttps](INFO): SBD MOMSN=11805011
2019-09-23T20:34:36.909Z,1569270876.909 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-09-23T20:34:36.983Z,1569270876.983 [NAL9602](FAULT): received: 
+CSQ:0

OK35, 2, 0, 0, 0

OK
2019-09-23T20:34:36.983Z,1569270876.983 [NAL9602] Data Fault, FailCount= 1
2019-09-23T20:34:36.983Z,1569270876.983 [NAL9602](ERROR): Data Fault
2019-09-23T20:34:37.087Z,1569270877.087 [CBIT](ERROR): Data Fault in component: NAL9602
2019-09-23T20:34:37.288Z,1569270877.288 [NAL9602](INFO): Powering down
2019-09-23T20:34:38.183Z,1569270878.183 [CBIT](INFO): Clearing failed state for component NAL9602
2019-09-23T20:34:38.183Z,1569270878.183 [NAL9602] No Fault, FailCount= 1
2019-09-23T20:34:40.966Z,1569270880.966 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:34:40.966Z,1569270880.966 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:34:40.966Z,1569270880.966 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:35:07.589Z,1569270907.589 [NAL9602](INFO): Powering up NAL9602
2019-09-23T20:35:18.533Z,1569270918.533 [NAL9602](INFO): NAL9602 initialized
2019-09-23T20:35:49.610Z,1569270949.610 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:39:13.257Z,1569271153.257 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T20:39:13.258Z,1569271153.258 [RDI_Pathfinder](ERROR): Failed to parse:
:TS05.0, -0.1,   0.0,1448.9,  0
2019-09-23T20:39:30.237Z,1569271170.237 [RDI_Pathfinder](ERROR): Failed to parse:
:B-32768,V
2019-09-23T20:39:41.555Z,1569271181.555 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:39:41.555Z,1569271181.555 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:39:41.555Z,1569271181.555 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:39:41.555Z,1569271181.555 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:39:41.970Z,1569271181.970 [Default:CheckIn:D] Stopped
2019-09-23T20:39:41.970Z,1569271181.970 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:39:42.339Z,1569271182.339 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 47.490560 min 
2019-09-23T20:39:42.339Z,1569271182.339 [Default:CheckIn:E] Stopped
2019-09-23T20:39:42.339Z,1569271182.339 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:39:42.339Z,1569271182.339 [Default:CheckIn] Stopped
2019-09-23T20:39:42.343Z,1569271182.343 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:39:42.343Z,1569271182.343 [Default:CheckIn](INFO): Running loop #9
2019-09-23T20:39:42.344Z,1569271182.344 [Default:CheckIn] Running Loop=9
2019-09-23T20:39:42.344Z,1569271182.344 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:39:42.344Z,1569271182.344 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:39:43.939Z,1569271183.939 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:39:44.338Z,1569271184.338 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203750.00,A,3648.17489,N,12147.27832,W,0.389,0.00,230919,,,A*7A
2019-09-23T20:39:44.340Z,1569271184.340 [NAL9602](INFO): GPS fix at 20190923T203750: (36.802915, -121.787972)
2019-09-23T20:39:44.367Z,1569271184.367 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:39:44.367Z,1569271184.367 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:39:46.752Z,1569271186.752 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T20:39:55.403Z,1569271195.403 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190923T194806/Courier0028.lzma
2019-09-23T20:39:57.409Z,1569271197.409 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0028.lzma.bak
2019-09-23T20:39:57.409Z,1569271197.409 [DataOverHttps](INFO): SBD MOMSN=11805039
2019-09-23T20:40:17.456Z,1569271217.456 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:40:19.191Z,1569271219.191 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190923T194806/Express0029.lzma
2019-09-23T20:40:21.199Z,1569271221.199 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0029.lzma.bak
2019-09-23T20:40:21.200Z,1569271221.200 [DataOverHttps](INFO): SBD MOMSN=11805042
2019-09-23T20:40:26.386Z,1569271226.386 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:40:26.386Z,1569271226.386 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:40:26.386Z,1569271226.386 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:45:26.973Z,1569271526.973 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:45:26.973Z,1569271526.973 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:45:26.974Z,1569271526.974 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:45:26.974Z,1569271526.974 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:45:27.360Z,1569271527.360 [Default:CheckIn:D] Stopped
2019-09-23T20:45:27.360Z,1569271527.360 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:45:27.771Z,1569271527.771 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.247054 min 
2019-09-23T20:45:27.771Z,1569271527.771 [Default:CheckIn:E] Stopped
2019-09-23T20:45:27.771Z,1569271527.771 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:45:27.771Z,1569271527.771 [Default:CheckIn] Stopped
2019-09-23T20:45:27.775Z,1569271527.775 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:45:27.775Z,1569271527.775 [Default:CheckIn](INFO): Running loop #10
2019-09-23T20:45:27.775Z,1569271527.775 [Default:CheckIn] Running Loop=10
2019-09-23T20:45:27.776Z,1569271527.776 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:45:27.776Z,1569271527.776 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:45:29.367Z,1569271529.367 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:45:29.762Z,1569271529.762 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204335.00,A,3648.16417,N,12147.28407,W,0.272,0.00,230919,,,A*7C
2019-09-23T20:45:29.764Z,1569271529.764 [NAL9602](INFO): GPS fix at 20190923T204335: (36.802736, -121.788068)
2019-09-23T20:45:29.814Z,1569271529.814 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:45:29.814Z,1569271529.814 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:45:33.846Z,1569271533.846 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T194806/Courier0031.lzma
2019-09-23T20:45:35.859Z,1569271535.859 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0031.lzma.bak
2019-09-23T20:45:35.860Z,1569271535.860 [DataOverHttps](INFO): SBD MOMSN=11805150
2019-09-23T20:45:57.311Z,1569271557.311 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190923T194806/Express0032.lzma
2019-09-23T20:45:59.317Z,1569271559.317 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0032.lzma.bak
2019-09-23T20:45:59.317Z,1569271559.317 [DataOverHttps](INFO): SBD MOMSN=11805220
2019-09-23T20:46:04.670Z,1569271564.670 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:46:04.670Z,1569271564.670 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:46:04.670Z,1569271564.670 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:46:05.041Z,1569271565.041 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T20:46:05.041Z,1569271565.041 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T20:46:53.506Z,1569271613.506 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T20:46:53.506Z,1569271613.506 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T20:48:05.886Z,1569271685.886 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-09-23T20:48:05.886Z,1569271685.886 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.   +0.00,        +0.00,   0.00,3573.46
2019-09-23T20:48:23.231Z,1569271703.231 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T20:48:23.240Z,1569271703.240 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092320473455,35.0, -0.1,   0RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-09-23T20:50:31.700Z,1569271831.700 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T20:50:43.868Z,1569271843.868 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T20:50:43.868Z,1569271843.868 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-09-23T20:51:02.400Z,1569271862.400 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:51:05.266Z,1569271865.266 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:51:05.266Z,1569271865.266 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:51:05.266Z,1569271865.266 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:51:05.266Z,1569271865.266 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:51:05.670Z,1569271865.670 [Default:CheckIn:D] Stopped
2019-09-23T20:51:05.670Z,1569271865.670 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:51:06.110Z,1569271866.110 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.885559 min 
2019-09-23T20:51:06.110Z,1569271866.110 [Default:CheckIn:E] Stopped
2019-09-23T20:51:06.111Z,1569271866.111 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:51:06.111Z,1569271866.111 [Default:CheckIn] Stopped
2019-09-23T20:51:06.111Z,1569271866.111 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:51:06.111Z,1569271866.111 [Default:CheckIn](INFO): Running loop #11
2019-09-23T20:51:06.111Z,1569271866.111 [Default:CheckIn] Running Loop=11
2019-09-23T20:51:06.111Z,1569271866.111 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:51:06.111Z,1569271866.111 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:51:07.663Z,1569271867.663 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:51:08.062Z,1569271868.062 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204914.00,A,3648.16358,N,12147.28820,W,0.039,0.00,230919,,,A*7D
2019-09-23T20:51:08.064Z,1569271868.064 [NAL9602](INFO): GPS fix at 20190923T204914: (36.802726, -121.788137)
2019-09-23T20:51:08.098Z,1569271868.098 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:51:08.098Z,1569271868.098 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:51:10.908Z,1569271870.908 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190923T194806/Courier0034.lzma
2019-09-23T20:51:12.917Z,1569271872.917 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0034.lzma.bak
2019-09-23T20:51:12.917Z,1569271872.917 [DataOverHttps](INFO): SBD MOMSN=11805239
2019-09-23T20:51:35.256Z,1569271895.256 [DataOverHttps](INFO): Sending 194 bytes from file Logs/20190923T194806/Express0035.lzma
2019-09-23T20:51:37.261Z,1569271897.261 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0035.lzma.bak
2019-09-23T20:51:37.261Z,1569271897.261 [DataOverHttps](INFO): SBD MOMSN=11805304
2019-09-23T20:51:38.809Z,1569271898.809 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-09-23T20:51:38.883Z,1569271898.883 [NAL9602](FAULT): received: 
+CSQ:0

OK35, 2, 0, 0, 0

OK
2019-09-23T20:51:38.883Z,1569271898.883 [NAL9602] Data Fault, FailCount= 1
2019-09-23T20:51:38.883Z,1569271898.883 [NAL9602](ERROR): Data Fault
2019-09-23T20:51:38.967Z,1569271898.967 [CBIT](ERROR): Data Fault in component: NAL9602
2019-09-23T20:51:39.212Z,1569271899.212 [NAL9602](INFO): Powering down
2019-09-23T20:51:40.069Z,1569271900.069 [CBIT](INFO): Clearing failed state for component NAL9602
2019-09-23T20:51:40.069Z,1569271900.069 [NAL9602] No Fault, FailCount= 1
2019-09-23T20:51:42.951Z,1569271902.951 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:51:42.951Z,1569271902.951 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:51:42.951Z,1569271902.951 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T20:52:09.513Z,1569271929.513 [NAL9602](INFO): Powering up NAL9602
2019-09-23T20:52:20.427Z,1569271940.427 [NAL9602](INFO): NAL9602 initialized
2019-09-23T20:52:51.528Z,1569271971.528 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:56:43.454Z,1569272203.454 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T20:56:43.455Z,1569272203.455 [Default:CheckIn:C.Wait] Stopped
2019-09-23T20:56:43.455Z,1569272203.455 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T20:56:43.455Z,1569272203.455 [Default:CheckIn:D] Running Loop=1
2019-09-23T20:56:43.911Z,1569272203.911 [Default:CheckIn:D] Stopped
2019-09-23T20:56:43.911Z,1569272203.911 [Default:CheckIn:E] Running Loop=1
2019-09-23T20:56:44.278Z,1569272204.278 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 64.522917 min 
2019-09-23T20:56:44.278Z,1569272204.278 [Default:CheckIn:E] Stopped
2019-09-23T20:56:44.279Z,1569272204.279 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T20:56:44.279Z,1569272204.279 [Default:CheckIn] Stopped
2019-09-23T20:56:44.279Z,1569272204.279 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T20:56:44.279Z,1569272204.279 [Default:CheckIn](INFO): Running loop #12
2019-09-23T20:56:44.279Z,1569272204.279 [Default:CheckIn] Running Loop=12
2019-09-23T20:56:44.279Z,1569272204.279 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T20:56:44.279Z,1569272204.279 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T20:56:45.891Z,1569272205.891 [NAL9602](DEBUG): Fix Requested
2019-09-23T20:56:46.258Z,1569272206.258 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205452.00,A,3648.16372,N,12147.28400,W,0.194,238.21,230919,,,A*79
2019-09-23T20:56:46.260Z,1569272206.260 [NAL9602](INFO): GPS fix at 20190923T205452: (36.802729, -121.788067)
2019-09-23T20:56:46.318Z,1569272206.318 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T20:56:46.319Z,1569272206.319 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T20:56:48.760Z,1569272208.760 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T20:56:50.678Z,1569272210.678 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0037.lzma
2019-09-23T20:56:52.689Z,1569272212.689 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0037.lzma.bak
2019-09-23T20:56:52.689Z,1569272212.689 [DataOverHttps](INFO): SBD MOMSN=11805391
2019-09-23T20:56:55.236Z,1569272215.236 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T20:56:55.236Z,1569272215.236 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   I,-32768,-32768,-32768,-32768,V
2019-09-23T20:57:14.693Z,1569272234.693 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20190923T194806/Express0038.lzma
2019-09-23T20:57:15.870Z,1569272235.870 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-09-23T20:57:15.870Z,1569272235.870 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.00,        +     +0.00,   0.00,4123.32
2019-09-23T20:57:16.697Z,1569272236.697 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0038.lzma.bak
2019-09-23T20:57:16.697Z,1569272236.697 [DataOverHttps](INFO): SBD MOMSN=11805394
2019-09-23T20:57:19.456Z,1569272239.456 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T20:57:22.329Z,1569272242.329 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T20:57:22.330Z,1569272242.330 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T20:57:22.330Z,1569272242.330 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:01:00.091Z,1569272460.091 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-09-23T21:02:11.606Z,1569272531.606 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T21:02:11.607Z,1569272531.607 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-09-23T21:02:22.978Z,1569272542.978 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:02:22.978Z,1569272542.978 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:02:22.979Z,1569272542.979 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:02:22.979Z,1569272542.979 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:02:23.326Z,1569272543.326 [Default:CheckIn:D] Stopped
2019-09-23T21:02:23.326Z,1569272543.326 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:02:23.738Z,1569272543.738 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.179834 min 
2019-09-23T21:02:23.738Z,1569272543.738 [Default:CheckIn:E] Stopped
2019-09-23T21:02:23.738Z,1569272543.738 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:02:23.739Z,1569272543.739 [Default:CheckIn] Stopped
2019-09-23T21:02:23.739Z,1569272543.739 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:02:23.739Z,1569272543.739 [Default:CheckIn](INFO): Running loop #13
2019-09-23T21:02:23.739Z,1569272543.739 [Default:CheckIn] Running Loop=13
2019-09-23T21:02:23.739Z,1569272543.739 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:02:23.739Z,1569272543.739 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:02:25.319Z,1569272545.319 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:02:25.714Z,1569272545.714 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210032.00,A,3648.16976,N,12147.29054,W,0.952,238.21,230919,,,A*77
2019-09-23T21:02:25.716Z,1569272545.716 [NAL9602](INFO): GPS fix at 20190923T210032: (36.802829, -121.788176)
2019-09-23T21:02:25.766Z,1569272545.766 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:02:25.766Z,1569272545.766 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:02:28.760Z,1569272548.760 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0040.lzma
2019-09-23T21:02:30.769Z,1569272550.769 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0040.lzma.bak
2019-09-23T21:02:30.769Z,1569272550.769 [DataOverHttps](INFO): SBD MOMSN=11805429
2019-09-23T21:02:55.479Z,1569272575.479 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190923T194806/Express0041.lzma
2019-09-23T21:02:55.647Z,1569272575.647 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T21:02:55.647Z,1569272575.647 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T21:02:57.485Z,1569272577.485 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0041.lzma.bak
2019-09-23T21:02:57.485Z,1569272577.485 [DataOverHttps](INFO): SBD MOMSN=11805484
2019-09-23T21:03:03.366Z,1569272583.366 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:03:03.366Z,1569272583.366 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:03:03.366Z,1569272583.366 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:03:17.932Z,1569272597.932 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T21:03:17.933Z,1569272597.933 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-32768-32768,-32768,
2019-09-23T21:03:22.249Z,1569272602.249 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-09-23T21:03:22.280Z,1569272602.280 [BPC1](INFO): Received data from all battery sticks.
2019-09-23T21:03:48.487Z,1569272628.487 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T21:03:48.491Z,1569272628.491 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T21:03:55.854Z,1569272635.854 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T21:03:55.854Z,1569272635.854 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092321030755,35.0, 0.0,1448.9,  0
2019-09-23T21:04:04.006Z,1569272644.006 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-09-23T21:04:04.006Z,1569272644.006 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19092321031555,35.0, -0.1,   0.,  0
2019-09-23T21:04:16.233Z,1569272656.233 [RDI_Pathfinder](ERROR): Failed to parse:
68,-32768,-32768,V
2019-09-23T21:04:25.909Z,1569272665.909 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T21:04:25.910Z,1569272665.910 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-09-23T21:04:34.766Z,1569272674.766 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T21:04:34.766Z,1569272674.766 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T21:05:19.614Z,1569272719.614 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T21:05:19.614Z,1569272719.614 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T21:06:48.898Z,1569272808.898 [NAL9602](INFO): SBD MO Status=2, MOMSN=1435, MT Status=2, MTMSN=0
2019-09-23T21:06:48.898Z,1569272808.898 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-09-23T21:07:28.080Z,1569272848.080 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T21:07:58.794Z,1569272878.794 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:08:04.093Z,1569272884.093 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:08:04.093Z,1569272884.093 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:08:04.093Z,1569272884.093 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:08:04.093Z,1569272884.093 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:08:04.482Z,1569272884.482 [Default:CheckIn:D] Stopped
2019-09-23T21:08:04.482Z,1569272884.482 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:08:04.927Z,1569272884.927 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.865763 min 
2019-09-23T21:08:04.927Z,1569272884.927 [Default:CheckIn:E] Stopped
2019-09-23T21:08:04.927Z,1569272884.927 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:08:04.927Z,1569272884.927 [Default:CheckIn] Stopped
2019-09-23T21:08:04.927Z,1569272884.927 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:08:04.927Z,1569272884.927 [Default:CheckIn](INFO): Running loop #14
2019-09-23T21:08:04.928Z,1569272884.928 [Default:CheckIn] Running Loop=14
2019-09-23T21:08:04.928Z,1569272884.928 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:08:04.928Z,1569272884.928 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:08:06.471Z,1569272886.471 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:08:06.886Z,1569272886.886 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210613.00,A,3648.16271,N,12147.28549,W,0.428,97.15,230919,,,A*46
2019-09-23T21:08:06.907Z,1569272886.907 [NAL9602](INFO): GPS fix at 20190923T210613: (36.802712, -121.788091)
2019-09-23T21:08:06.976Z,1569272886.976 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:08:06.976Z,1569272886.976 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:08:11.271Z,1569272891.271 [DataOverHttps](INFO): Sending 80 bytes from file Logs/20190923T194806/Courier0043.lzma
2019-09-23T21:08:13.281Z,1569272893.281 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0043.lzma.bak
2019-09-23T21:08:13.281Z,1569272893.281 [DataOverHttps](INFO): SBD MOMSN=11805495
2019-09-23T21:08:37.644Z,1569272917.644 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-09-23T21:08:37.727Z,1569272917.727 [NAL9602](FAULT): received: 
+CSQ:0

OK35, 2, 0, 0, 0

OK
2019-09-23T21:08:37.727Z,1569272917.727 [NAL9602] Data Fault, FailCount= 1
2019-09-23T21:08:37.728Z,1569272917.728 [NAL9602](ERROR): Data Fault
2019-09-23T21:08:37.804Z,1569272917.804 [CBIT](ERROR): Data Fault in component: NAL9602
2019-09-23T21:08:38.048Z,1569272918.048 [NAL9602](INFO): Powering down
2019-09-23T21:08:38.958Z,1569272918.958 [CBIT](INFO): Clearing failed state for component NAL9602
2019-09-23T21:08:38.958Z,1569272918.958 [NAL9602] No Fault, FailCount= 1
2019-09-23T21:08:43.639Z,1569272923.639 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190923T194806/Express0044.lzma
2019-09-23T21:08:45.645Z,1569272925.645 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0044.lzma.bak
2019-09-23T21:08:45.646Z,1569272925.646 [DataOverHttps](INFO): SBD MOMSN=11805498
2019-09-23T21:08:57.125Z,1569272937.125 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:08:57.125Z,1569272937.125 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:08:57.125Z,1569272937.125 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:09:08.348Z,1569272948.348 [NAL9602](INFO): Powering up NAL9602
2019-09-23T21:09:14.866Z,1569272954.866 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T21:09:14.866Z,1569272954.866 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-09-23T21:09:19.256Z,1569272959.256 [NAL9602](INFO): NAL9602 initialized
2019-09-23T21:09:50.380Z,1569272990.380 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:13:35.853Z,1569273215.853 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-09-23T21:13:35.853Z,1569273215.853 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-09-23T21:13:57.652Z,1569273237.652 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:13:57.652Z,1569273237.652 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:13:57.652Z,1569273237.652 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:13:57.652Z,1569273237.652 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:13:58.073Z,1569273238.073 [Default:CheckIn:D] Stopped
2019-09-23T21:13:58.073Z,1569273238.073 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:13:58.458Z,1569273238.458 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.758936 min 
2019-09-23T21:13:58.458Z,1569273238.458 [Default:CheckIn:E] Stopped
2019-09-23T21:13:58.459Z,1569273238.459 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:13:58.459Z,1569273238.459 [Default:CheckIn] Stopped
2019-09-23T21:13:58.459Z,1569273238.459 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:13:58.459Z,1569273238.459 [Default:CheckIn](INFO): Running loop #15
2019-09-23T21:13:58.459Z,1569273238.459 [Default:CheckIn] Running Loop=15
2019-09-23T21:13:58.459Z,1569273238.459 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:13:58.460Z,1569273238.460 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:14:00.051Z,1569273240.051 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:14:00.450Z,1569273240.450 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211206.00,A,3648.16089,N,12147.27827,W,0.719,0.00,230919,,,A*73
2019-09-23T21:14:00.464Z,1569273240.464 [NAL9602](INFO): GPS fix at 20190923T211206: (36.802681, -121.787971)
2019-09-23T21:14:00.534Z,1569273240.534 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:14:00.535Z,1569273240.535 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:14:02.552Z,1569273242.552 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T21:14:06.714Z,1569273246.714 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T194806/Courier0046.lzma
2019-09-23T21:14:08.725Z,1569273248.725 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0046.lzma.bak
2019-09-23T21:14:08.725Z,1569273248.725 [DataOverHttps](INFO): SBD MOMSN=11805559
2019-09-23T21:14:31.779Z,1569273271.779 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190923T194806/Express0047.lzma
2019-09-23T21:14:33.267Z,1569273273.267 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:14:33.785Z,1569273273.785 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0047.lzma.bak
2019-09-23T21:14:33.785Z,1569273273.785 [DataOverHttps](INFO): SBD MOMSN=11805562
2019-09-23T21:14:39.370Z,1569273279.370 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:14:39.370Z,1569273279.370 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:14:39.370Z,1569273279.370 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:19:39.937Z,1569273579.937 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:19:39.937Z,1569273579.937 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:19:39.937Z,1569273579.937 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:19:39.937Z,1569273579.937 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:19:40.351Z,1569273580.351 [Default:CheckIn:D] Stopped
2019-09-23T21:19:40.351Z,1569273580.351 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:19:40.763Z,1569273580.763 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.463574 min 
2019-09-23T21:19:40.763Z,1569273580.763 [Default:CheckIn:E] Stopped
2019-09-23T21:19:40.763Z,1569273580.763 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:19:40.763Z,1569273580.763 [Default:CheckIn] Stopped
2019-09-23T21:19:40.763Z,1569273580.763 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:19:40.764Z,1569273580.764 [Default:CheckIn](INFO): Running loop #16
2019-09-23T21:19:40.764Z,1569273580.764 [Default:CheckIn] Running Loop=16
2019-09-23T21:19:40.764Z,1569273580.764 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:19:40.764Z,1569273580.764 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:19:42.339Z,1569273582.339 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:19:42.734Z,1569273582.734 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211748.00,A,3648.17048,N,12147.28802,W,0.330,0.00,230919,,,A*77
2019-09-23T21:19:42.737Z,1569273582.737 [NAL9602](INFO): GPS fix at 20190923T211748: (36.802841, -121.788134)
2019-09-23T21:19:42.774Z,1569273582.774 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:19:42.774Z,1569273582.774 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:19:46.980Z,1569273586.980 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0049.lzma
2019-09-23T21:19:48.991Z,1569273588.991 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0049.lzma.bak
2019-09-23T21:19:48.992Z,1569273588.992 [DataOverHttps](INFO): SBD MOMSN=11805574
2019-09-23T21:20:12.031Z,1569273612.031 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190923T194806/Express0050.lzma
2019-09-23T21:20:14.037Z,1569273614.037 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0050.lzma.bak
2019-09-23T21:20:14.037Z,1569273614.037 [DataOverHttps](INFO): SBD MOMSN=11805577
2019-09-23T21:20:20.046Z,1569273620.046 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:20:20.046Z,1569273620.046 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:20:20.046Z,1569273620.046 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:24:44.620Z,1569273884.620 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T21:25:15.324Z,1569273915.324 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:25:20.602Z,1569273920.602 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:25:20.602Z,1569273920.602 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:25:20.602Z,1569273920.602 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:25:20.602Z,1569273920.602 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:25:21.022Z,1569273921.022 [Default:CheckIn:D] Stopped
2019-09-23T21:25:21.022Z,1569273921.022 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:25:21.466Z,1569273921.466 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 93.141431 min 
2019-09-23T21:25:21.466Z,1569273921.466 [Default:CheckIn:E] Stopped
2019-09-23T21:25:21.467Z,1569273921.467 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:25:21.467Z,1569273921.467 [Default:CheckIn] Stopped
2019-09-23T21:25:21.467Z,1569273921.467 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:25:21.467Z,1569273921.467 [Default:CheckIn](INFO): Running loop #17
2019-09-23T21:25:21.467Z,1569273921.467 [Default:CheckIn] Running Loop=17
2019-09-23T21:25:21.467Z,1569273921.467 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:25:21.467Z,1569273921.467 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:25:23.011Z,1569273923.011 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:25:23.406Z,1569273923.406 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212330.00,A,3648.16817,N,12147.28394,W,0.214,0.00,230919,,,A*7F
2019-09-23T21:25:23.413Z,1569273923.413 [NAL9602](INFO): GPS fix at 20190923T212330: (36.802803, -121.788066)
2019-09-23T21:25:23.465Z,1569273923.465 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:25:23.465Z,1569273923.465 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:25:26.925Z,1569273926.925 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190923T194806/Courier0052.lzma
2019-09-23T21:25:28.933Z,1569273928.933 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0052.lzma.bak
2019-09-23T21:25:28.933Z,1569273928.933 [DataOverHttps](INFO): SBD MOMSN=11805677
2019-09-23T21:25:51.371Z,1569273951.371 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190923T194806/Express0053.lzma
2019-09-23T21:25:53.377Z,1569273953.377 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0053.lzma.bak
2019-09-23T21:25:53.377Z,1569273953.377 [DataOverHttps](INFO): SBD MOMSN=11805684
2019-09-23T21:25:54.108Z,1569273954.108 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-09-23T21:25:54.191Z,1569273954.191 [NAL9602](FAULT): received: 
+CSQ:0

OK35, 2, 0, 0, 0

OK
2019-09-23T21:25:54.191Z,1569273954.191 [NAL9602] Data Fault, FailCount= 1
2019-09-23T21:25:54.191Z,1569273954.191 [NAL9602](ERROR): Data Fault
2019-09-23T21:25:54.258Z,1569273954.258 [CBIT](ERROR): Data Fault in component: NAL9602
2019-09-23T21:25:54.512Z,1569273954.512 [NAL9602](INFO): Powering down
2019-09-23T21:25:55.377Z,1569273955.377 [CBIT](INFO): Clearing failed state for component NAL9602
2019-09-23T21:25:55.377Z,1569273955.377 [NAL9602] No Fault, FailCount= 1
2019-09-23T21:25:59.419Z,1569273959.419 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:25:59.423Z,1569273959.423 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:25:59.423Z,1569273959.423 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:26:24.840Z,1569273984.840 [NAL9602](INFO): Powering up NAL9602
2019-09-23T21:26:35.729Z,1569273995.729 [NAL9602](INFO): NAL9602 initialized
2019-09-23T21:27:06.858Z,1569274026.858 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:30:59.984Z,1569274259.984 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:30:59.984Z,1569274259.984 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:30:59.984Z,1569274259.984 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:30:59.985Z,1569274259.985 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:31:00.394Z,1569274260.394 [Default:CheckIn:D] Stopped
2019-09-23T21:31:00.394Z,1569274260.394 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:31:00.782Z,1569274260.782 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.797624 min 
2019-09-23T21:31:00.782Z,1569274260.782 [Default:CheckIn:E] Stopped
2019-09-23T21:31:00.782Z,1569274260.782 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:31:00.783Z,1569274260.783 [Default:CheckIn] Stopped
2019-09-23T21:31:00.783Z,1569274260.783 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:31:00.783Z,1569274260.783 [Default:CheckIn](INFO): Running loop #18
2019-09-23T21:31:00.783Z,1569274260.783 [Default:CheckIn] Running Loop=18
2019-09-23T21:31:00.783Z,1569274260.783 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:31:00.783Z,1569274260.783 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:31:02.383Z,1569274262.383 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:31:02.793Z,1569274262.793 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212908.00,A,3648.16549,N,12147.28092,W,0.175,104.82,230919,,,A*76
2019-09-23T21:31:02.795Z,1569274262.795 [NAL9602](INFO): GPS fix at 20190923T212908: (36.802758, -121.788015)
2019-09-23T21:31:02.897Z,1569274262.897 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:31:02.897Z,1569274262.897 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:31:04.477Z,1569274264.477 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T21:31:07.021Z,1569274267.021 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0055.lzma
2019-09-23T21:31:22.097Z,1569274282.097 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0055.lzma.bak
2019-09-23T21:31:22.097Z,1569274282.097 [DataOverHttps](INFO): SBD MOMSN=11805695
2019-09-23T21:31:35.172Z,1569274295.172 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:31:44.360Z,1569274304.360 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20190923T194806/Express0056.lzma
2019-09-23T21:31:46.365Z,1569274306.365 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0056.lzma.bak
2019-09-23T21:31:46.365Z,1569274306.365 [DataOverHttps](INFO): SBD MOMSN=11805698
2019-09-23T21:31:51.781Z,1569274311.781 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:31:51.781Z,1569274311.781 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:31:51.781Z,1569274311.781 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:36:52.354Z,1569274612.354 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:36:52.354Z,1569274612.354 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:36:52.354Z,1569274612.354 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:36:52.354Z,1569274612.354 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:36:52.751Z,1569274612.751 [Default:CheckIn:D] Stopped
2019-09-23T21:36:52.751Z,1569274612.751 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:36:53.164Z,1569274613.164 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 104.670239 min 
2019-09-23T21:36:53.164Z,1569274613.164 [Default:CheckIn:E] Stopped
2019-09-23T21:36:53.164Z,1569274613.164 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:36:53.164Z,1569274613.164 [Default:CheckIn] Stopped
2019-09-23T21:36:53.164Z,1569274613.164 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:36:53.165Z,1569274613.165 [Default:CheckIn](INFO): Running loop #19
2019-09-23T21:36:53.165Z,1569274613.165 [Default:CheckIn] Running Loop=19
2019-09-23T21:36:53.165Z,1569274613.165 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:36:53.165Z,1569274613.165 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:36:54.755Z,1569274614.755 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:36:55.146Z,1569274615.146 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213502.00,A,3648.16537,N,12147.28373,W,0.117,135.11,230919,,,A*78
2019-09-23T21:36:55.160Z,1569274615.160 [NAL9602](INFO): GPS fix at 20190923T213502: (36.802756, -121.788062)
2019-09-23T21:36:55.218Z,1569274615.218 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:36:55.218Z,1569274615.218 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:36:59.848Z,1569274619.848 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190923T194806/Courier0058.lzma
2019-09-23T21:37:01.857Z,1569274621.857 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0058.lzma.bak
2019-09-23T21:37:01.857Z,1569274621.857 [DataOverHttps](INFO): SBD MOMSN=11805799
2019-09-23T21:37:23.911Z,1569274643.911 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20190923T194806/Express0059.lzma
2019-09-23T21:37:25.917Z,1569274645.917 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0059.lzma.bak
2019-09-23T21:37:25.917Z,1569274645.917 [DataOverHttps](INFO): SBD MOMSN=11805802
2019-09-23T21:37:31.626Z,1569274651.626 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:37:31.626Z,1569274651.626 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:37:31.626Z,1569274651.626 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:40:35.054Z,1569274835.054 [RDI_Pathfinder](ERROR): Failed to parse:
    +0.00,        +0.00,        +0.00,   0.00,6720.05
2019-09-23T21:41:09.392Z,1569274869.392 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-09-23T21:41:09.392Z,1569274869.392 [RDI_Pathfinder](ERROR): Failed to parse:
:RA   0.00,   0.00,   0.00,   0.00
2019-09-23T21:41:57.828Z,1569274917.828 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T21:42:28.540Z,1569274948.540 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:42:32.234Z,1569274952.234 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:42:32.234Z,1569274952.234 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:42:32.234Z,1569274952.234 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:42:32.234Z,1569274952.234 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:42:32.606Z,1569274952.606 [Default:CheckIn:D] Stopped
2019-09-23T21:42:32.606Z,1569274952.606 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 110.334497 min 
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn:E] Stopped
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn] Stopped
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn](INFO): Running loop #20
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn] Running Loop=20
2019-09-23T21:42:33.030Z,1569274953.030 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:42:33.031Z,1569274953.031 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:42:34.615Z,1569274954.615 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:42:34.997Z,1569274954.997 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214041.00,A,3648.16207,N,12147.28167,W,0.369,135.11,230919,,,A*75
2019-09-23T21:42:34.999Z,1569274954.999 [NAL9602](INFO): GPS fix at 20190923T214041: (36.802701, -121.788028)
2019-09-23T21:42:35.066Z,1569274955.066 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:42:35.066Z,1569274955.066 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:42:46.259Z,1569274966.259 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T194806/Courier0061.lzma
2019-09-23T21:42:48.265Z,1569274968.265 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0061.lzma.bak
2019-09-23T21:42:48.265Z,1569274968.265 [DataOverHttps](INFO): SBD MOMSN=11805816
2019-09-23T21:43:11.115Z,1569274991.115 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190923T194806/Express0062.lzma
2019-09-23T21:43:13.121Z,1569274993.121 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0062.lzma.bak
2019-09-23T21:43:13.121Z,1569274993.121 [DataOverHttps](INFO): SBD MOMSN=11805827
2019-09-23T21:43:18.666Z,1569274998.666 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:43:18.666Z,1569274998.666 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:43:18.666Z,1569274998.666 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:43:56.176Z,1569275036.176 [CommandLine](IMPORTANT): got command failComponent
2019-09-23T21:43:56.181Z,1569275036.181 [CommandLine](IMPORTANT): Failed components:
2019-09-23T21:43:56.181Z,1569275036.181 [CommandLine](IMPORTANT): No failed Components.
2019-09-23T21:47:36.783Z,1569275256.783 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T21:48:07.504Z,1569275287.504 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:48:19.251Z,1569275299.251 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:48:19.251Z,1569275299.251 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:48:19.251Z,1569275299.251 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:48:19.251Z,1569275299.251 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:48:19.648Z,1569275299.648 [Default:CheckIn:D] Stopped
2019-09-23T21:48:19.648Z,1569275299.648 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:48:20.047Z,1569275300.047 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 116.118530 min 
2019-09-23T21:48:20.047Z,1569275300.047 [Default:CheckIn:E] Stopped
2019-09-23T21:48:20.047Z,1569275300.047 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:48:20.047Z,1569275300.047 [Default:CheckIn] Stopped
2019-09-23T21:48:20.071Z,1569275300.071 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:48:20.071Z,1569275300.071 [Default:CheckIn](INFO): Running loop #21
2019-09-23T21:48:20.071Z,1569275300.071 [Default:CheckIn] Running Loop=21
2019-09-23T21:48:20.072Z,1569275300.072 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:48:20.072Z,1569275300.072 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:48:21.639Z,1569275301.639 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:48:22.038Z,1569275302.038 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214628.00,A,3648.16517,N,12147.28239,W,0.214,0.00,230919,,,A*7E
2019-09-23T21:48:22.040Z,1569275302.040 [NAL9602](INFO): GPS fix at 20190923T214628: (36.802753, -121.788040)
2019-09-23T21:48:22.128Z,1569275302.128 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:48:22.128Z,1569275302.128 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:48:31.200Z,1569275311.200 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190923T194806/Courier0064.lzma
2019-09-23T21:48:33.209Z,1569275313.209 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0064.lzma.bak
2019-09-23T21:48:33.209Z,1569275313.209 [DataOverHttps](INFO): SBD MOMSN=11805883
2019-09-23T21:48:52.852Z,1569275332.852 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-09-23T21:48:52.927Z,1569275332.927 [NAL9602](FAULT): received: 
+CSQ:0

OK35, 2, 0, 0, 0

OK
2019-09-23T21:48:52.927Z,1569275332.927 [NAL9602] Data Fault, FailCount= 1
2019-09-23T21:48:52.928Z,1569275332.928 [NAL9602](ERROR): Data Fault
2019-09-23T21:48:53.051Z,1569275333.051 [CBIT](ERROR): Data Fault in component: NAL9602
2019-09-23T21:48:53.248Z,1569275333.248 [NAL9602](INFO): Powering down
2019-09-23T21:48:54.168Z,1569275334.168 [CBIT](INFO): Clearing failed state for component NAL9602
2019-09-23T21:48:54.168Z,1569275334.168 [NAL9602] No Fault, FailCount= 1
2019-09-23T21:49:01.027Z,1569275341.027 [DataOverHttps](INFO): Sending 249 bytes from file Logs/20190923T194806/Express0065.lzma
2019-09-23T21:49:03.033Z,1569275343.033 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0065.lzma.bak
2019-09-23T21:49:03.033Z,1569275343.033 [DataOverHttps](INFO): SBD MOMSN=11805886
2019-09-23T21:49:09.075Z,1569275349.075 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:49:09.079Z,1569275349.079 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:49:09.079Z,1569275349.079 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:49:23.548Z,1569275363.548 [NAL9602](INFO): Powering up NAL9602
2019-09-23T21:49:34.456Z,1569275374.456 [NAL9602](INFO): NAL9602 initialized
2019-09-23T21:50:05.568Z,1569275405.568 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:54:09.633Z,1569275649.633 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-09-23T21:54:09.633Z,1569275649.633 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:54:09.633Z,1569275649.633 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:54:09.633Z,1569275649.633 [Default:CheckIn:D] Running Loop=1
2019-09-23T21:54:10.039Z,1569275650.039 [Default:CheckIn:D] Stopped
2019-09-23T21:54:10.039Z,1569275650.039 [Default:CheckIn:E] Running Loop=1
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 121.958366 min 
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn:E] Stopped
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn] Stopped
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn](INFO): Running loop #22
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn] Running Loop=22
2019-09-23T21:54:10.456Z,1569275650.456 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-09-23T21:54:10.457Z,1569275650.457 [Default:CheckIn:Read_GPS] Running Loop=1
2019-09-23T21:54:12.027Z,1569275652.027 [NAL9602](DEBUG): Fix Requested
2019-09-23T21:54:12.422Z,1569275652.422 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215218.00,A,3648.16315,N,12147.28280,W,1.166,0.00,230919,,,A*79
2019-09-23T21:54:12.424Z,1569275652.424 [NAL9602](INFO): GPS fix at 20190923T215218: (36.802719, -121.788047)
2019-09-23T21:54:12.450Z,1569275652.450 [Default:CheckIn:Read_GPS] Stopped
2019-09-23T21:54:12.450Z,1569275652.450 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-09-23T21:54:14.553Z,1569275654.553 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-09-23T21:54:15.649Z,1569275655.649 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190923T194806/Courier0067.lzma
2019-09-23T21:54:17.661Z,1569275657.661 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Courier0067.lzma.bak
2019-09-23T21:54:17.661Z,1569275657.661 [DataOverHttps](INFO): SBD MOMSN=11805912
2019-09-23T21:54:40.959Z,1569275680.959 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190923T194806/Express0068.lzma
2019-09-23T21:54:42.965Z,1569275682.965 [DataOverHttps](INFO): Moved sent file to Logs/20190923T194806/Express0068.lzma.bak
2019-09-23T21:54:42.965Z,1569275682.965 [DataOverHttps](INFO): SBD MOMSN=11805918
2019-09-23T21:54:45.257Z,1569275685.257 [NAL9602](INFO): Not Powering down - fast GPS
2019-09-23T21:54:48.543Z,1569275688.543 [Default:CheckIn:Read_Iridium] Stopped
2019-09-23T21:54:48.543Z,1569275688.543 [Default:CheckIn:C.Wait] Running Loop=1
2019-09-23T21:54:48.543Z,1569275688.543 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-09-23T21:54:56.257Z,1569275696.257 [CommandLine](IMPORTANT): got command restart application
2019-09-23T21:54:57.299Z,1569275697.299 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-09-23T21:54:57.299Z,1569275697.299 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:57.300Z,1569275697.300 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.479Z,1569275697.479 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-09-23T21:54:57.480Z,1569275697.480 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.481Z,1569275697.481 [CommandLine](INFO): Join timeout helper Thread ID is 1113
2019-09-23T21:54:57.482Z,1569275697.482 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-09-23T21:54:57.482Z,1569275697.482 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.483Z,1569275697.483 [NavChartDb](INFO): Join timeout helper Thread ID is 1114
2019-09-23T21:54:57.551Z,1569275697.551 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:57.552Z,1569275697.552 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.567Z,1569275697.567 [ComponentRegistry](INFO): Shutting down WetLabsUBAT ThreadHandler
2019-09-23T21:54:57.567Z,1569275697.567 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.568Z,1569275697.568 [WetLabsUBAT](INFO): Join timeout helper Thread ID is 1115
2019-09-23T21:54:57.784Z,1569275697.784 [WetLabsUBAT ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:57.784Z,1569275697.784 [WetLabsUBAT](INFO): uninitialize
2019-09-23T21:54:57.784Z,1569275697.784 [WetLabsUBAT](INFO): Powering down
2019-09-23T21:54:57.800Z,1569275697.800 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.819Z,1569275697.819 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-09-23T21:54:57.820Z,1569275697.820 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.820Z,1569275697.820 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1116
2019-09-23T21:54:57.956Z,1569275697.956 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:57.957Z,1569275697.957 [WetLabsBB2FL](INFO): Powering down
2019-09-23T21:54:57.957Z,1569275697.957 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.959Z,1569275697.959 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-09-23T21:54:57.959Z,1569275697.959 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:57.960Z,1569275697.960 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1117
2019-09-23T21:54:58.960Z,1569275698.960 [CTD_Seabird](INFO): Powering down
2019-09-23T21:54:58.976Z,1569275698.976 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:58.983Z,1569275698.983 [CTD_Seabird](INFO): Powering down
2019-09-23T21:54:58.999Z,1569275698.999 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.013Z,1569275699.013 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-09-23T21:54:59.013Z,1569275699.013 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.013Z,1569275699.013 [Radio_Surface](INFO): Join timeout helper Thread ID is 1118
2019-09-23T21:54:59.391Z,1569275699.391 [Radio_Surface](INFO): Powering down
2019-09-23T21:54:59.392Z,1569275699.392 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:59.392Z,1569275699.392 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.400Z,1569275699.400 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-09-23T21:54:59.400Z,1569275699.400 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.401Z,1569275699.401 [DataOverHttps](INFO): Join timeout helper Thread ID is 1119
2019-09-23T21:54:59.599Z,1569275699.599 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:59.603Z,1569275699.603 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.604Z,1569275699.604 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-09-23T21:54:59.604Z,1569275699.604 [logger ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.605Z,1569275699.605 [logger](INFO): Join timeout helper Thread ID is 1120
2019-09-23T21:54:59.627Z,1569275699.627 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:59.628Z,1569275699.628 [logger ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.644Z,1569275699.644 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-09-23T21:54:59.644Z,1569275699.644 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.644Z,1569275699.644 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-09-23T21:54:59.644Z,1569275699.644 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:54:59.645Z,1569275699.645 [controlThread](INFO): Join timeout helper Thread ID is 1121
2019-09-23T21:54:59.783Z,1569275699.783 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-09-23T21:54:59.784Z,1569275699.784 [controlThread](DEBUG): Uninitializing ControlThread
2019-09-23T21:54:59.784Z,1569275699.784 [AHRS_M2](INFO): Powering down
2019-09-23T21:54:59.856Z,1569275699.856 [NAL9602](INFO): Powering down
2019-09-23T21:54:59.927Z,1569275699.927 [RDI_Pathfinder](INFO): Powering down
2019-09-23T21:54:59.928Z,1569275699.928 [DAT](INFO): Powering down
2019-09-23T21:55:00.048Z,1569275700.048 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-09-23T21:55:00.049Z,1569275700.049 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-09-23T21:55:00.049Z,1569275700.049 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-09-23T21:55:00.050Z,1569275700.050 [MissionManager](INFO): Uninitializing Mission Default
2019-09-23T21:55:00.050Z,1569275700.050 [Default] Stopped
2019-09-23T21:55:00.050Z,1569275700.050 [Default](DEBUG): Aggregate::uninitialize Default
2019-09-23T21:55:00.050Z,1569275700.050 [Default:B.GoToSurface] Stopped
2019-09-23T21:55:00.050Z,1569275700.050 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-09-23T21:55:00.050Z,1569275700.050 [Default:CheckIn] Stopped
2019-09-23T21:55:00.050Z,1569275700.050 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-09-23T21:55:00.050Z,1569275700.050 [Default:CheckIn:C.Wait] Stopped
2019-09-23T21:55:00.051Z,1569275700.051 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-09-23T21:55:00.053Z,1569275700.053 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-09-23T21:55:00.053Z,1569275700.053 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-09-23T21:55:00.053Z,1569275700.053 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-09-23T21:55:00.054Z,1569275700.054 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-09-23T21:55:00.054Z,1569275700.054 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-09-23T21:55:00.055Z,1569275700.055 [BuoyancyServo](INFO): Powering down
2019-09-23T21:55:00.067Z,1569275700.067 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-09-23T21:55:00.068Z,1569275700.068 [ElevatorServo](INFO): Powering down
2019-09-23T21:55:00.068Z,1569275700.068 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-09-23T21:55:00.069Z,1569275700.069 [MassServo](INFO): Powering down
2019-09-23T21:55:00.069Z,1569275700.069 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-09-23T21:55:00.069Z,1569275700.069 [RudderServo](INFO): Powering down
2019-09-23T21:55:00.070Z,1569275700.070 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-09-23T21:55:00.070Z,1569275700.070 [ThrusterServo](INFO): Powering down
2019-09-23T21:55:00.071Z,1569275700.071 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-09-23T21:55:00.072Z,1569275700.072 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-09-23T21:55:00.072Z,1569275700.072 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-09-23T21:55:00.072Z,1569275700.072 [CBIT](DEBUG): Powering off loads.
2019-09-23T21:55:00.083Z,1569275700.083 [CBIT](DEBUG): Disabling WDT.
2019-09-23T21:55:00.095Z,1569275700.095 [CBIT](DEBUG): Opening all GF detection circuits.
2019-09-23T21:55:00.096Z,1569275700.096 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:55:00.205Z,1569275700.205 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:55:00.212Z,1569275700.212 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:55:00.284Z,1569275700.284 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:55:00.328Z,1569275700.328 [WetLabsUBAT](INFO): WetLabs destructor: _dataLog is not open
2019-09-23T21:55:00.328Z,1569275700.328 [WetLabsUBAT](INFO): WetLabs destructor: done
2019-09-23T21:55:00.340Z,1569275700.340 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:55:00.342Z,1569275700.342 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:55:00.358Z,1569275700.358 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-09-23T21:55:00.430Z,1569275700.430 [logger ThreadHandler](INFO): Thread cancelled.