2019-05-07T01:24:00.187Z,1557192240.187 [Supervisor](DEBUG): Initializing supervisor.
2019-05-07T01:24:00.190Z,1557192240.190 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-07T01:24:00.191Z,1557192240.191 [SyncHandler](INFO): Protected caller Thread ID is 1379
2019-05-07T01:24:00.191Z,1557192240.191 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-07T01:24:00.192Z,1557192240.192 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-07T01:24:00.193Z,1557192240.193 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1380
2019-05-07T01:24:00.196Z,1557192240.196 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-07T01:24:00.208Z,1557192240.208 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-07T01:24:00.209Z,1557192240.209 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-07T01:24:00.209Z,1557192240.209 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1381
2019-05-07T01:24:00.210Z,1557192240.210 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-07T01:24:00.211Z,1557192240.211 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-07T01:24:00.211Z,1557192240.211 [logger ThreadHandler](INFO): Protected caller Thread ID is 1382
2019-05-07T01:24:00.213Z,1557192240.213 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-07T01:24:00.213Z,1557192240.213 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-07T01:24:00.215Z,1557192240.215 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-07T01:24:00.867Z,1557192240.867 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-07T01:24:00.867Z,1557192240.867 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-07T01:24:00.966Z,1557192240.966 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-07T01:24:00.966Z,1557192240.966 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-07T01:24:01.293Z,1557192241.293 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-07T01:24:01.294Z,1557192241.294 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-07T01:24:01.436Z,1557192241.436 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-07T01:24:01.437Z,1557192241.437 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-07T01:24:01.643Z,1557192241.643 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-07T01:24:01.644Z,1557192241.644 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-07T01:24:02.163Z,1557192242.163 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-07T01:24:02.164Z,1557192242.164 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-07T01:24:02.375Z,1557192242.375 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-07T01:24:02.376Z,1557192242.376 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-07T01:24:02.522Z,1557192242.522 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-07T01:24:02.523Z,1557192242.523 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-07T01:24:02.718Z,1557192242.718 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-07T01:24:02.719Z,1557192242.719 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-07T01:24:02.815Z,1557192242.815 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-07T01:24:02.816Z,1557192242.816 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-07T01:24:03.139Z,1557192243.139 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-07T01:24:03.140Z,1557192243.140 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-07T01:24:03.220Z,1557192243.220 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-07T01:24:03.323Z,1557192243.323 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-07T01:24:03.324Z,1557192243.324 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-07T01:24:03.904Z,1557192243.904 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-07T01:24:03.904Z,1557192243.904 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-07T01:24:04.300Z,1557192244.300 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-07T01:24:04.302Z,1557192244.302 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-07T01:24:04.303Z,1557192244.303 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-07T01:24:04.512Z,1557192244.512 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-07T01:24:04.613Z,1557192244.613 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-07T01:24:04.711Z,1557192244.711 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-07T01:24:04.940Z,1557192244.940 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-07T01:24:04.941Z,1557192244.941 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-07T01:24:05.025Z,1557192245.025 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-07T01:24:05.119Z,1557192245.119 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-07T01:24:05.215Z,1557192245.215 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-07T01:24:05.298Z,1557192245.298 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-07T01:24:05.407Z,1557192245.407 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-07T01:24:05.577Z,1557192245.577 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-07T01:24:05.709Z,1557192245.709 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-07T01:24:05.709Z,1557192245.709 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-07T01:24:05.723Z,1557192245.723 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-07T01:24:06.123Z,1557192246.123 [AHRS_M2] Loaded
2019-05-07T01:24:06.123Z,1557192246.123 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-07T01:24:06.197Z,1557192246.197 [DataOverHttps] Loaded
2019-05-07T01:24:06.197Z,1557192246.197 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-07T01:24:06.198Z,1557192246.198 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-07T01:24:06.199Z,1557192246.199 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1461
2019-05-07T01:24:06.212Z,1557192246.212 [Depth_Keller] Loaded
2019-05-07T01:24:06.212Z,1557192246.212 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-07T01:24:06.217Z,1557192246.217 [DropWeight] Loaded
2019-05-07T01:24:06.218Z,1557192246.218 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-07T01:24:06.276Z,1557192246.276 [DUSBL_Hydroid] Loaded
2019-05-07T01:24:06.277Z,1557192246.277 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-07T01:24:06.318Z,1557192246.318 [Micromodem] Loaded
2019-05-07T01:24:06.319Z,1557192246.319 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-07T01:24:06.421Z,1557192246.421 [NAL9602] Loaded
2019-05-07T01:24:06.422Z,1557192246.422 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-07T01:24:06.438Z,1557192246.438 [Onboard] Loaded
2019-05-07T01:24:06.438Z,1557192246.438 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-07T01:24:06.444Z,1557192246.444 [PowerOnly] Loaded
2019-05-07T01:24:06.444Z,1557192246.444 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-07T01:24:06.451Z,1557192246.451 [Radio_Surface] Loaded
2019-05-07T01:24:06.451Z,1557192246.451 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-07T01:24:06.452Z,1557192246.452 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-07T01:24:06.453Z,1557192246.453 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1462
2019-05-07T01:24:06.499Z,1557192246.499 [RDI_Pathfinder] Loaded
2019-05-07T01:24:06.499Z,1557192246.499 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-07T01:24:08.605Z,1557192248.605 [BPC1] Loaded
2019-05-07T01:24:08.605Z,1557192248.605 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-07T01:24:08.605Z,1557192248.605 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-07T01:24:08.606Z,1557192248.606 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-07T01:24:08.619Z,1557192248.619 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-07T01:24:08.620Z,1557192248.620 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-07T01:24:08.729Z,1557192248.729 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-07T01:24:08.730Z,1557192248.730 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-07T01:24:08.751Z,1557192248.751 [NavChart] Loaded
2019-05-07T01:24:08.751Z,1557192248.751 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-07T01:24:08.755Z,1557192248.755 [UniversalFixResidualReporter] Loaded
2019-05-07T01:24:08.755Z,1557192248.755 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-07T01:24:08.756Z,1557192248.756 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-07T01:24:08.756Z,1557192248.756 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-07T01:24:08.870Z,1557192248.870 [BuoyancyServo] Loaded
2019-05-07T01:24:08.870Z,1557192248.870 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-07T01:24:08.886Z,1557192248.886 [ElevatorServo] Loaded
2019-05-07T01:24:08.886Z,1557192248.886 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-07T01:24:08.901Z,1557192248.901 [MassServo] Loaded
2019-05-07T01:24:08.902Z,1557192248.902 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-07T01:24:08.917Z,1557192248.917 [RudderServo] Loaded
2019-05-07T01:24:08.917Z,1557192248.917 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-07T01:24:08.932Z,1557192248.932 [ThrusterServo] Loaded
2019-05-07T01:24:08.933Z,1557192248.933 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-07T01:24:08.933Z,1557192248.933 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-07T01:24:08.934Z,1557192248.934 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-07T01:24:09.192Z,1557192249.192 [CTD_NeilBrown] Loaded
2019-05-07T01:24:09.193Z,1557192249.193 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-07T01:24:09.194Z,1557192249.194 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-07T01:24:09.194Z,1557192249.194 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1463
2019-05-07T01:24:09.240Z,1557192249.240 [WetLabsSeaOWL_UV_A] Loaded
2019-05-07T01:24:09.241Z,1557192249.241 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-07T01:24:09.242Z,1557192249.242 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-07T01:24:09.242Z,1557192249.242 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1464
2019-05-07T01:24:09.243Z,1557192249.243 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-07T01:24:09.243Z,1557192249.243 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-07T01:24:09.552Z,1557192249.552 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-07T01:24:09.553Z,1557192249.553 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-07T01:24:09.595Z,1557192249.595 [DepthRateCalculator] Loaded
2019-05-07T01:24:09.595Z,1557192249.595 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-07T01:24:09.601Z,1557192249.601 [PitchRateCalculator] Loaded
2019-05-07T01:24:09.601Z,1557192249.601 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-07T01:24:09.614Z,1557192249.614 [SpeedCalculator] Loaded
2019-05-07T01:24:09.615Z,1557192249.615 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-07T01:24:09.636Z,1557192249.636 [TempGradientCalculator] Loaded
2019-05-07T01:24:09.636Z,1557192249.636 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-07T01:24:09.642Z,1557192249.642 [YawRateCalculator] Loaded
2019-05-07T01:24:09.642Z,1557192249.642 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-07T01:24:09.684Z,1557192249.684 [ElevatorOffsetCalculator] Loaded
2019-05-07T01:24:09.685Z,1557192249.685 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-07T01:24:09.685Z,1557192249.685 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-07T01:24:09.686Z,1557192249.686 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-07T01:24:09.831Z,1557192249.831 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-07T01:24:09.853Z,1557192249.853 [SBIT] Loaded
2019-05-07T01:24:09.853Z,1557192249.853 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-07T01:24:09.854Z,1557192249.854 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-07T01:24:09.866Z,1557192249.866 [IBIT] Loaded
2019-05-07T01:24:09.866Z,1557192249.866 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-07T01:24:09.869Z,1557192249.869 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-07T01:24:10.011Z,1557192250.011 [CBIT] Loaded
2019-05-07T01:24:10.012Z,1557192250.012 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-07T01:24:10.012Z,1557192250.012 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-07T01:24:10.012Z,1557192250.012 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-07T01:24:10.085Z,1557192250.085 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-07T01:24:10.086Z,1557192250.086 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-07T01:24:10.191Z,1557192250.191 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-07T01:24:10.192Z,1557192250.192 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-07T01:24:10.262Z,1557192250.262 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-07T01:24:10.348Z,1557192250.348 [VerticalControl] Loaded
2019-05-07T01:24:10.349Z,1557192250.349 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-07T01:24:10.349Z,1557192250.349 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-07T01:24:10.410Z,1557192250.410 [HorizontalControl] Loaded
2019-05-07T01:24:10.410Z,1557192250.410 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-07T01:24:10.411Z,1557192250.411 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-07T01:24:10.413Z,1557192250.413 [SpeedControl] Loaded
2019-05-07T01:24:10.413Z,1557192250.413 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-07T01:24:10.414Z,1557192250.414 [LoopControl](DEBUG): Construct LoopControl.
2019-05-07T01:24:10.414Z,1557192250.414 [LoopControl] Loaded
2019-05-07T01:24:10.415Z,1557192250.415 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-07T01:24:10.415Z,1557192250.415 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-07T01:24:10.416Z,1557192250.416 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-07T01:24:10.443Z,1557192250.443 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-07T01:24:10.447Z,1557192250.447 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-07T01:24:10.448Z,1557192250.448 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-07T01:24:10.454Z,1557192250.454 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-07T01:24:10.455Z,1557192250.455 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-07T01:24:10.456Z,1557192250.456 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1465
2019-05-07T01:24:10.460Z,1557192250.460 [Supervisor](INFO): Main Thread ID is 802
2019-05-07T01:24:10.460Z,1557192250.460 [Supervisor](DEBUG): Running supervisor.
2019-05-07T01:24:10.461Z,1557192250.461 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1466
2019-05-07T01:24:10.463Z,1557192250.463 [controlThread ThreadHandler](INFO): Handler Thread ID is 1467
2019-05-07T01:24:10.464Z,1557192250.464 [controlThread](DEBUG): Initializing ControlThread
2019-05-07T01:24:10.469Z,1557192250.469 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-07T01:24:10.470Z,1557192250.470 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-07T01:24:10.471Z,1557192250.471 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-07T01:24:10.471Z,1557192250.471 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-07T01:24:10.471Z,1557192250.471 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-07T01:24:10.472Z,1557192250.472 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-07T01:24:10.472Z,1557192250.472 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-07T01:24:10.473Z,1557192250.473 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-07T01:24:10.473Z,1557192250.473 [SBIT](INFO): Initialize SBIT Component.
2019-05-07T01:24:10.473Z,1557192250.473 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-07T01:24:10.474Z,1557192250.474 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-07T01:24:10.474Z,1557192250.474 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-07T01:24:10.475Z,1557192250.475 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-05-07T01:24:10.476Z,1557192250.476 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-07T01:24:10.477Z,1557192250.477 [IBIT](INFO): Initialize IBIT Component.
2019-05-07T01:24:10.478Z,1557192250.478 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-07T01:24:10.479Z,1557192250.479 [logger ThreadHandler](INFO): Handler Thread ID is 1468
2019-05-07T01:24:10.490Z,1557192250.490 [CBIT](DEBUG): Initialized mux pins.
2019-05-07T01:24:10.490Z,1557192250.490 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-07T01:24:10.499Z,1557192250.499 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1469
2019-05-07T01:24:10.500Z,1557192250.500 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-07T01:24:10.511Z,1557192250.511 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1470
2019-05-07T01:24:10.514Z,1557192250.514 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-07T01:24:10.514Z,1557192250.514 [CBIT](DEBUG): Initializing heartbeat.
2019-05-07T01:24:10.523Z,1557192250.523 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1471
2019-05-07T01:24:10.524Z,1557192250.524 [CTD_NeilBrown](INFO): Powering down
2019-05-07T01:24:10.551Z,1557192250.551 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1472
2019-05-07T01:24:10.551Z,1557192250.551 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T01:24:10.583Z,1557192250.583 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1473
2019-05-07T01:24:10.586Z,1557192250.586 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-07T01:24:10.586Z,1557192250.586 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-07T01:24:10.587Z,1557192250.587 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-07T01:24:10.587Z,1557192250.587 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-07T01:24:10.587Z,1557192250.587 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-07T01:24:10.587Z,1557192250.587 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-07T01:24:10.587Z,1557192250.587 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-07T01:24:10.588Z,1557192250.588 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-07T01:24:10.588Z,1557192250.588 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-07T01:24:10.588Z,1557192250.588 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-07T01:24:10.588Z,1557192250.588 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-07T01:24:10.588Z,1557192250.588 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-07T01:24:10.589Z,1557192250.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-07T01:24:10.589Z,1557192250.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-07T01:24:10.589Z,1557192250.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-07T01:24:10.589Z,1557192250.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-07T01:24:10.589Z,1557192250.589 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-07T01:24:10.589Z,1557192250.589 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-07T01:24:10.622Z,1557192250.622 [CBIT](DEBUG): Backplane powered.
2019-05-07T01:24:10.623Z,1557192250.623 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-07T01:24:10.624Z,1557192250.624 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-07T01:24:10.625Z,1557192250.625 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-07T01:24:10.625Z,1557192250.625 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-07T01:24:10.626Z,1557192250.626 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-07T01:24:10.636Z,1557192250.636 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T01:24:10.663Z,1557192250.663 [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-05-07T01:24:10.663Z,1557192250.663 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-07T01:24:10.724Z,1557192250.724 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-07T01:24:10.725Z,1557192250.725 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-07T01:24:10.735Z,1557192250.735 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-07T01:24:10.761Z,1557192250.761 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-07T01:24:10.772Z,1557192250.772 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-07T01:24:10.777Z,1557192250.777 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-07T01:24:10.797Z,1557192250.797 [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-05-07T01:24:10.801Z,1557192250.801 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,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-05-07T01:24:10.822Z,1557192250.822 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-07T01:24:10.914Z,1557192250.914 [Radio_Surface](INFO): Powering up
2019-05-07T01:24:10.969Z,1557192250.969 [DUSBL_Hydroid](INFO): Powering up
2019-05-07T01:24:10.969Z,1557192250.969 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-07T01:24:11.062Z,1557192251.062 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:24:11.079Z,1557192251.079 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-07T01:24:11.080Z,1557192251.080 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:24:11.087Z,1557192251.087 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-07T01:24:11.087Z,1557192251.087 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:24:11.095Z,1557192251.095 [MassServo](DEBUG): Initializing MassServo.
2019-05-07T01:24:11.095Z,1557192251.095 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:24:11.103Z,1557192251.103 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T01:24:11.103Z,1557192251.103 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:24:11.111Z,1557192251.111 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-07T01:24:11.225Z,1557192251.225 [Micromodem](INFO): Powering up
2019-05-07T01:24:11.225Z,1557192251.225 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-07T01:24:11.970Z,1557192251.970 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-07T01:24:11.970Z,1557192251.970 [RudderServo](FAULT): Rudder failed to initialize
2019-05-07T01:24:11.971Z,1557192251.971 [RudderServo] Communications Fault, FailCount= 1
2019-05-07T01:24:11.971Z,1557192251.971 [RudderServo](ERROR): Communications Fault
2019-05-07T01:24:12.082Z,1557192252.082 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-07T01:24:12.255Z,1557192252.255 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T01:24:12.255Z,1557192252.255 [RudderServo](INFO): Powering down
2019-05-07T01:24:12.927Z,1557192252.927 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-07T01:24:13.047Z,1557192253.047 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-07T01:24:13.051Z,1557192253.051 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-07T01:24:13.052Z,1557192253.052 [RudderServo] No Fault, FailCount= 1
2019-05-07T01:24:16.574Z,1557192256.574 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,012416,INIT,2.0.2769*4D

2019-05-07T01:24:16.989Z,1557192256.989 [Micromodem](ERROR): Response from modem failed NMEA checksum: CREV012416,SLOT1,2.0.27690*62

2019-05-07T01:24:24.251Z,1557192264.251 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T01:24:29.072Z,1557192269.072 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-07T01:24:36.749Z,1557192276.749 [NAL9602](INFO): Powering up NAL9602
2019-05-07T01:24:47.661Z,1557192287.661 [NAL9602](INFO): NAL9602 initialized
2019-05-07T01:24:48.061Z,1557192288.061 [Micromodem](ERROR): Response from modem unexpected: $CADQF,200,1*52

2019-05-07T01:24:48.465Z,1557192288.465 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-07T01:24:48.478Z,1557192288.478 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:24:48.872Z,1557192288.872 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190507012446.938591,05,115,14,0092,0150,246,00,00,01,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,200,-0.10,-999,9760,4000*77

2019-05-07T01:24:54.984Z,1557192294.984 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-07T01:24:54.992Z,1557192294.992 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-07T01:24:56.603Z,1557192296.603 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T01:24:56.603Z,1557192296.603 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050618324024,35.0, -0.1, 48.9,  0
2019-05-07T01:25:06.047Z,1557192306.047 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.022460
CHAN A1 (24V): -0.027028
CHAN A2 (12V): -0.006647
CHAN A3 (5V): -0.002165
CHAN B0 (3.3V): 0.000197
CHAN B1 (3.15aV): -0.000084
CHAN B2 (3.15bV): 0.000033
CHAN B3 (GND): 0.001797
OPEN: 0.005867
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-07T01:25:48.293Z,1557192348.293 [SBIT](IMPORTANT): SBIT PASSED
2019-05-07T01:25:48.336Z,1557192348.336 [CommandLine](IMPORTANT): got command configSet list
2019-05-07T01:25:48.336Z,1557192348.336 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-07T01:25:48.337Z,1557192348.337 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-07T01:25:48.337Z,1557192348.337 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-07T01:25:48.337Z,1557192348.337 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-07T01:25:48.337Z,1557192348.337 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-07T01:25:48.337Z,1557192348.337 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-07T01:25:48.337Z,1557192348.337 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-07T01:25:48.337Z,1557192348.337 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-07T01:25:48.338Z,1557192348.338 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-07T01:25:48.338Z,1557192348.338 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-07T01:25:48.338Z,1557192348.338 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-07T01:25:48.338Z,1557192348.338 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-07T01:25:48.339Z,1557192348.339 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-07T01:25:48.339Z,1557192348.339 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-07T01:25:48.705Z,1557192348.705 [MissionManager](IMPORTANT): Started mission Startup
2019-05-07T01:25:48.705Z,1557192348.705 [Startup] Running Loop=1
2019-05-07T01:25:48.706Z,1557192348.706 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-07T01:25:48.706Z,1557192348.706 [Startup:A.GoToSurface] Running Loop=1
2019-05-07T01:25:48.706Z,1557192348.706 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T01:25:48.707Z,1557192348.707 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T01:25:48.707Z,1557192348.707 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T01:25:48.707Z,1557192348.707 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T01:25:48.708Z,1557192348.708 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T01:25:48.708Z,1557192348.708 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T01:25:48.709Z,1557192348.709 [Startup:StartupSatComms] Running Loop=1
2019-05-07T01:25:48.709Z,1557192348.709 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-07T01:25:48.710Z,1557192348.710 [Startup:StartupSatComms:A] Running Loop=1
2019-05-07T01:25:49.108Z,1557192349.108 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-07T01:26:25.419Z,1557192385.419 [CommandLine](IMPORTANT): got command show variable range
2019-05-07T01:26:25.421Z,1557192385.421 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-07T01:26:25.640Z,1557192385.640 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-07T01:26:25.640Z,1557192385.640 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-07T01:26:25.669Z,1557192385.669 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-07T01:26:25.672Z,1557192385.672 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-07T01:26:25.673Z,1557192385.673 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-07T01:26:25.677Z,1557192385.677 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-07T01:26:25.678Z,1557192385.678 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-07T01:26:25.679Z,1557192385.679 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-07T01:26:25.679Z,1557192385.679 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-07T01:26:25.840Z,1557192385.840 [NAL9602](INFO): SBD MO Status=2, MOMSN=3825, MT Status=2, MTMSN=0
2019-05-07T01:26:25.840Z,1557192385.840 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T01:26:36.676Z,1557192396.676 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004947
2019-05-07T01:26:37.931Z,1557192397.931 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-07T01:26:40.795Z,1557192400.795 [CommandLine](IMPORTANT): got command show stack
2019-05-07T01:26:40.796Z,1557192400.796 [CommandLine](IMPORTANT): Behavior Stack:

2019-05-07T01:26:40.797Z,1557192400.797 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-05-07T01:26:40.797Z,1557192400.797 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:A
2019-05-07T01:26:48.900Z,1557192408.900 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-07T01:25:48.7Z
2019-05-07T01:26:48.900Z,1557192408.900 [Startup:StartupSatComms:A] Stopped
2019-05-07T01:26:48.901Z,1557192408.901 [Startup:StartupSatComms:B] Running Loop=1
2019-05-07T01:26:49.296Z,1557192409.296 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T01:26:54.172Z,1557192414.172 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T01:26:54.172Z,1557192414.172 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T01:26:54.690Z,1557192414.690 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190507T011229/Courier0010.lzma
2019-05-07T01:26:55.334Z,1557192415.334 [NAL9602](INFO): SBD MO Status=2, MOMSN=3825, MT Status=2, MTMSN=0
2019-05-07T01:26:55.335Z,1557192415.335 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T01:26:55.497Z,1557192415.497 [DataOverHttps](INFO): Moved sent file to Logs/20190507T011229/Courier0010.lzma.bak
2019-05-07T01:26:55.497Z,1557192415.497 [DataOverHttps](INFO): SBD MOMSN=10947663
2019-05-07T01:27:09.730Z,1557192429.730 [DataOverHttps](INFO): Sending 286 bytes from file Logs/20190507T011229/Express0011.lzma
2019-05-07T01:27:09.897Z,1557192429.897 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-05-07T01:27:10.536Z,1557192430.536 [DataOverHttps](INFO): Moved sent file to Logs/20190507T011229/Express0011.lzma.bak
2019-05-07T01:27:10.536Z,1557192430.536 [DataOverHttps](INFO): SBD MOMSN=10947665
2019-05-07T01:27:10.731Z,1557192430.731 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-07T01:27:10.731Z,1557192430.731 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-07T01:27:10.745Z,1557192430.745 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-07T01:27:11.178Z,1557192431.178 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-07T01:27:11.178Z,1557192431.178 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-07T01:27:22.806Z,1557192442.806 [NAL9602](INFO): SBD MO Status=0, MOMSN=3825, MT Status=0, MTMSN=0
2019-05-07T01:27:22.806Z,1557192442.806 [NAL9602](INFO): No messages in MT queue
2019-05-07T01:27:23.025Z,1557192443.025 [DataOverHttps](INFO): Sending 1534 bytes from file Logs/20190507T012400/Express0001.lzma
2019-05-07T01:27:23.630Z,1557192443.630 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:23.828Z,1557192443.828 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0001.lzma.bak
2019-05-07T01:27:23.828Z,1557192443.828 [DataOverHttps](INFO): SBD MOMSN=10947668
2019-05-07T01:27:24.855Z,1557192444.855 [Startup:StartupSatComms:B] Stopped
2019-05-07T01:27:24.855Z,1557192444.855 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-07T01:27:24.855Z,1557192444.855 [Startup:StartupSatComms] Stopped
2019-05-07T01:27:24.856Z,1557192444.856 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-07T01:27:24.856Z,1557192444.856 [Startup](INFO): Completed Startup
2019-05-07T01:27:24.856Z,1557192444.856 [MissionManager](INFO): Startup is completed.
2019-05-07T01:27:24.857Z,1557192444.857 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-07T01:27:24.857Z,1557192444.857 [Startup] Stopped
2019-05-07T01:27:24.857Z,1557192444.857 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-07T01:27:24.857Z,1557192444.857 [Startup:A.GoToSurface] Stopped
2019-05-07T01:27:24.857Z,1557192444.857 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T01:27:25.284Z,1557192445.284 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T01:27:25.285Z,1557192445.285 [Default] Running Loop=1
2019-05-07T01:27:25.285Z,1557192445.285 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T01:27:25.285Z,1557192445.285 [Default:B.GoToSurface] Running Loop=1
2019-05-07T01:27:25.285Z,1557192445.285 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T01:27:25.285Z,1557192445.285 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T01:27:25.285Z,1557192445.285 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T01:27:25.286Z,1557192445.286 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T01:27:25.291Z,1557192445.291 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T01:27:25.291Z,1557192445.291 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T01:27:25.291Z,1557192445.291 [Default:A.Wait] Running Loop=1
2019-05-07T01:27:25.292Z,1557192445.292 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:27:26.054Z,1557192446.054 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:29.286Z,1557192449.286 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:32.110Z,1557192452.110 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:34.966Z,1557192454.966 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:38.183Z,1557192458.183 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:38.612Z,1557192458.612 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T01:27:38.612Z,1557192458.612 [Default:A.Wait] Stopped
2019-05-07T01:27:38.612Z,1557192458.612 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:27:39.004Z,1557192459.004 [Default:CheckIn] Running Loop=1
2019-05-07T01:27:39.004Z,1557192459.004 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:27:39.004Z,1557192459.004 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:27:39.410Z,1557192459.410 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-07T01:27:41.010Z,1557192461.010 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:42.888Z,1557192462.888 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-07T01:27:42.888Z,1557192462.888 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-07T01:27:42.915Z,1557192462.915 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-07T01:27:42.919Z,1557192462.919 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-07T01:27:42.923Z,1557192462.923 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-07T01:27:42.926Z,1557192462.926 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-07T01:27:42.930Z,1557192462.930 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-07T01:27:42.931Z,1557192462.931 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-07T01:27:42.937Z,1557192462.937 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-07T01:27:42.947Z,1557192462.947 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-07T01:27:42.951Z,1557192462.951 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         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/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

    <Description>
        This mission is requests a DUSBL arming.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="NumberOfRequests"><Description>
        Number of pings to requst.
    </Description><Units:count/><Value>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>   

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    <ReadData>
        <When>
            <Arg Name="EnabledDUSBL"/>
        </When>
            <Universal:acoustic_contact_range/>
            <Universal:acoustic_contact_direction_vehicle_frame/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

        <Sequence Repeat="NumberOfRequests"/>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.transponderCode/><Arg Name="TransponderCode"/></Assign>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.pingRequested/><Arg Name="NumberOfPings"/></Assign>
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:second/><Value>10</Value></Setting>
          </Guidance:Wait>
      </Aggregate>    
</Mission>


2019-05-07T01:27:42.953Z,1557192462.953 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-07T01:27:43.027Z,1557192463.027 [Default] Stopped
2019-05-07T01:27:43.027Z,1557192463.027 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T01:27:43.027Z,1557192463.027 [Default:B.GoToSurface] Stopped
2019-05-07T01:27:43.028Z,1557192463.028 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T01:27:43.028Z,1557192463.028 [Default:CheckIn] Stopped
2019-05-07T01:27:43.028Z,1557192463.028 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:27:43.028Z,1557192463.028 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:27:43.028Z,1557192463.028 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-07T01:27:43.028Z,1557192463.028 [DUSBL] Running Loop=1
2019-05-07T01:27:43.028Z,1557192463.028 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-07T01:27:43.028Z,1557192463.028 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T01:27:43.028Z,1557192463.028 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:C] Running Loop=1
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:RequestRepeater] Running Loop=1
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:27:43.029Z,1557192463.029 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T01:27:43.030Z,1557192463.030 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:27:43.030Z,1557192463.030 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:27:43.030Z,1557192463.030 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:27:43.031Z,1557192463.031 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-07T01:27:43.032Z,1557192463.032 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-07T01:27:43.032Z,1557192463.032 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-07T01:27:43.032Z,1557192463.032 [DUSBL:A.Pitch] Running Loop=1
2019-05-07T01:27:44.230Z,1557192464.230 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:44.620Z,1557192464.620 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:27:44.620Z,1557192464.620 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:27:44.621Z,1557192464.621 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:27:45.028Z,1557192465.028 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:27:45.028Z,1557192465.028 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:27:47.062Z,1557192467.062 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:49.890Z,1557192469.890 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.269501
2019-05-07T01:27:49.891Z,1557192469.891 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:27:49.891Z,1557192469.891 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:27:49.892Z,1557192469.892 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:27:49.910Z,1557192469.910 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:50.280Z,1557192470.280 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:27:50.280Z,1557192470.280 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:27:53.131Z,1557192473.131 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:53.175Z,1557192473.175 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T01:27:53.175Z,1557192473.175 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T01:27:53.175Z,1557192473.175 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:27:53.177Z,1557192473.177 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T01:27:53.177Z,1557192473.177 [DUSBL:RequestRepeater] Stopped
2019-05-07T01:27:53.177Z,1557192473.177 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T01:27:53.178Z,1557192473.178 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T01:27:53.178Z,1557192473.178 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T01:27:53.179Z,1557192473.179 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-07T01:27:53.179Z,1557192473.179 [DUSBL:RequestRepeater] Running Loop=2
2019-05-07T01:27:53.180Z,1557192473.180 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T01:27:53.180Z,1557192473.180 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:27:53.180Z,1557192473.180 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:27:53.180Z,1557192473.180 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T01:27:53.180Z,1557192473.180 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:27:55.134Z,1557192475.134 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.242900
2019-05-07T01:27:55.134Z,1557192475.134 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:27:55.135Z,1557192475.135 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:27:55.136Z,1557192475.136 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:27:55.528Z,1557192475.528 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:27:55.528Z,1557192475.528 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:27:55.950Z,1557192475.950 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:27:59.202Z,1557192479.202 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:28:00.394Z,1557192480.394 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.258889
2019-05-07T01:28:00.395Z,1557192480.395 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:28:00.395Z,1557192480.395 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:28:00.396Z,1557192480.396 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:28:00.780Z,1557192480.780 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:28:00.780Z,1557192480.780 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:28:02.006Z,1557192482.006 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:28:03.641Z,1557192483.641 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T01:28:03.641Z,1557192483.641 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T01:28:03.641Z,1557192483.641 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:28:03.641Z,1557192483.641 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T01:28:03.641Z,1557192483.641 [DUSBL:RequestRepeater] Stopped
2019-05-07T01:28:03.641Z,1557192483.641 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater] Running Loop=3
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T01:28:03.642Z,1557192483.642 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:28:05.238Z,1557192485.238 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:28:05.638Z,1557192485.638 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.242870
2019-05-07T01:28:05.638Z,1557192485.638 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:28:05.639Z,1557192485.639 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:28:05.639Z,1557192485.639 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:28:06.032Z,1557192486.032 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:28:06.032Z,1557192486.032 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:28:08.066Z,1557192488.066 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:28:10.898Z,1557192490.898 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.258970
2019-05-07T01:28:10.899Z,1557192490.899 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-07T01:28:10.899Z,1557192490.899 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-07T01:28:10.900Z,1557192490.900 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-07T01:28:10.918Z,1557192490.918 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:28:11.284Z,1557192491.284 [DUSBL_Hydroid](INFO): USBL response received:!U1,P
2019-05-07T01:28:11.284Z,1557192491.284 [DUSBL_Hydroid](INFO): Command Ack
2019-05-07T01:28:14.142Z,1557192494.142 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:28:14.204Z,1557192494.204 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-07T01:28:14.204Z,1557192494.204 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T01:28:14.204Z,1557192494.204 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:28:14.205Z,1557192494.205 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-07T01:28:14.205Z,1557192494.205 [DUSBL:RequestRepeater] Stopped
2019-05-07T01:28:14.205Z,1557192494.205 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T01:28:14.205Z,1557192494.205 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T01:28:14.205Z,1557192494.205 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T01:28:14.205Z,1557192494.205 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-07T01:28:14.205Z,1557192494.205 [DUSBL:RequestRepeater] Running Loop=4
2019-05-07T01:28:14.206Z,1557192494.206 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-07T01:28:14.206Z,1557192494.206 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-07T01:28:14.206Z,1557192494.206 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-07T01:28:14.206Z,1557192494.206 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-07T01:28:14.206Z,1557192494.206 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:28:14.523Z,1557192494.523 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,012647.00,A,3648.17089,N,12147.28518,W,0.311,192.96,070519,,,A*7F
2019-05-07T01:28:14.526Z,1557192494.526 [NAL9602](INFO): GPS fix at 20190507T012647: (36.802848, -121.788086)
2019-05-07T01:28:15.381Z,1557192495.381 [CommandLine](IMPORTANT): got command stop
2019-05-07T01:28:15.381Z,1557192495.381 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-07T01:28:15.381Z,1557192495.381 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-07T01:28:15.388Z,1557192495.388 [MissionManager](INFO): MissionManager is completed.
2019-05-07T01:28:15.388Z,1557192495.388 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL] Stopped
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL:A.Pitch] Stopped
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL:B.SetSpeed] Stopped
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL:C] Stopped
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL:RequestRepeater] Stopped
2019-05-07T01:28:15.388Z,1557192495.388 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-07T01:28:15.389Z,1557192495.389 [DUSBL:RequestRepeater:A] Stopped
2019-05-07T01:28:15.389Z,1557192495.389 [DUSBL:RequestRepeater:B] Stopped
2019-05-07T01:28:15.389Z,1557192495.389 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-07T01:28:15.389Z,1557192495.389 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:28:15.764Z,1557192495.764 [MissionManager](IMPORTANT): Started mission Default
2019-05-07T01:28:15.765Z,1557192495.765 [Default] Running Loop=1
2019-05-07T01:28:15.765Z,1557192495.765 [Default](DEBUG): Aggregate::initialize Default
2019-05-07T01:28:15.765Z,1557192495.765 [Default:B.GoToSurface] Running Loop=1
2019-05-07T01:28:15.765Z,1557192495.765 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-07T01:28:15.765Z,1557192495.765 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-07T01:28:15.765Z,1557192495.765 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-07T01:28:15.766Z,1557192495.766 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-07T01:28:15.766Z,1557192495.766 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-07T01:28:15.767Z,1557192495.767 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-07T01:28:15.767Z,1557192495.767 [Default:A.Wait] Running Loop=1
2019-05-07T01:28:15.767Z,1557192495.767 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:28:29.110Z,1557192509.110 [Default:A.Wait](INFO): Done Waiting.
2019-05-07T01:28:29.110Z,1557192509.110 [Default:A.Wait] Stopped
2019-05-07T01:28:29.110Z,1557192509.110 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:28:29.513Z,1557192509.513 [Default:CheckIn] Running Loop=1
2019-05-07T01:28:29.513Z,1557192509.513 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:28:29.514Z,1557192509.514 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:28:31.114Z,1557192511.114 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:28:31.498Z,1557192511.498 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,012704.00,A,3648.17329,N,12147.28566,W,0.156,192.96,070519,,,A*78
2019-05-07T01:28:31.500Z,1557192511.500 [NAL9602](INFO): GPS fix at 20190507T012704: (36.802888, -121.788094)
2019-05-07T01:28:31.563Z,1557192511.563 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:28:31.563Z,1557192511.563 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:28:31.957Z,1557192511.957 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-07T01:28:37.363Z,1557192517.363 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20190507T012400/Courier0004.lzma
2019-05-07T01:28:38.171Z,1557192518.171 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0004.lzma.bak
2019-05-07T01:28:38.171Z,1557192518.171 [DataOverHttps](INFO): SBD MOMSN=10947711
2019-05-07T01:28:50.675Z,1557192530.675 [DataOverHttps](INFO): Sending 567 bytes from file Logs/20190507T012400/Express0005.lzma
2019-05-07T01:28:51.480Z,1557192531.480 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0005.lzma.bak
2019-05-07T01:28:51.480Z,1557192531.480 [DataOverHttps](INFO): SBD MOMSN=10947715
2019-05-07T01:28:52.640Z,1557192532.640 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:28:52.640Z,1557192532.640 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:28:52.640Z,1557192532.640 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:29:03.868Z,1557192543.868 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T01:31:35.408Z,1557192695.408 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-07T01:31:35.411Z,1557192695.411 [BPC1](INFO): Received data from all battery sticks.
2019-05-07T01:31:53.191Z,1557192713.191 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T01:33:53.198Z,1557192833.198 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T01:33:53.198Z,1557192833.198 [Default:CheckIn:C.Wait] Stopped
2019-05-07T01:33:53.198Z,1557192833.198 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:33:53.202Z,1557192833.202 [Default:CheckIn:D] Running Loop=1
2019-05-07T01:33:53.595Z,1557192833.595 [Default:CheckIn:D] Stopped
2019-05-07T01:33:53.595Z,1557192833.595 [Default:CheckIn:E] Running Loop=1
2019-05-07T01:33:53.982Z,1557192833.982 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.630502 min 
2019-05-07T01:33:53.982Z,1557192833.982 [Default:CheckIn:E] Stopped
2019-05-07T01:33:53.982Z,1557192833.982 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T01:33:53.982Z,1557192833.982 [Default:CheckIn] Stopped
2019-05-07T01:33:53.982Z,1557192833.982 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:33:53.983Z,1557192833.983 [Default:CheckIn](INFO): Running loop #2
2019-05-07T01:33:53.983Z,1557192833.983 [Default:CheckIn] Running Loop=2
2019-05-07T01:33:53.983Z,1557192833.983 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:33:53.983Z,1557192833.983 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:33:55.582Z,1557192835.582 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:33:55.966Z,1557192835.966 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,013229.00,A,3648.16982,N,12147.27912,W,0.292,192.96,070519,,,A*72
2019-05-07T01:33:55.968Z,1557192835.968 [NAL9602](INFO): GPS fix at 20190507T013229: (36.802830, -121.787985)
2019-05-07T01:33:56.013Z,1557192836.013 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:33:56.013Z,1557192836.013 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:34:01.770Z,1557192841.770 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190507T012400/Courier0007.lzma
2019-05-07T01:34:02.576Z,1557192842.576 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0007.lzma.bak
2019-05-07T01:34:02.576Z,1557192842.576 [DataOverHttps](INFO): SBD MOMSN=10947849
2019-05-07T01:34:14.696Z,1557192854.696 [DataOverHttps](INFO): Sending 753 bytes from file Logs/20190507T012400/Express0008.lzma
2019-05-07T01:34:15.500Z,1557192855.500 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0008.lzma.bak
2019-05-07T01:34:15.500Z,1557192855.500 [DataOverHttps](INFO): SBD MOMSN=10947852
2019-05-07T01:34:16.304Z,1557192856.304 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:34:16.304Z,1557192856.304 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:34:16.304Z,1557192856.304 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:34:27.568Z,1557192867.568 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T01:34:27.568Z,1557192867.568 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T01:35:04.309Z,1557192904.309 [NAL9602](INFO): SBD MO Status=2, MOMSN=3826, MT Status=2, MTMSN=0
2019-05-07T01:35:04.310Z,1557192904.310 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T01:35:21.278Z,1557192921.278 [NAL9602](INFO): SBD MO Status=2, MOMSN=3826, MT Status=2, MTMSN=0
2019-05-07T01:35:21.278Z,1557192921.278 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T01:36:10.162Z,1557192970.162 [NAL9602](INFO): SBD MO Status=2, MOMSN=3826, MT Status=2, MTMSN=0
2019-05-07T01:36:10.162Z,1557192970.162 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T01:38:48.191Z,1557193128.191 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T01:38:48.192Z,1557193128.192 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,
2019-05-07T01:38:57.848Z,1557193137.848 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T01:39:16.878Z,1557193156.878 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T01:39:16.878Z,1557193156.878 [Default:CheckIn:C.Wait] Stopped
2019-05-07T01:39:16.878Z,1557193156.878 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:39:16.878Z,1557193156.878 [Default:CheckIn:D] Running Loop=1
2019-05-07T01:39:17.279Z,1557193157.279 [Default:CheckIn:D] Stopped
2019-05-07T01:39:17.279Z,1557193157.279 [Default:CheckIn:E] Running Loop=1
2019-05-07T01:39:17.673Z,1557193157.673 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.025239 min 
2019-05-07T01:39:17.674Z,1557193157.674 [Default:CheckIn:E] Stopped
2019-05-07T01:39:17.674Z,1557193157.674 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T01:39:17.674Z,1557193157.674 [Default:CheckIn] Stopped
2019-05-07T01:39:17.674Z,1557193157.674 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:39:17.694Z,1557193157.694 [Default:CheckIn](INFO): Running loop #3
2019-05-07T01:39:17.694Z,1557193157.694 [Default:CheckIn] Running Loop=3
2019-05-07T01:39:17.695Z,1557193157.695 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:39:17.695Z,1557193157.695 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:39:19.278Z,1557193159.278 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:39:19.666Z,1557193159.666 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,013753.00,A,3648.16499,N,12147.28413,W,0.700,192.96,070519,,,A*70
2019-05-07T01:39:19.668Z,1557193159.668 [NAL9602](INFO): GPS fix at 20190507T013753: (36.802750, -121.788069)
2019-05-07T01:39:19.691Z,1557193159.691 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:39:19.692Z,1557193159.692 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:39:25.434Z,1557193165.434 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0010.lzma
2019-05-07T01:39:26.240Z,1557193166.240 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0010.lzma.bak
2019-05-07T01:39:26.240Z,1557193166.240 [DataOverHttps](INFO): SBD MOMSN=10947863
2019-05-07T01:39:28.625Z,1557193168.625 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T01:39:28.625Z,1557193168.625 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050618471224,35.0, -0.1,  8.9,  0
2019-05-07T01:39:37.807Z,1557193177.807 [DataOverHttps](INFO): Sending 814 bytes from file Logs/20190507T012400/Express0011.lzma
2019-05-07T01:39:38.612Z,1557193178.612 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0011.lzma.bak
2019-05-07T01:39:38.612Z,1557193178.612 [DataOverHttps](INFO): SBD MOMSN=10947866
2019-05-07T01:39:39.568Z,1557193179.568 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:39:39.568Z,1557193179.568 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:39:39.568Z,1557193179.568 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:39:52.049Z,1557193192.049 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T01:39:55.297Z,1557193195.297 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T01:41:43.592Z,1557193303.592 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T01:43:06.391Z,1557193386.391 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-07T01:44:04.963Z,1557193444.963 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190507014403.949583,06,131.9,-9.99,-999,-9.99,203,-0.05,-999,9760,4000*76

2019-05-07T01:44:40.160Z,1557193480.160 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T01:44:40.160Z,1557193480.160 [Default:CheckIn:C.Wait] Stopped
2019-05-07T01:44:40.160Z,1557193480.160 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:44:40.160Z,1557193480.160 [Default:CheckIn:D] Running Loop=1
2019-05-07T01:44:40.538Z,1557193480.538 [Default:CheckIn:D] Stopped
2019-05-07T01:44:40.538Z,1557193480.538 [Default:CheckIn:E] Running Loop=1
2019-05-07T01:44:40.929Z,1557193480.929 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.412891 min 
2019-05-07T01:44:40.929Z,1557193480.929 [Default:CheckIn:E] Stopped
2019-05-07T01:44:40.929Z,1557193480.929 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T01:44:40.929Z,1557193480.929 [Default:CheckIn] Stopped
2019-05-07T01:44:40.929Z,1557193480.929 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:44:40.929Z,1557193480.929 [Default:CheckIn](INFO): Running loop #4
2019-05-07T01:44:40.929Z,1557193480.929 [Default:CheckIn] Running Loop=4
2019-05-07T01:44:40.930Z,1557193480.930 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:44:40.930Z,1557193480.930 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:44:42.534Z,1557193482.534 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:44:42.932Z,1557193482.932 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,014316.00,A,3648.16510,N,12147.27921,W,0.253,0.00,070519,,,A*77
2019-05-07T01:44:42.934Z,1557193482.934 [NAL9602](INFO): GPS fix at 20190507T014316: (36.802752, -121.787987)
2019-05-07T01:44:42.978Z,1557193482.978 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:44:42.978Z,1557193482.978 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:44:48.850Z,1557193488.850 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0013.lzma
2019-05-07T01:44:49.656Z,1557193489.656 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0013.lzma.bak
2019-05-07T01:44:49.656Z,1557193489.656 [DataOverHttps](INFO): SBD MOMSN=10947982
2019-05-07T01:45:01.476Z,1557193501.476 [DataOverHttps](INFO): Sending 699 bytes from file Logs/20190507T012400/Express0014.lzma
2019-05-07T01:45:02.280Z,1557193502.280 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0014.lzma.bak
2019-05-07T01:45:02.280Z,1557193502.280 [DataOverHttps](INFO): SBD MOMSN=10947985
2019-05-07T01:45:03.229Z,1557193503.229 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:45:03.229Z,1557193503.229 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:45:03.229Z,1557193503.229 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:45:13.709Z,1557193513.709 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T01:45:13.782Z,1557193513.782 [NAL9602](FAULT): received: 
+CSQ:0

OK26, 2, 0, 0, 0

OK
2019-05-07T01:45:13.782Z,1557193513.782 [NAL9602] Data Fault, FailCount= 1
2019-05-07T01:45:13.783Z,1557193513.783 [NAL9602](ERROR): Data Fault
2019-05-07T01:45:13.831Z,1557193513.831 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T01:45:14.112Z,1557193514.112 [NAL9602](INFO): Powering down
2019-05-07T01:45:14.958Z,1557193514.958 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T01:45:14.959Z,1557193514.959 [NAL9602] No Fault, FailCount= 1
2019-05-07T01:45:44.416Z,1557193544.416 [NAL9602](INFO): Powering up NAL9602
2019-05-07T01:45:55.321Z,1557193555.321 [NAL9602](INFO): NAL9602 initialized
2019-05-07T01:46:26.428Z,1557193586.428 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T01:50:00.193Z,1557193800.193 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T01:50:00.194Z,1557193800.194 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-3768,V
2019-05-07T01:50:03.810Z,1557193803.810 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T01:50:03.810Z,1557193803.810 [Default:CheckIn:C.Wait] Stopped
2019-05-07T01:50:03.810Z,1557193803.810 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:50:03.811Z,1557193803.811 [Default:CheckIn:D] Running Loop=1
2019-05-07T01:50:04.234Z,1557193804.234 [Default:CheckIn:D] Stopped
2019-05-07T01:50:04.234Z,1557193804.234 [Default:CheckIn:E] Running Loop=1
2019-05-07T01:50:04.623Z,1557193804.623 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.807815 min 
2019-05-07T01:50:04.623Z,1557193804.623 [Default:CheckIn:E] Stopped
2019-05-07T01:50:04.623Z,1557193804.623 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T01:50:04.623Z,1557193804.623 [Default:CheckIn] Stopped
2019-05-07T01:50:04.623Z,1557193804.623 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:50:04.624Z,1557193804.624 [Default:CheckIn](INFO): Running loop #5
2019-05-07T01:50:04.624Z,1557193804.624 [Default:CheckIn] Running Loop=5
2019-05-07T01:50:04.624Z,1557193804.624 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:50:04.624Z,1557193804.624 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:50:06.222Z,1557193806.222 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:50:08.632Z,1557193808.632 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T01:50:09.454Z,1557193809.454 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:50:12.282Z,1557193812.282 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:50:15.110Z,1557193815.110 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:50:17.938Z,1557193817.938 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:50:21.194Z,1557193821.194 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:50:21.559Z,1557193821.559 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,014854.00,A,3648.17193,N,12147.28147,W,0.156,141.07,070519,,,A*76
2019-05-07T01:50:21.561Z,1557193821.561 [NAL9602](INFO): GPS fix at 20190507T014854: (36.802866, -121.788025)
2019-05-07T01:50:21.592Z,1557193821.592 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:50:21.592Z,1557193821.592 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:50:27.890Z,1557193827.890 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0016.lzma
2019-05-07T01:50:28.696Z,1557193828.696 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0016.lzma.bak
2019-05-07T01:50:28.696Z,1557193828.696 [DataOverHttps](INFO): SBD MOMSN=10947995
2019-05-07T01:50:40.659Z,1557193840.659 [DataOverHttps](INFO): Sending 850 bytes from file Logs/20190507T012400/Express0017.lzma
2019-05-07T01:50:41.464Z,1557193841.464 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0017.lzma.bak
2019-05-07T01:50:41.464Z,1557193841.464 [DataOverHttps](INFO): SBD MOMSN=10947998
2019-05-07T01:50:42.289Z,1557193842.289 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:50:42.289Z,1557193842.289 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:50:42.289Z,1557193842.289 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T01:50:53.964Z,1557193853.964 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T01:51:50.171Z,1557193910.171 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T01:51:50.171Z,1557193910.171 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-3768,-32768,V
2019-05-07T01:54:30.534Z,1557194070.534 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T01:54:30.534Z,1557194070.534 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050619021424,0,1448.9,  0
2019-05-07T01:55:42.841Z,1557194142.841 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T01:55:42.841Z,1557194142.841 [Default:CheckIn:C.Wait] Stopped
2019-05-07T01:55:42.841Z,1557194142.841 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T01:55:42.841Z,1557194142.841 [Default:CheckIn:D] Running Loop=1
2019-05-07T01:55:43.260Z,1557194143.260 [Default:CheckIn:D] Stopped
2019-05-07T01:55:43.260Z,1557194143.260 [Default:CheckIn:E] Running Loop=1
2019-05-07T01:55:43.665Z,1557194143.665 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.458264 min 
2019-05-07T01:55:43.665Z,1557194143.665 [Default:CheckIn:E] Stopped
2019-05-07T01:55:43.665Z,1557194143.665 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T01:55:43.666Z,1557194143.666 [Default:CheckIn] Stopped
2019-05-07T01:55:43.666Z,1557194143.666 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T01:55:43.666Z,1557194143.666 [Default:CheckIn](INFO): Running loop #6
2019-05-07T01:55:43.666Z,1557194143.666 [Default:CheckIn] Running Loop=6
2019-05-07T01:55:43.666Z,1557194143.666 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T01:55:43.666Z,1557194143.666 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T01:55:45.258Z,1557194145.258 [NAL9602](DEBUG): Fix Requested
2019-05-07T01:55:45.650Z,1557194145.650 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,015418.00,A,3648.16769,N,12147.28489,W,0.233,141.07,070519,,,A*76
2019-05-07T01:55:45.652Z,1557194145.652 [NAL9602](INFO): GPS fix at 20190507T015418: (36.802795, -121.788082)
2019-05-07T01:55:45.685Z,1557194145.685 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T01:55:45.685Z,1557194145.685 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T01:55:51.334Z,1557194151.334 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0019.lzma
2019-05-07T01:55:52.143Z,1557194152.143 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0019.lzma.bak
2019-05-07T01:55:52.144Z,1557194152.144 [DataOverHttps](INFO): SBD MOMSN=10948117
2019-05-07T01:56:04.119Z,1557194164.119 [DataOverHttps](INFO): Sending 621 bytes from file Logs/20190507T012400/Express0020.lzma
2019-05-07T01:56:04.924Z,1557194164.924 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0020.lzma.bak
2019-05-07T01:56:04.924Z,1557194164.924 [DataOverHttps](INFO): SBD MOMSN=10948120
2019-05-07T01:56:06.365Z,1557194166.365 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T01:56:06.365Z,1557194166.365 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T01:56:06.365Z,1557194166.365 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:00:11.177Z,1557194411.177 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2019-05-07T02:00:11.177Z,1557194411.177 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768-32768,V
2019-05-07T02:00:47.901Z,1557194447.901 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T02:01:06.923Z,1557194466.923 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:01:06.924Z,1557194466.924 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:01:06.924Z,1557194466.924 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:01:06.924Z,1557194466.924 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:01:07.361Z,1557194467.361 [Default:CheckIn:D] Stopped
2019-05-07T02:01:07.361Z,1557194467.361 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.859943 min 
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn:E] Stopped
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn] Stopped
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn](INFO): Running loop #7
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn] Running Loop=7
2019-05-07T02:01:07.724Z,1557194467.724 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:01:07.725Z,1557194467.725 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:01:09.326Z,1557194469.326 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:01:09.719Z,1557194469.719 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,015943.00,A,3648.16647,N,12147.27686,W,0.117,0.00,070519,,,A*7C
2019-05-07T02:01:09.721Z,1557194469.721 [NAL9602](INFO): GPS fix at 20190507T015943: (36.802774, -121.787948)
2019-05-07T02:01:09.753Z,1557194469.753 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:01:09.754Z,1557194469.754 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:01:15.626Z,1557194475.626 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0022.lzma
2019-05-07T02:01:16.432Z,1557194476.432 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0022.lzma.bak
2019-05-07T02:01:16.432Z,1557194476.432 [DataOverHttps](INFO): SBD MOMSN=10948130
2019-05-07T02:01:28.255Z,1557194488.255 [DataOverHttps](INFO): Sending 735 bytes from file Logs/20190507T012400/Express0023.lzma
2019-05-07T02:01:29.060Z,1557194489.060 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0023.lzma.bak
2019-05-07T02:01:29.060Z,1557194489.060 [DataOverHttps](INFO): SBD MOMSN=10948135
2019-05-07T02:01:29.957Z,1557194489.957 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:01:29.957Z,1557194489.957 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:01:29.957Z,1557194489.957 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:01:42.036Z,1557194502.036 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:01:57.405Z,1557194517.405 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T02:01:57.405Z,1557194517.405 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,8
2019-05-07T02:05:10.529Z,1557194710.529 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T02:05:10.529Z,1557194710.529 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050619125424,35.0, -0.1,  8.9,  0
2019-05-07T02:06:30.561Z,1557194790.561 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:06:30.561Z,1557194790.561 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:06:30.561Z,1557194790.561 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:06:30.562Z,1557194790.562 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:06:30.935Z,1557194790.935 [Default:CheckIn:D] Stopped
2019-05-07T02:06:30.935Z,1557194790.935 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:06:31.355Z,1557194791.355 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.252840 min 
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn:E] Stopped
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn] Stopped
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn](INFO): Running loop #8
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn] Running Loop=8
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:06:31.356Z,1557194791.356 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:06:32.942Z,1557194792.942 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:06:33.338Z,1557194793.338 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,020507.00,A,3648.16208,N,12147.28266,W,0.117,0.00,070519,,,A*7C
2019-05-07T02:06:33.340Z,1557194793.340 [NAL9602](INFO): GPS fix at 20190507T020507: (36.802701, -121.788044)
2019-05-07T02:06:33.395Z,1557194793.395 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:06:33.395Z,1557194793.395 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:06:39.250Z,1557194799.250 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0025.lzma
2019-05-07T02:06:40.056Z,1557194800.056 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0025.lzma.bak
2019-05-07T02:06:40.056Z,1557194800.056 [DataOverHttps](INFO): SBD MOMSN=10948263
2019-05-07T02:06:52.423Z,1557194812.423 [DataOverHttps](INFO): Sending 580 bytes from file Logs/20190507T012400/Express0026.lzma
2019-05-07T02:06:53.228Z,1557194813.228 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0026.lzma.bak
2019-05-07T02:06:53.228Z,1557194813.228 [DataOverHttps](INFO): SBD MOMSN=10948266
2019-05-07T02:06:53.997Z,1557194813.997 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:06:53.997Z,1557194813.997 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:06:53.997Z,1557194813.997 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:07:04.071Z,1557194824.071 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T02:07:04.159Z,1557194824.159 [NAL9602](FAULT): received: 
+CSQ:0

OK26, 2, 0, 0, 0

OK
2019-05-07T02:07:04.159Z,1557194824.159 [NAL9602] Data Fault, FailCount= 1
2019-05-07T02:07:04.159Z,1557194824.159 [NAL9602](ERROR): Data Fault
2019-05-07T02:07:04.199Z,1557194824.199 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T02:07:04.473Z,1557194824.473 [NAL9602](INFO): Powering down
2019-05-07T02:07:05.406Z,1557194825.406 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T02:07:05.406Z,1557194825.406 [NAL9602] No Fault, FailCount= 1
2019-05-07T02:07:34.776Z,1557194854.776 [NAL9602](INFO): Powering up NAL9602
2019-05-07T02:07:45.680Z,1557194865.680 [NAL9602](INFO): NAL9602 initialized
2019-05-07T02:08:16.792Z,1557194896.792 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:11:54.573Z,1557195114.573 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:11:54.573Z,1557195114.573 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:11:54.573Z,1557195114.573 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:11:54.573Z,1557195114.573 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:11:54.975Z,1557195114.975 [Default:CheckIn:D] Stopped
2019-05-07T02:11:54.975Z,1557195114.975 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.653503 min 
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn:E] Stopped
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn] Stopped
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn](INFO): Running loop #9
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn] Running Loop=9
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:11:55.389Z,1557195115.389 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:11:56.982Z,1557195116.982 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:11:57.382Z,1557195117.382 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,021031.00,A,3648.16748,N,12147.28260,W,0.467,0.00,070519,,,A*78
2019-05-07T02:11:57.384Z,1557195117.384 [NAL9602](INFO): GPS fix at 20190507T021031: (36.802791, -121.788043)
2019-05-07T02:11:57.458Z,1557195117.458 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:11:57.458Z,1557195117.458 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:11:59.472Z,1557195119.472 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T02:12:00.713Z,1557195120.713 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T02:12:00.713Z,1557195120.713 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-4
2019-05-07T02:12:07.218Z,1557195127.218 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0028.lzma
2019-05-07T02:12:08.024Z,1557195128.024 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0028.lzma.bak
2019-05-07T02:12:08.024Z,1557195128.024 [DataOverHttps](INFO): SBD MOMSN=10948306
2019-05-07T02:12:19.647Z,1557195139.647 [DataOverHttps](INFO): Sending 666 bytes from file Logs/20190507T012400/Express0029.lzma
2019-05-07T02:12:20.448Z,1557195140.448 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0029.lzma.bak
2019-05-07T02:12:20.448Z,1557195140.448 [DataOverHttps](INFO): SBD MOMSN=10948309
2019-05-07T02:12:21.325Z,1557195141.325 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:12:21.325Z,1557195141.325 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:12:21.326Z,1557195141.326 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:12:30.191Z,1557195150.191 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:13:04.531Z,1557195184.531 [RDI_Pathfinder](ERROR): Failed to parse:
:R,   0.00,   0.00,   0.00,   0.00
2019-05-07T02:14:07.545Z,1557195247.545 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T02:14:07.545Z,1557195247.545 [RDI_Pathfinder](ERROR): Failed to parse:
:TS9215124,35.0, -0.1,   0.0,1448.9,  0
2019-05-07T02:16:29.368Z,1557195389.368 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-07T02:17:14.610Z,1557195434.610 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T02:17:14.610Z,1557195434.610 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050619245824,35.0, -0.1,   0.0, 0
2019-05-07T02:17:21.886Z,1557195441.886 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:17:21.886Z,1557195441.886 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:17:21.886Z,1557195441.886 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:17:21.914Z,1557195441.914 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:17:22.348Z,1557195442.348 [Default:CheckIn:D] Stopped
2019-05-07T02:17:22.348Z,1557195442.348 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:17:22.690Z,1557195442.690 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.109717 min 
2019-05-07T02:17:22.690Z,1557195442.690 [Default:CheckIn:E] Stopped
2019-05-07T02:17:22.694Z,1557195442.694 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:17:22.694Z,1557195442.694 [Default:CheckIn] Stopped
2019-05-07T02:17:22.695Z,1557195442.695 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:17:22.695Z,1557195442.695 [Default:CheckIn](INFO): Running loop #10
2019-05-07T02:17:22.695Z,1557195442.695 [Default:CheckIn] Running Loop=10
2019-05-07T02:17:22.695Z,1557195442.695 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:17:22.695Z,1557195442.695 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:17:24.294Z,1557195444.294 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:17:24.686Z,1557195444.686 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,021558.00,A,3648.16817,N,12147.28412,W,0.292,174.24,070519,,,A*7C
2019-05-07T02:17:24.688Z,1557195444.688 [NAL9602](INFO): GPS fix at 20190507T021558: (36.802803, -121.788069)
2019-05-07T02:17:24.732Z,1557195444.732 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:17:24.732Z,1557195444.732 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:17:30.762Z,1557195450.762 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190507T012400/Courier0031.lzma
2019-05-07T02:17:31.568Z,1557195451.568 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0031.lzma.bak
2019-05-07T02:17:31.568Z,1557195451.568 [DataOverHttps](INFO): SBD MOMSN=10948405
2019-05-07T02:17:43.335Z,1557195463.335 [DataOverHttps](INFO): Sending 757 bytes from file Logs/20190507T012400/Express0032.lzma
2019-05-07T02:17:44.143Z,1557195464.143 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0032.lzma.bak
2019-05-07T02:17:44.144Z,1557195464.144 [DataOverHttps](INFO): SBD MOMSN=10948408
2019-05-07T02:17:45.041Z,1557195465.041 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:17:45.041Z,1557195465.041 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:17:45.042Z,1557195465.042 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:18:18.176Z,1557195498.176 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2019-05-07T02:18:18.176Z,1557195498.176 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.068,V
2019-05-07T02:20:52.502Z,1557195652.502 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-07T02:20:52.502Z,1557195652.502 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,       -0.09,        +0.13,     ,   0.00,108.00
2019-05-07T02:22:26.996Z,1557195746.996 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T02:22:31.463Z,1557195751.463 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T02:22:31.463Z,1557195751.463 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050619301424,35206.00
2019-05-07T02:22:45.597Z,1557195765.597 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:22:45.597Z,1557195765.597 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:22:45.597Z,1557195765.597 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:22:45.597Z,1557195765.597 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:22:45.997Z,1557195765.997 [Default:CheckIn:D] Stopped
2019-05-07T02:22:45.997Z,1557195765.997 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:22:46.413Z,1557195766.413 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.503878 min 
2019-05-07T02:22:46.413Z,1557195766.413 [Default:CheckIn:E] Stopped
2019-05-07T02:22:46.414Z,1557195766.414 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:22:46.414Z,1557195766.414 [Default:CheckIn] Stopped
2019-05-07T02:22:46.414Z,1557195766.414 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:22:46.414Z,1557195766.414 [Default:CheckIn](INFO): Running loop #11
2019-05-07T02:22:46.415Z,1557195766.415 [Default:CheckIn] Running Loop=11
2019-05-07T02:22:46.415Z,1557195766.415 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:22:46.415Z,1557195766.415 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:22:48.010Z,1557195768.010 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:22:48.399Z,1557195768.399 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,022122.00,A,3648.16950,N,12147.28310,W,0.350,174.24,070519,,,A*7E
2019-05-07T02:22:48.401Z,1557195768.401 [NAL9602](INFO): GPS fix at 20190507T022122: (36.802825, -121.788052)
2019-05-07T02:22:48.456Z,1557195768.456 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:22:48.457Z,1557195768.457 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:22:54.370Z,1557195774.370 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0034.lzma
2019-05-07T02:22:55.176Z,1557195775.176 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0034.lzma.bak
2019-05-07T02:22:55.176Z,1557195775.176 [DataOverHttps](INFO): SBD MOMSN=10948433
2019-05-07T02:23:06.956Z,1557195786.956 [DataOverHttps](INFO): Sending 793 bytes from file Logs/20190507T012400/Express0035.lzma
2019-05-07T02:23:07.760Z,1557195787.760 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0035.lzma.bak
2019-05-07T02:23:07.760Z,1557195787.760 [DataOverHttps](INFO): SBD MOMSN=10948436
2019-05-07T02:23:08.647Z,1557195788.647 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:23:08.647Z,1557195788.647 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:23:08.647Z,1557195788.647 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:23:21.129Z,1557195801.129 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:28:09.217Z,1557196089.217 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:28:09.217Z,1557196089.217 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:28:09.217Z,1557196089.217 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:28:09.217Z,1557196089.217 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:28:09.609Z,1557196089.609 [Default:CheckIn:D] Stopped
2019-05-07T02:28:09.609Z,1557196089.609 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:28:10.020Z,1557196090.020 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.897404 min 
2019-05-07T02:28:10.020Z,1557196090.020 [Default:CheckIn:E] Stopped
2019-05-07T02:28:10.020Z,1557196090.020 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:28:10.020Z,1557196090.020 [Default:CheckIn] Stopped
2019-05-07T02:28:10.020Z,1557196090.020 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:28:10.020Z,1557196090.020 [Default:CheckIn](INFO): Running loop #12
2019-05-07T02:28:10.021Z,1557196090.021 [Default:CheckIn] Running Loop=12
2019-05-07T02:28:10.021Z,1557196090.021 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:28:10.021Z,1557196090.021 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:28:11.610Z,1557196091.610 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:28:12.003Z,1557196092.003 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,022645.00,A,3648.16738,N,12147.28251,W,0.194,174.24,070519,,,A*76
2019-05-07T02:28:12.005Z,1557196092.005 [NAL9602](INFO): GPS fix at 20190507T022645: (36.802790, -121.788042)
2019-05-07T02:28:12.028Z,1557196092.028 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:28:12.028Z,1557196092.028 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:28:17.662Z,1557196097.662 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0037.lzma
2019-05-07T02:28:18.468Z,1557196098.468 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0037.lzma.bak
2019-05-07T02:28:18.468Z,1557196098.468 [DataOverHttps](INFO): SBD MOMSN=10948531
2019-05-07T02:28:20.556Z,1557196100.556 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T02:28:20.556Z,1557196100.556 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T02:28:30.311Z,1557196110.311 [DataOverHttps](INFO): Sending 703 bytes from file Logs/20190507T012400/Express0038.lzma
2019-05-07T02:28:31.116Z,1557196111.116 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0038.lzma.bak
2019-05-07T02:28:31.116Z,1557196111.116 [DataOverHttps](INFO): SBD MOMSN=10948534
2019-05-07T02:28:31.853Z,1557196111.853 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:28:31.854Z,1557196111.854 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:28:31.854Z,1557196111.854 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:28:42.736Z,1557196122.736 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T02:28:42.810Z,1557196122.810 [NAL9602](FAULT): received: 
+CSQ:0

OK26, 2, 0, 0, 0

OK
2019-05-07T02:28:42.810Z,1557196122.810 [NAL9602] Data Fault, FailCount= 1
2019-05-07T02:28:42.811Z,1557196122.811 [NAL9602](ERROR): Data Fault
2019-05-07T02:28:42.869Z,1557196122.869 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T02:28:43.144Z,1557196123.144 [NAL9602](INFO): Powering down
2019-05-07T02:28:43.993Z,1557196123.993 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T02:28:43.993Z,1557196123.993 [NAL9602] No Fault, FailCount= 1
2019-05-07T02:29:13.441Z,1557196153.441 [NAL9602](INFO): Powering up NAL9602
2019-05-07T02:29:24.363Z,1557196164.363 [NAL9602](INFO): NAL9602 initialized
2019-05-07T02:29:55.456Z,1557196195.456 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:33:32.464Z,1557196412.464 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:33:32.464Z,1557196412.464 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:33:32.464Z,1557196412.464 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:33:32.465Z,1557196412.465 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:33:32.834Z,1557196412.834 [Default:CheckIn:D] Stopped
2019-05-07T02:33:32.834Z,1557196412.834 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:33:33.253Z,1557196413.253 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.284497 min 
2019-05-07T02:33:33.253Z,1557196413.253 [Default:CheckIn:E] Stopped
2019-05-07T02:33:33.253Z,1557196413.253 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:33:33.254Z,1557196413.254 [Default:CheckIn] Stopped
2019-05-07T02:33:33.254Z,1557196413.254 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:33:33.254Z,1557196413.254 [Default:CheckIn](INFO): Running loop #13
2019-05-07T02:33:33.254Z,1557196413.254 [Default:CheckIn] Running Loop=13
2019-05-07T02:33:33.254Z,1557196413.254 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:33:33.254Z,1557196413.254 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:33:34.850Z,1557196414.850 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:33:37.661Z,1557196417.661 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T02:33:38.486Z,1557196418.486 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:33:41.326Z,1557196421.326 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:33:44.162Z,1557196424.162 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:33:44.536Z,1557196424.536 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,023217.00,A,3648.16542,N,12147.28268,W,0.117,162.56,070519,,,A*78
2019-05-07T02:33:44.538Z,1557196424.538 [NAL9602](INFO): GPS fix at 20190507T023217: (36.802757, -121.788045)
2019-05-07T02:33:44.584Z,1557196424.584 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:33:44.584Z,1557196424.584 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:33:50.153Z,1557196430.153 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0040.lzma
2019-05-07T02:33:50.944Z,1557196430.944 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0040.lzma.bak
2019-05-07T02:33:50.944Z,1557196430.944 [DataOverHttps](INFO): SBD MOMSN=10948586
2019-05-07T02:34:03.059Z,1557196443.059 [DataOverHttps](INFO): Sending 835 bytes from file Logs/20190507T012400/Express0041.lzma
2019-05-07T02:34:03.864Z,1557196443.864 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0041.lzma.bak
2019-05-07T02:34:03.864Z,1557196443.864 [DataOverHttps](INFO): SBD MOMSN=10948589
2019-05-07T02:34:04.837Z,1557196444.837 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:34:04.837Z,1557196444.837 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:34:04.837Z,1557196444.837 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:34:16.925Z,1557196456.925 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:39:05.421Z,1557196745.421 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:39:05.421Z,1557196745.421 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:39:05.421Z,1557196745.421 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:39:05.421Z,1557196745.421 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:39:05.817Z,1557196745.817 [Default:CheckIn:D] Stopped
2019-05-07T02:39:05.817Z,1557196745.817 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:39:06.251Z,1557196746.251 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.834212 min 
2019-05-07T02:39:06.251Z,1557196746.251 [Default:CheckIn:E] Stopped
2019-05-07T02:39:06.251Z,1557196746.251 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:39:06.251Z,1557196746.251 [Default:CheckIn] Stopped
2019-05-07T02:39:06.251Z,1557196746.251 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:39:06.251Z,1557196746.251 [Default:CheckIn](INFO): Running loop #14
2019-05-07T02:39:06.251Z,1557196746.251 [Default:CheckIn] Running Loop=14
2019-05-07T02:39:06.252Z,1557196746.252 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:39:06.252Z,1557196746.252 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:39:07.826Z,1557196747.826 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:39:08.218Z,1557196748.218 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,023741.00,A,3648.16418,N,12147.28169,W,0.292,341.76,070519,,,A*7D
2019-05-07T02:39:08.220Z,1557196748.220 [NAL9602](INFO): GPS fix at 20190507T023741: (36.802736, -121.788028)
2019-05-07T02:39:08.253Z,1557196748.253 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:39:08.253Z,1557196748.253 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:39:13.838Z,1557196753.838 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0043.lzma
2019-05-07T02:39:14.644Z,1557196754.644 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0043.lzma.bak
2019-05-07T02:39:14.644Z,1557196754.644 [DataOverHttps](INFO): SBD MOMSN=10948664
2019-05-07T02:39:26.267Z,1557196766.267 [DataOverHttps](INFO): Sending 650 bytes from file Logs/20190507T012400/Express0044.lzma
2019-05-07T02:39:27.072Z,1557196767.072 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0044.lzma.bak
2019-05-07T02:39:27.072Z,1557196767.072 [DataOverHttps](INFO): SBD MOMSN=10948667
2019-05-07T02:39:28.073Z,1557196768.073 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:39:28.073Z,1557196768.073 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:39:28.073Z,1557196768.073 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:43:49.054Z,1557197029.054 [NAL9602](INFO): SBD MO Status=2, MOMSN=3826, MT Status=2, MTMSN=0
2019-05-07T02:43:49.054Z,1557197029.054 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T02:44:10.067Z,1557197050.067 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T02:44:28.669Z,1557197068.669 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:44:28.669Z,1557197068.669 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:44:28.669Z,1557197068.669 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:44:28.670Z,1557197068.670 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:44:29.071Z,1557197069.071 [Default:CheckIn:D] Stopped
2019-05-07T02:44:29.071Z,1557197069.071 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:44:29.491Z,1557197069.491 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 76.221769 min 
2019-05-07T02:44:29.491Z,1557197069.491 [Default:CheckIn:E] Stopped
2019-05-07T02:44:29.491Z,1557197069.491 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:44:29.491Z,1557197069.491 [Default:CheckIn] Stopped
2019-05-07T02:44:29.491Z,1557197069.491 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:44:29.491Z,1557197069.491 [Default:CheckIn](INFO): Running loop #15
2019-05-07T02:44:29.492Z,1557197069.492 [Default:CheckIn] Running Loop=15
2019-05-07T02:44:29.492Z,1557197069.492 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:44:29.492Z,1557197069.492 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:44:31.074Z,1557197071.074 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:44:31.470Z,1557197071.470 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,024305.00,A,3648.16516,N,12147.28237,W,0.117,341.76,070519,,,A*77
2019-05-07T02:44:31.473Z,1557197071.473 [NAL9602](INFO): GPS fix at 20190507T024305: (36.802753, -121.788039)
2019-05-07T02:44:31.505Z,1557197071.505 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:44:31.506Z,1557197071.506 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:44:37.442Z,1557197077.442 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0046.lzma
2019-05-07T02:44:38.248Z,1557197078.248 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0046.lzma.bak
2019-05-07T02:44:38.248Z,1557197078.248 [DataOverHttps](INFO): SBD MOMSN=10948733
2019-05-07T02:44:50.191Z,1557197090.191 [DataOverHttps](INFO): Sending 773 bytes from file Logs/20190507T012400/Express0047.lzma
2019-05-07T02:44:50.996Z,1557197090.996 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0047.lzma.bak
2019-05-07T02:44:50.996Z,1557197090.996 [DataOverHttps](INFO): SBD MOMSN=10948736
2019-05-07T02:44:51.697Z,1557197091.697 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:44:51.697Z,1557197091.697 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:44:51.697Z,1557197091.697 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:45:04.188Z,1557197104.188 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:49:52.280Z,1557197392.280 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:49:52.280Z,1557197392.280 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:49:52.281Z,1557197392.281 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:49:52.281Z,1557197392.281 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:49:52.699Z,1557197392.699 [Default:CheckIn:D] Stopped
2019-05-07T02:49:52.699Z,1557197392.699 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:49:53.117Z,1557197393.117 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.615568 min 
2019-05-07T02:49:53.117Z,1557197393.117 [Default:CheckIn:E] Stopped
2019-05-07T02:49:53.117Z,1557197393.117 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:49:53.118Z,1557197393.118 [Default:CheckIn] Stopped
2019-05-07T02:49:53.118Z,1557197393.118 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:49:53.123Z,1557197393.123 [Default:CheckIn](INFO): Running loop #16
2019-05-07T02:49:53.123Z,1557197393.123 [Default:CheckIn] Running Loop=16
2019-05-07T02:49:53.124Z,1557197393.124 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:49:53.124Z,1557197393.124 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:49:54.678Z,1557197394.678 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:49:55.084Z,1557197395.084 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,024828.00,A,3648.16253,N,12147.28014,W,0.175,160.66,070519,,,A*72
2019-05-07T02:49:55.091Z,1557197395.091 [NAL9602](INFO): GPS fix at 20190507T024828: (36.802709, -121.788002)
2019-05-07T02:49:55.137Z,1557197395.137 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:49:55.137Z,1557197395.137 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:50:01.006Z,1557197401.006 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0049.lzma
2019-05-07T02:50:01.812Z,1557197401.812 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0049.lzma.bak
2019-05-07T02:50:01.812Z,1557197401.812 [DataOverHttps](INFO): SBD MOMSN=10948808
2019-05-07T02:50:14.132Z,1557197414.132 [DataOverHttps](INFO): Sending 702 bytes from file Logs/20190507T012400/Express0050.lzma
2019-05-07T02:50:14.924Z,1557197414.924 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0050.lzma.bak
2019-05-07T02:50:14.924Z,1557197414.924 [DataOverHttps](INFO): SBD MOMSN=10948811
2019-05-07T02:50:15.709Z,1557197415.709 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:50:15.709Z,1557197415.709 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:50:15.709Z,1557197415.709 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:50:25.777Z,1557197425.777 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T02:50:25.854Z,1557197425.854 [NAL9602](FAULT): received: 
+CSQ:0

OK26, 2, 0, 0, 0

OK
2019-05-07T02:50:25.854Z,1557197425.854 [NAL9602] Data Fault, FailCount= 1
2019-05-07T02:50:25.854Z,1557197425.854 [NAL9602](ERROR): Data Fault
2019-05-07T02:50:25.891Z,1557197425.891 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T02:50:26.180Z,1557197426.180 [NAL9602](INFO): Powering down
2019-05-07T02:50:27.026Z,1557197427.026 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T02:50:27.026Z,1557197427.026 [NAL9602] No Fault, FailCount= 1
2019-05-07T02:50:56.480Z,1557197456.480 [NAL9602](INFO): Powering up NAL9602
2019-05-07T02:51:07.384Z,1557197467.384 [NAL9602](INFO): NAL9602 initialized
2019-05-07T02:51:38.492Z,1557197498.492 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T02:52:14.490Z,1557197534.490 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T02:52:14.491Z,1557197534.491 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050619595824,35.0, -0.1,   0.0,1448:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T02:55:16.300Z,1557197716.300 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T02:55:16.300Z,1557197716.300 [Default:CheckIn:C.Wait] Stopped
2019-05-07T02:55:16.300Z,1557197716.300 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T02:55:16.301Z,1557197716.301 [Default:CheckIn:D] Running Loop=1
2019-05-07T02:55:16.706Z,1557197716.706 [Default:CheckIn:D] Stopped
2019-05-07T02:55:16.706Z,1557197716.706 [Default:CheckIn:E] Running Loop=1
2019-05-07T02:55:17.142Z,1557197717.142 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.015682 min 
2019-05-07T02:55:17.142Z,1557197717.142 [Default:CheckIn:E] Stopped
2019-05-07T02:55:17.142Z,1557197717.142 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T02:55:17.142Z,1557197717.142 [Default:CheckIn] Stopped
2019-05-07T02:55:17.142Z,1557197717.142 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T02:55:17.143Z,1557197717.143 [Default:CheckIn](INFO): Running loop #17
2019-05-07T02:55:17.143Z,1557197717.143 [Default:CheckIn] Running Loop=17
2019-05-07T02:55:17.143Z,1557197717.143 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T02:55:17.143Z,1557197717.143 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T02:55:18.706Z,1557197718.706 [NAL9602](DEBUG): Fix Requested
2019-05-07T02:55:19.114Z,1557197719.114 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,025351.00,A,3648.16579,N,12147.28517,W,0.292,0.00,070519,,,A*72
2019-05-07T02:55:19.123Z,1557197719.123 [NAL9602](INFO): GPS fix at 20190507T025351: (36.802763, -121.788086)
2019-05-07T02:55:19.167Z,1557197719.167 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T02:55:19.167Z,1557197719.167 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T02:55:20.748Z,1557197720.748 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T02:55:25.198Z,1557197725.198 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0052.lzma
2019-05-07T02:55:26.004Z,1557197726.004 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0052.lzma.bak
2019-05-07T02:55:26.004Z,1557197726.004 [DataOverHttps](INFO): SBD MOMSN=10948874
2019-05-07T02:55:37.955Z,1557197737.955 [DataOverHttps](INFO): Sending 708 bytes from file Logs/20190507T012400/Express0053.lzma
2019-05-07T02:55:38.760Z,1557197738.760 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0053.lzma.bak
2019-05-07T02:55:38.760Z,1557197738.760 [DataOverHttps](INFO): SBD MOMSN=10948877
2019-05-07T02:55:39.781Z,1557197739.781 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T02:55:39.781Z,1557197739.781 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T02:55:39.781Z,1557197739.781 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T02:55:51.488Z,1557197751.488 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:00:40.385Z,1557198040.385 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:00:40.385Z,1557198040.385 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:00:40.385Z,1557198040.385 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:00:40.385Z,1557198040.385 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:00:40.773Z,1557198040.773 [Default:CheckIn:D] Stopped
2019-05-07T03:00:40.773Z,1557198040.773 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.416805 min 
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn:E] Stopped
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn] Stopped
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn](INFO): Running loop #18
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn] Running Loop=18
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:00:41.175Z,1557198041.175 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:00:42.794Z,1557198042.794 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:00:43.171Z,1557198043.171 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,025916.00,A,3648.16351,N,12147.28056,W,0.019,301.91,070519,,,A*7C
2019-05-07T03:00:43.173Z,1557198043.173 [NAL9602](INFO): GPS fix at 20190507T025916: (36.802725, -121.788009)
2019-05-07T03:00:43.209Z,1557198043.209 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:00:43.209Z,1557198043.209 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:00:49.022Z,1557198049.022 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0055.lzma
2019-05-07T03:00:49.828Z,1557198049.828 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0055.lzma.bak
2019-05-07T03:00:49.828Z,1557198049.828 [DataOverHttps](INFO): SBD MOMSN=10948938
2019-05-07T03:01:01.560Z,1557198061.560 [DataOverHttps](INFO): Sending 732 bytes from file Logs/20190507T012400/Express0056.lzma
2019-05-07T03:01:02.364Z,1557198062.364 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0056.lzma.bak
2019-05-07T03:01:02.364Z,1557198062.364 [DataOverHttps](INFO): SBD MOMSN=10948941
2019-05-07T03:01:03.393Z,1557198063.393 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:01:03.393Z,1557198063.393 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:01:03.393Z,1557198063.393 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:01:30.442Z,1557198090.442 [NAL9602](INFO): SBD MO Status=2, MOMSN=3826, MT Status=2, MTMSN=0
2019-05-07T03:01:30.442Z,1557198090.442 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T03:02:20.183Z,1557198140.183 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T03:02:20.183Z,1557198140.183 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T03:03:14.685Z,1557198194.685 [NAL9602](INFO): SBD MO Status=2, MOMSN=3826, MT Status=2, MTMSN=0
2019-05-07T03:03:14.685Z,1557198194.685 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T03:03:44.973Z,1557198224.973 [NAL9602](INFO): SBD MO Status=0, MOMSN=3826, MT Status=0, MTMSN=0
2019-05-07T03:03:44.974Z,1557198224.974 [NAL9602](INFO): No messages in MT queue
2019-05-07T03:03:55.124Z,1557198235.124 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T03:03:55.125Z,1557198235.125 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190506201139 -0.1,   0.0,1448.9,  0
2019-05-07T03:04:15.672Z,1557198255.672 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:04:35.494Z,1557198275.494 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T03:04:35.494Z,1557198275.494 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-3268,-32768,V
2019-05-07T03:06:03.978Z,1557198363.978 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:06:03.978Z,1557198363.978 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:06:03.978Z,1557198363.978 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:06:03.979Z,1557198363.979 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:06:04.382Z,1557198364.382 [Default:CheckIn:D] Stopped
2019-05-07T03:06:04.383Z,1557198364.383 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:06:04.777Z,1557198364.777 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.810295 min 
2019-05-07T03:06:04.777Z,1557198364.777 [Default:CheckIn:E] Stopped
2019-05-07T03:06:04.777Z,1557198364.777 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:06:04.777Z,1557198364.777 [Default:CheckIn] Stopped
2019-05-07T03:06:04.778Z,1557198364.778 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:06:04.778Z,1557198364.778 [Default:CheckIn](INFO): Running loop #19
2019-05-07T03:06:04.778Z,1557198364.778 [Default:CheckIn] Running Loop=19
2019-05-07T03:06:04.778Z,1557198364.778 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:06:04.778Z,1557198364.778 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:06:06.382Z,1557198366.382 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:06:06.775Z,1557198366.775 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,030440.00,A,3648.16534,N,12147.28463,W,0.175,301.91,070519,,,A*7A
2019-05-07T03:06:06.777Z,1557198366.777 [NAL9602](INFO): GPS fix at 20190507T030440: (36.802756, -121.788077)
2019-05-07T03:06:06.820Z,1557198366.820 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:06:06.821Z,1557198366.821 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:06:12.674Z,1557198372.674 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0058.lzma
2019-05-07T03:06:13.480Z,1557198373.480 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0058.lzma.bak
2019-05-07T03:06:13.480Z,1557198373.480 [DataOverHttps](INFO): SBD MOMSN=10949007
2019-05-07T03:06:20.551Z,1557198380.551 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T03:06:20.552Z,1557198380.552 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190506235.0, -0.1,   0.0,144

2019-05-07T03:06:25.283Z,1557198385.283 [DataOverHttps](INFO): Sending 557 bytes from file Logs/20190507T012400/Express0059.lzma
2019-05-07T03:06:26.091Z,1557198386.091 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0059.lzma.bak
2019-05-07T03:06:26.092Z,1557198386.092 [DataOverHttps](INFO): SBD MOMSN=10949010
2019-05-07T03:06:27.033Z,1557198387.033 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:06:27.033Z,1557198387.033 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:06:27.033Z,1557198387.033 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:09:21.194Z,1557198561.194 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T03:09:21.194Z,1557198561.194 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,
2019-05-07T03:09:52.665Z,1557198592.665 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T03:10:56.495Z,1557198656.495 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T03:10:56.496Z,1557198656.496 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T03:11:08.996Z,1557198668.996 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T03:11:27.613Z,1557198687.613 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:11:27.613Z,1557198687.613 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:11:27.613Z,1557198687.613 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:11:27.614Z,1557198687.614 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:11:28.021Z,1557198688.021 [Default:CheckIn:D] Stopped
2019-05-07T03:11:28.021Z,1557198688.021 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:11:28.433Z,1557198688.433 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 103.204281 min 
2019-05-07T03:11:28.433Z,1557198688.433 [Default:CheckIn:E] Stopped
2019-05-07T03:11:28.433Z,1557198688.433 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:11:28.433Z,1557198688.433 [Default:CheckIn] Stopped
2019-05-07T03:11:28.433Z,1557198688.433 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:11:28.434Z,1557198688.434 [Default:CheckIn](INFO): Running loop #20
2019-05-07T03:11:28.434Z,1557198688.434 [Default:CheckIn] Running Loop=20
2019-05-07T03:11:28.434Z,1557198688.434 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:11:28.434Z,1557198688.434 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:11:30.022Z,1557198690.022 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:11:30.410Z,1557198690.410 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,031004.00,A,3648.16456,N,12147.27756,W,0.311,301.91,070519,,,A*70
2019-05-07T03:11:30.412Z,1557198690.412 [NAL9602](INFO): GPS fix at 20190507T031004: (36.802743, -121.787959)
2019-05-07T03:11:30.446Z,1557198690.446 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:11:30.446Z,1557198690.446 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:11:36.766Z,1557198696.766 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0061.lzma
2019-05-07T03:11:37.572Z,1557198697.572 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0061.lzma.bak
2019-05-07T03:11:37.572Z,1557198697.572 [DataOverHttps](INFO): SBD MOMSN=10949079
2019-05-07T03:11:49.599Z,1557198709.599 [DataOverHttps](INFO): Sending 651 bytes from file Logs/20190507T012400/Express0062.lzma
2019-05-07T03:11:50.404Z,1557198710.404 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0062.lzma.bak
2019-05-07T03:11:50.404Z,1557198710.404 [DataOverHttps](INFO): SBD MOMSN=10949084
2019-05-07T03:11:51.471Z,1557198711.471 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:11:51.471Z,1557198711.471 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:11:51.471Z,1557198711.471 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:12:03.132Z,1557198723.132 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:13:54.663Z,1557198834.663 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T03:13:54.663Z,1557198834.663 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050620213824,35.0, -0.1,   0.0,1448.9A,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T03:16:34.636Z,1557198994.636 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-05-07T03:16:34.636Z,1557198994.636 [RDI_Pathfinder](ERROR): Failed to parse:
:RA   0.00,   0.00,   0.00,   0.00
2019-05-07T03:16:52.019Z,1557199012.019 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:16:52.019Z,1557199012.019 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:16:52.019Z,1557199012.019 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:16:52.019Z,1557199012.019 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:16:52.432Z,1557199012.432 [Default:CheckIn:D] Stopped
2019-05-07T03:16:52.432Z,1557199012.432 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:16:52.829Z,1557199012.829 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.611117 min 
2019-05-07T03:16:52.830Z,1557199012.830 [Default:CheckIn:E] Stopped
2019-05-07T03:16:52.830Z,1557199012.830 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:16:52.830Z,1557199012.830 [Default:CheckIn] Stopped
2019-05-07T03:16:52.830Z,1557199012.830 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:16:52.830Z,1557199012.830 [Default:CheckIn](INFO): Running loop #21
2019-05-07T03:16:52.830Z,1557199012.830 [Default:CheckIn] Running Loop=21
2019-05-07T03:16:52.831Z,1557199012.831 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:16:52.831Z,1557199012.831 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:16:54.430Z,1557199014.430 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:16:54.826Z,1557199014.826 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,031528.00,A,3648.16541,N,12147.28514,W,0.350,0.00,070519,,,A*78
2019-05-07T03:16:54.828Z,1557199014.828 [NAL9602](INFO): GPS fix at 20190507T031528: (36.802757, -121.788086)
2019-05-07T03:16:54.852Z,1557199014.852 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:16:54.852Z,1557199014.852 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:17:00.926Z,1557199020.926 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0064.lzma
2019-05-07T03:17:01.732Z,1557199021.732 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0064.lzma.bak
2019-05-07T03:17:01.732Z,1557199021.732 [DataOverHttps](INFO): SBD MOMSN=10949138
2019-05-07T03:17:13.615Z,1557199033.615 [DataOverHttps](INFO): Sending 600 bytes from file Logs/20190507T012400/Express0065.lzma
2019-05-07T03:17:14.420Z,1557199034.420 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0065.lzma.bak
2019-05-07T03:17:14.420Z,1557199034.420 [DataOverHttps](INFO): SBD MOMSN=10949144
2019-05-07T03:17:15.494Z,1557199035.494 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:17:15.494Z,1557199035.494 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:17:15.494Z,1557199035.494 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:17:25.548Z,1557199045.548 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T03:17:25.622Z,1557199045.622 [NAL9602](FAULT): received: 
+CSQ:1

OK26, 0, 0, 0, 0

OK
2019-05-07T03:17:25.623Z,1557199045.623 [NAL9602] Data Fault, FailCount= 1
2019-05-07T03:17:25.623Z,1557199045.623 [NAL9602](ERROR): Data Fault
2019-05-07T03:17:25.722Z,1557199045.722 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T03:17:25.936Z,1557199045.936 [NAL9602](INFO): Powering down
2019-05-07T03:17:26.867Z,1557199046.867 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T03:17:26.867Z,1557199046.867 [NAL9602] No Fault, FailCount= 1
2019-05-07T03:17:43.353Z,1557199063.353 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-07T03:17:56.241Z,1557199076.241 [NAL9602](INFO): Powering up NAL9602
2019-05-07T03:18:07.178Z,1557199087.178 [NAL9602](INFO): NAL9602 initialized
2019-05-07T03:18:38.252Z,1557199118.252 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:19:37.273Z,1557199177.273 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-07T03:22:16.037Z,1557199336.037 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:22:16.037Z,1557199336.037 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:22:16.037Z,1557199336.037 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:22:16.038Z,1557199336.038 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:22:16.464Z,1557199336.464 [Default:CheckIn:D] Stopped
2019-05-07T03:22:16.464Z,1557199336.464 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:22:16.863Z,1557199336.863 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 114.011654 min 
2019-05-07T03:22:16.863Z,1557199336.863 [Default:CheckIn:E] Stopped
2019-05-07T03:22:16.863Z,1557199336.863 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:22:16.863Z,1557199336.863 [Default:CheckIn] Stopped
2019-05-07T03:22:16.864Z,1557199336.864 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:22:16.864Z,1557199336.864 [Default:CheckIn](INFO): Running loop #22
2019-05-07T03:22:16.864Z,1557199336.864 [Default:CheckIn] Running Loop=22
2019-05-07T03:22:16.864Z,1557199336.864 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:22:16.864Z,1557199336.864 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:22:18.446Z,1557199338.446 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:20.860Z,1557199340.860 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T03:22:21.678Z,1557199341.678 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:24.120Z,1557199344.120 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:27.342Z,1557199347.342 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:30.162Z,1557199350.162 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:32.994Z,1557199352.994 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:35.826Z,1557199355.826 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:39.066Z,1557199359.066 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:41.882Z,1557199361.882 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:45.110Z,1557199365.110 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:47.942Z,1557199367.942 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:51.174Z,1557199371.174 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:54.002Z,1557199374.002 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:22:57.234Z,1557199377.234 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:00.059Z,1557199380.059 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:02.899Z,1557199382.899 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:06.118Z,1557199386.118 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:08.950Z,1557199388.950 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:12.178Z,1557199392.178 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:15.010Z,1557199395.010 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:18.242Z,1557199398.242 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:21.071Z,1557199401.071 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:23.894Z,1557199403.894 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:27.126Z,1557199407.126 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:29.958Z,1557199409.958 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:33.190Z,1557199413.190 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:36.030Z,1557199416.030 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:36.473Z,1557199416.473 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-07T03:23:36.474Z,1557199416.474 [RDI_Pathfinder](ERROR): Failed to parse:
:BD +0.00,        +0.00,        +0.00,   0.00,3871.39
2019-05-07T03:23:39.250Z,1557199419.250 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:42.082Z,1557199422.082 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:45.310Z,1557199425.310 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:48.142Z,1557199428.142 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:50.962Z,1557199430.962 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:23:51.354Z,1557199431.354 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,032224.00,A,3648.16146,N,12147.28088,W,0.117,0.00,070519,,,A*72
2019-05-07T03:23:51.356Z,1557199431.356 [NAL9602](INFO): GPS fix at 20190507T032224: (36.802691, -121.788015)
2019-05-07T03:23:51.406Z,1557199431.406 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:23:51.407Z,1557199431.407 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:23:56.942Z,1557199436.942 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0067.lzma
2019-05-07T03:23:57.748Z,1557199437.748 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0067.lzma.bak
2019-05-07T03:23:57.748Z,1557199437.748 [DataOverHttps](INFO): SBD MOMSN=10949243
2019-05-07T03:24:10.207Z,1557199450.207 [DataOverHttps](INFO): Sending 865 bytes from file Logs/20190507T012400/Express0068.lzma
2019-05-07T03:24:11.012Z,1557199451.012 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0068.lzma.bak
2019-05-07T03:24:11.012Z,1557199451.012 [DataOverHttps](INFO): SBD MOMSN=10949246
2019-05-07T03:24:12.104Z,1557199452.104 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:24:12.104Z,1557199452.104 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:24:12.104Z,1557199452.104 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:24:24.156Z,1557199464.156 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:26:21.339Z,1557199581.339 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T03:26:21.340Z,1557199581.340 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,  

2019-05-07T03:27:33.276Z,1557199653.276 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-05-07T03:29:12.645Z,1557199752.645 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:29:12.645Z,1557199752.645 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:29:12.645Z,1557199752.645 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:29:12.646Z,1557199752.646 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:29:13.044Z,1557199753.044 [Default:CheckIn:D] Stopped
2019-05-07T03:29:13.044Z,1557199753.044 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:29:13.466Z,1557199753.466 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 120.954655 min 
2019-05-07T03:29:13.466Z,1557199753.466 [Default:CheckIn:E] Stopped
2019-05-07T03:29:13.466Z,1557199753.466 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:29:13.467Z,1557199753.467 [Default:CheckIn] Stopped
2019-05-07T03:29:13.467Z,1557199753.467 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:29:13.467Z,1557199753.467 [Default:CheckIn](INFO): Running loop #23
2019-05-07T03:29:13.467Z,1557199753.467 [Default:CheckIn] Running Loop=23
2019-05-07T03:29:13.467Z,1557199753.467 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:29:13.467Z,1557199753.467 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:29:15.054Z,1557199755.054 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:29:15.446Z,1557199755.446 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,032749.00,A,3648.16868,N,12147.27731,W,0.972,19.38,070519,,,A*4B
2019-05-07T03:29:15.448Z,1557199755.448 [NAL9602](INFO): GPS fix at 20190507T032749: (36.802811, -121.787955)
2019-05-07T03:29:15.482Z,1557199755.482 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:29:15.482Z,1557199755.482 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:29:21.358Z,1557199761.358 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0070.lzma
2019-05-07T03:29:22.165Z,1557199762.165 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0070.lzma.bak
2019-05-07T03:29:22.166Z,1557199762.166 [DataOverHttps](INFO): SBD MOMSN=10949286
2019-05-07T03:29:33.223Z,1557199773.223 [NAL9602](INFO): SBD MO Status=2, MOMSN=3827, MT Status=2, MTMSN=0
2019-05-07T03:29:33.223Z,1557199773.223 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T03:29:34.607Z,1557199774.607 [DataOverHttps](INFO): Sending 608 bytes from file Logs/20190507T012400/Express0071.lzma
2019-05-07T03:29:35.412Z,1557199775.412 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0071.lzma.bak
2019-05-07T03:29:35.412Z,1557199775.412 [DataOverHttps](INFO): SBD MOMSN=10949289
2019-05-07T03:29:36.489Z,1557199776.489 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:29:36.490Z,1557199776.490 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:29:36.490Z,1557199776.490 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:29:59.132Z,1557199799.132 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T03:29:59.132Z,1557199799.132 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00, :BI,-32768,-32768,-32768,-32768,V
2019-05-07T03:29:59.498Z,1557199799.498 [NAL9602](INFO): SBD MO Status=0, MOMSN=3827, MT Status=0, MTMSN=0
2019-05-07T03:29:59.498Z,1557199799.498 [NAL9602](INFO): No messages in MT queue
2019-05-07T03:30:30.188Z,1557199830.188 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:34:37.099Z,1557200077.099 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:34:37.099Z,1557200077.099 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:34:37.099Z,1557200077.099 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:34:37.099Z,1557200077.099 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:34:37.474Z,1557200077.474 [Default:CheckIn:D] Stopped
2019-05-07T03:34:37.474Z,1557200077.474 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:34:37.865Z,1557200077.865 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 126.361816 min 
2019-05-07T03:34:37.866Z,1557200077.866 [Default:CheckIn:E] Stopped
2019-05-07T03:34:37.866Z,1557200077.866 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:34:37.866Z,1557200077.866 [Default:CheckIn] Stopped
2019-05-07T03:34:37.866Z,1557200077.866 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:34:37.882Z,1557200077.882 [Default:CheckIn](INFO): Running loop #24
2019-05-07T03:34:37.882Z,1557200077.882 [Default:CheckIn] Running Loop=24
2019-05-07T03:34:37.882Z,1557200077.882 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:34:37.883Z,1557200077.883 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:34:39.470Z,1557200079.470 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:34:39.866Z,1557200079.866 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,033313.00,A,3648.16468,N,12147.28599,W,0.136,205.34,070519,,,A*79
2019-05-07T03:34:39.868Z,1557200079.868 [NAL9602](INFO): GPS fix at 20190507T033313: (36.802745, -121.788100)
2019-05-07T03:34:39.891Z,1557200079.891 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:34:39.891Z,1557200079.891 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:34:45.778Z,1557200085.778 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0073.lzma
2019-05-07T03:34:46.584Z,1557200086.584 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0073.lzma.bak
2019-05-07T03:34:46.584Z,1557200086.584 [DataOverHttps](INFO): SBD MOMSN=10949323
2019-05-07T03:34:58.775Z,1557200098.775 [DataOverHttps](INFO): Sending 688 bytes from file Logs/20190507T012400/Express0074.lzma
2019-05-07T03:34:59.580Z,1557200099.580 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0074.lzma.bak
2019-05-07T03:34:59.580Z,1557200099.580 [DataOverHttps](INFO): SBD MOMSN=10949327
2019-05-07T03:35:00.537Z,1557200100.537 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:35:00.537Z,1557200100.537 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:35:00.537Z,1557200100.537 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:37:00.202Z,1557200220.202 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-05-07T03:37:00.202Z,1557200220.202 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-05-07T03:37:00.202Z,1557200220.202 [RDI_Pathfinder](ERROR): Communications Fault
2019-05-07T03:37:00.203Z,1557200220.203 [RDI_Pathfinder](ERROR): Failed to parse:
2019-05-07T03:37:00.223Z,1557200220.223 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-05-07T03:37:00.603Z,1557200220.603 [RDI_Pathfinder](INFO): Powering down
2019-05-07T03:37:01.375Z,1557200221.375 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-05-07T03:37:01.375Z,1557200221.375 [RDI_Pathfinder] No Fault, FailCount= 1
2019-05-07T03:37:14.683Z,1557200234.683 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T03:39:32.022Z,1557200372.022 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T03:39:32.022Z,1557200372.022 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050620471580,35.0, -0.1,   .9,  0
2019-05-07T03:39:42.108Z,1557200382.108 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T03:39:56.698Z,1557200396.698 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-07T03:39:56.698Z,1557200396.698 [RDI_Pathfinder](ERROR): Failed to parse:
:BD +0.00,        +0.00,        +0.00,   0.00,162.00
2019-05-07T03:40:01.139Z,1557200401.139 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:40:01.139Z,1557200401.139 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:40:01.139Z,1557200401.139 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:40:01.140Z,1557200401.140 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:40:01.519Z,1557200401.519 [Default:CheckIn:D] Stopped
2019-05-07T03:40:01.519Z,1557200401.519 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:40:01.937Z,1557200401.937 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 131.762573 min 
2019-05-07T03:40:01.937Z,1557200401.937 [Default:CheckIn:E] Stopped
2019-05-07T03:40:01.937Z,1557200401.937 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:40:01.937Z,1557200401.937 [Default:CheckIn] Stopped
2019-05-07T03:40:01.937Z,1557200401.937 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:40:01.937Z,1557200401.937 [Default:CheckIn](INFO): Running loop #25
2019-05-07T03:40:01.937Z,1557200401.937 [Default:CheckIn] Running Loop=25
2019-05-07T03:40:01.938Z,1557200401.938 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:40:01.938Z,1557200401.938 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:40:03.526Z,1557200403.526 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:40:03.927Z,1557200403.927 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,033837.00,A,3648.15349,N,12147.29194,W,0.700,205.34,070519,,,A*78
2019-05-07T03:40:03.929Z,1557200403.929 [NAL9602](INFO): GPS fix at 20190507T033837: (36.802558, -121.788199)
2019-05-07T03:40:03.962Z,1557200403.962 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:40:03.962Z,1557200403.962 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:40:09.762Z,1557200409.762 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0076.lzma
2019-05-07T03:40:10.568Z,1557200410.568 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0076.lzma.bak
2019-05-07T03:40:10.568Z,1557200410.568 [DataOverHttps](INFO): SBD MOMSN=10949367
2019-05-07T03:40:22.619Z,1557200422.619 [DataOverHttps](INFO): Sending 809 bytes from file Logs/20190507T012400/Express0077.lzma
2019-05-07T03:40:23.397Z,1557200423.397 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0077.lzma.bak
2019-05-07T03:40:23.397Z,1557200423.397 [DataOverHttps](INFO): SBD MOMSN=10949370
2019-05-07T03:40:24.239Z,1557200424.239 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:40:24.239Z,1557200424.239 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:40:24.239Z,1557200424.239 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:40:35.915Z,1557200435.915 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:41:28.042Z,1557200488.042 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T03:45:24.824Z,1557200724.824 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:45:24.825Z,1557200724.825 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:45:24.825Z,1557200724.825 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:45:24.825Z,1557200724.825 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:45:25.227Z,1557200725.227 [Default:CheckIn:D] Stopped
2019-05-07T03:45:25.227Z,1557200725.227 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:45:25.657Z,1557200725.657 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 137.157715 min 
2019-05-07T03:45:25.658Z,1557200725.658 [Default:CheckIn:E] Stopped
2019-05-07T03:45:25.658Z,1557200725.658 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:45:25.658Z,1557200725.658 [Default:CheckIn] Stopped
2019-05-07T03:45:25.658Z,1557200725.658 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:45:25.662Z,1557200725.662 [Default:CheckIn](INFO): Running loop #26
2019-05-07T03:45:25.662Z,1557200725.662 [Default:CheckIn] Running Loop=26
2019-05-07T03:45:25.662Z,1557200725.662 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:45:25.663Z,1557200725.663 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:45:27.222Z,1557200727.222 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:45:27.615Z,1557200727.615 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,034401.00,A,3648.17087,N,12147.28079,W,0.525,205.34,070519,,,A*73
2019-05-07T03:45:27.617Z,1557200727.617 [NAL9602](INFO): GPS fix at 20190507T034401: (36.802848, -121.788013)
2019-05-07T03:45:27.641Z,1557200727.641 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:45:27.641Z,1557200727.641 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:45:31.378Z,1557200731.378 [RDI_Pathfinder](ERROR): Failed to parse:
:0,   0.00,   0.00,   0.00
2019-05-07T03:45:33.254Z,1557200733.254 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0079.lzma
2019-05-07T03:45:34.060Z,1557200734.060 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0079.lzma.bak
2019-05-07T03:45:34.060Z,1557200734.060 [DataOverHttps](INFO): SBD MOMSN=10949429
2019-05-07T03:45:48.939Z,1557200748.939 [DataOverHttps](INFO): Sending 706 bytes from file Logs/20190507T012400/Express0080.lzma
2019-05-07T03:45:49.744Z,1557200749.744 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0080.lzma.bak
2019-05-07T03:45:49.744Z,1557200749.744 [DataOverHttps](INFO): SBD MOMSN=10949432
2019-05-07T03:45:50.781Z,1557200750.781 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:45:50.781Z,1557200750.781 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:45:50.782Z,1557200750.782 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:45:58.412Z,1557200758.412 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T03:45:58.486Z,1557200758.486 [NAL9602](FAULT): received: 
+CSQ:1

OK27, 0, 0, 0, 0

OK
2019-05-07T03:45:58.487Z,1557200758.487 [NAL9602] Data Fault, FailCount= 1
2019-05-07T03:45:58.487Z,1557200758.487 [NAL9602](ERROR): Data Fault
2019-05-07T03:45:58.545Z,1557200758.545 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T03:45:58.827Z,1557200758.827 [NAL9602](INFO): Powering down
2019-05-07T03:45:59.715Z,1557200759.715 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T03:45:59.715Z,1557200759.715 [NAL9602] No Fault, FailCount= 1
2019-05-07T03:46:25.095Z,1557200785.095 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T03:46:29.117Z,1557200789.117 [NAL9602](INFO): Powering up NAL9602
2019-05-07T03:46:40.025Z,1557200800.025 [NAL9602](INFO): NAL9602 initialized
2019-05-07T03:47:11.132Z,1557200831.132 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:47:39.845Z,1557200859.845 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-07T03:48:41.685Z,1557200921.685 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T03:48:41.685Z,1557200921.685 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-2768,V
2019-05-07T03:50:36.013Z,1557201036.013 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T03:50:36.013Z,1557201036.013 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-3276,V
2019-05-07T03:50:51.345Z,1557201051.345 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:50:51.345Z,1557201051.345 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:50:51.345Z,1557201051.345 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:50:51.346Z,1557201051.346 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:50:51.759Z,1557201051.759 [Default:CheckIn:D] Stopped
2019-05-07T03:50:51.759Z,1557201051.759 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:50:52.160Z,1557201052.160 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 142.599902 min 
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn:E] Stopped
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn] Stopped
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn](INFO): Running loop #27
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn] Running Loop=27
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:50:52.161Z,1557201052.161 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:50:53.754Z,1557201053.754 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:50:54.147Z,1557201054.147 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,034927.00,A,3648.15955,N,12147.28146,W,0.505,0.00,070519,,,A*71
2019-05-07T03:50:54.149Z,1557201054.149 [NAL9602](INFO): GPS fix at 20190507T034927: (36.802659, -121.788024)
2019-05-07T03:50:54.186Z,1557201054.186 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:50:54.186Z,1557201054.186 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:50:55.801Z,1557201055.801 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T03:50:59.758Z,1557201059.758 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190507T012400/Courier0082.lzma
2019-05-07T03:51:00.851Z,1557201060.851 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0082.lzma.bak
2019-05-07T03:51:00.851Z,1557201060.851 [DataOverHttps](INFO): SBD MOMSN=10949437
2019-05-07T03:51:12.216Z,1557201072.216 [DataOverHttps](INFO): Sending 710 bytes from file Logs/20190507T012400/Express0083.lzma
2019-05-07T03:51:13.020Z,1557201073.020 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0083.lzma.bak
2019-05-07T03:51:13.021Z,1557201073.021 [DataOverHttps](INFO): SBD MOMSN=10949440
2019-05-07T03:51:14.025Z,1557201074.025 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:51:14.025Z,1557201074.025 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:51:14.025Z,1557201074.025 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:51:26.506Z,1557201086.506 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T03:52:37.722Z,1557201157.722 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-05-07T03:52:37.722Z,1557201157.722 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-05-07T03:52:37.722Z,1557201157.722 [RDI_Pathfinder](ERROR): Communications Fault
2019-05-07T03:52:37.723Z,1557201157.723 [RDI_Pathfinder](ERROR): Failed to parse:
2019-05-07T03:52:37.747Z,1557201157.747 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-05-07T03:52:38.107Z,1557201158.107 [RDI_Pathfinder](INFO): Powering down
2019-05-07T03:52:38.867Z,1557201158.867 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-05-07T03:52:38.867Z,1557201158.867 [RDI_Pathfinder] No Fault, FailCount= 1
2019-05-07T03:52:52.201Z,1557201172.201 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-07T03:53:26.514Z,1557201206.514 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T03:53:26.515Z,1557201206.515 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050621011031,35.0, 0.0,1448.9,  0
2019-05-07T03:55:26.503Z,1557201326.503 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-07T03:56:12.571Z,1557201372.571 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T03:56:12.571Z,1557201372.571 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050621035631,35.0, -0.1,   0.0,144

2019-05-07T03:56:14.583Z,1557201374.583 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T03:56:14.583Z,1557201374.583 [Default:CheckIn:C.Wait] Stopped
2019-05-07T03:56:14.583Z,1557201374.583 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T03:56:14.584Z,1557201374.584 [Default:CheckIn:D] Running Loop=1
2019-05-07T03:56:14.997Z,1557201374.997 [Default:CheckIn:D] Stopped
2019-05-07T03:56:14.997Z,1557201374.997 [Default:CheckIn:E] Running Loop=1
2019-05-07T03:56:15.404Z,1557201375.404 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 147.987207 min 
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn:E] Stopped
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn] Stopped
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn](INFO): Running loop #28
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn] Running Loop=28
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T03:56:15.405Z,1557201375.405 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T03:56:16.994Z,1557201376.994 [NAL9602](DEBUG): Fix Requested
2019-05-07T03:56:17.386Z,1557201377.386 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,035451.00,A,3648.17127,N,12147.28606,W,0.292,0.00,070519,,,A*79
2019-05-07T03:56:17.388Z,1557201377.388 [NAL9602](INFO): GPS fix at 20190507T035451: (36.802855, -121.788101)
2019-05-07T03:56:17.422Z,1557201377.422 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T03:56:17.422Z,1557201377.422 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T03:56:23.314Z,1557201383.314 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0085.lzma
2019-05-07T03:56:24.126Z,1557201384.126 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0085.lzma.bak
2019-05-07T03:56:24.127Z,1557201384.127 [DataOverHttps](INFO): SBD MOMSN=10949499
2019-05-07T03:56:35.992Z,1557201395.992 [DataOverHttps](INFO): Sending 766 bytes from file Logs/20190507T012400/Express0086.lzma
2019-05-07T03:56:36.796Z,1557201396.796 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0086.lzma.bak
2019-05-07T03:56:36.796Z,1557201396.796 [DataOverHttps](INFO): SBD MOMSN=10949502
2019-05-07T03:56:37.637Z,1557201397.637 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T03:56:37.637Z,1557201397.637 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T03:56:37.637Z,1557201397.637 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T03:56:47.719Z,1557201407.719 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050621043131,35.0, -0.1,   0.0,1448.9,  0
2019-05-07T03:57:34.962Z,1557201454.962 [NAL9602](INFO): SBD MO Status=2, MOMSN=3828, MT Status=2, MTMSN=0
2019-05-07T03:57:34.962Z,1557201454.962 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T03:58:18.585Z,1557201498.585 [NAL9602](INFO): SBD MO Status=2, MOMSN=3828, MT Status=2, MTMSN=0
2019-05-07T03:58:18.586Z,1557201498.586 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T03:58:25.897Z,1557201505.897 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T03:58:25.897Z,1557201505.897 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T04:00:53.351Z,1557201653.351 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-07T04:01:19.981Z,1557201679.981 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T04:01:38.187Z,1557201698.187 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T04:01:38.187Z,1557201698.187 [Default:CheckIn:C.Wait] Stopped
2019-05-07T04:01:38.187Z,1557201698.187 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:01:38.188Z,1557201698.188 [Default:CheckIn:D] Running Loop=1
2019-05-07T04:01:38.596Z,1557201698.596 [Default:CheckIn:D] Stopped
2019-05-07T04:01:38.596Z,1557201698.596 [Default:CheckIn:E] Running Loop=1
2019-05-07T04:01:38.999Z,1557201698.999 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 153.380534 min 
2019-05-07T04:01:38.999Z,1557201698.999 [Default:CheckIn:E] Stopped
2019-05-07T04:01:38.999Z,1557201698.999 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T04:01:38.000Z,1557201699.000 [Default:CheckIn] Stopped
2019-05-07T04:01:38.000Z,1557201699.000 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:01:38.000Z,1557201699.000 [Default:CheckIn](INFO): Running loop #29
2019-05-07T04:01:39.000Z,1557201699.000 [Default:CheckIn] Running Loop=29
2019-05-07T04:01:39.000Z,1557201699.000 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T04:01:39.000Z,1557201699.000 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T04:01:40.602Z,1557201700.602 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:01:40.994Z,1557201700.994 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,040014.00,A,3648.16615,N,12147.28289,W,0.136,0.00,070519,,,A*77
2019-05-07T04:01:40.996Z,1557201700.996 [NAL9602](INFO): GPS fix at 20190507T040014: (36.802769, -121.788048)
2019-05-07T04:01:41.019Z,1557201701.019 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T04:01:41.019Z,1557201701.019 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T04:01:46.826Z,1557201706.826 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0088.lzma
2019-05-07T04:01:47.632Z,1557201707.632 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0088.lzma.bak
2019-05-07T04:01:47.632Z,1557201707.632 [DataOverHttps](INFO): SBD MOMSN=10949536
2019-05-07T04:02:02.443Z,1557201722.443 [DataOverHttps](INFO): Sending 718 bytes from file Logs/20190507T012400/Express0089.lzma
2019-05-07T04:02:03.248Z,1557201723.248 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0089.lzma.bak
2019-05-07T04:02:03.248Z,1557201723.248 [DataOverHttps](INFO): SBD MOMSN=10949539
2019-05-07T04:02:04.917Z,1557201724.917 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T04:02:04.917Z,1557201724.917 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T04:02:04.917Z,1557201724.917 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:02:12.968Z,1557201732.968 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T04:04:50.560Z,1557201890.560 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T04:04:50.560Z,1557201890.560 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050621123431,35.0, -0.1,   0.0, 0
2019-05-07T04:07:05.513Z,1557202025.513 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T04:07:05.513Z,1557202025.513 [Default:CheckIn:C.Wait] Stopped
2019-05-07T04:07:05.513Z,1557202025.513 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:07:05.514Z,1557202025.514 [Default:CheckIn:D] Running Loop=1
2019-05-07T04:07:05.897Z,1557202025.897 [Default:CheckIn:D] Stopped
2019-05-07T04:07:05.897Z,1557202025.897 [Default:CheckIn:E] Running Loop=1
2019-05-07T04:07:06.315Z,1557202026.315 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 158.835547 min 
2019-05-07T04:07:06.315Z,1557202026.315 [Default:CheckIn:E] Stopped
2019-05-07T04:07:06.315Z,1557202026.315 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T04:07:06.315Z,1557202026.315 [Default:CheckIn] Stopped
2019-05-07T04:07:06.316Z,1557202026.316 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:07:06.316Z,1557202026.316 [Default:CheckIn](INFO): Running loop #30
2019-05-07T04:07:06.316Z,1557202026.316 [Default:CheckIn] Running Loop=30
2019-05-07T04:07:06.316Z,1557202026.316 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T04:07:06.316Z,1557202026.316 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T04:07:07.906Z,1557202027.906 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:07:08.298Z,1557202028.298 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,040541.00,A,3648.16418,N,12147.28463,W,0.194,0.00,070519,,,A*77
2019-05-07T04:07:08.300Z,1557202028.300 [NAL9602](INFO): GPS fix at 20190507T040541: (36.802736, -121.788077)
2019-05-07T04:07:08.333Z,1557202028.333 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T04:07:08.333Z,1557202028.333 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T04:07:14.350Z,1557202034.350 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0091.lzma
2019-05-07T04:07:15.162Z,1557202035.162 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0091.lzma.bak
2019-05-07T04:07:15.175Z,1557202035.175 [DataOverHttps](INFO): SBD MOMSN=10949576
2019-05-07T04:07:27.140Z,1557202047.140 [DataOverHttps](INFO): Sending 673 bytes from file Logs/20190507T012400/Express0092.lzma
2019-05-07T04:07:27.944Z,1557202047.944 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0092.lzma.bak
2019-05-07T04:07:27.944Z,1557202047.944 [DataOverHttps](INFO): SBD MOMSN=10949579
2019-05-07T04:07:28.969Z,1557202048.969 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T04:07:28.969Z,1557202048.969 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T04:07:28.969Z,1557202048.969 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:07:39.032Z,1557202059.032 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-07T04:07:39.106Z,1557202059.106 [NAL9602](FAULT): received: 
+CSQ:0

OK28, 2, 0, 0, 0

OK
2019-05-07T04:07:39.106Z,1557202059.106 [NAL9602] Data Fault, FailCount= 1
2019-05-07T04:07:39.106Z,1557202059.106 [NAL9602](ERROR): Data Fault
2019-05-07T04:07:39.217Z,1557202059.217 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-07T04:07:39.436Z,1557202059.436 [NAL9602](INFO): Powering down
2019-05-07T04:07:40.317Z,1557202060.317 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-07T04:07:40.318Z,1557202060.318 [NAL9602] No Fault, FailCount= 1
2019-05-07T04:08:09.737Z,1557202089.737 [NAL9602](INFO): Powering up NAL9602
2019-05-07T04:08:20.649Z,1557202100.649 [NAL9602](INFO): NAL9602 initialized
2019-05-07T04:08:51.373Z,1557202131.373 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-07T04:08:51.373Z,1557202131.373 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-3268,V
2019-05-07T04:08:51.756Z,1557202131.756 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T04:10:50.565Z,1557202250.565 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-07T04:10:50.565Z,1557202250.565 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190506211834310.1,   0.0,1448.9,  0
2019-05-07T04:11:13.587Z,1557202273.587 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-05-07T04:12:08.524Z,1557202328.524 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T04:12:08.524Z,1557202328.524 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T04:12:29.548Z,1557202349.548 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T04:12:29.548Z,1557202349.548 [Default:CheckIn:C.Wait] Stopped
2019-05-07T04:12:29.548Z,1557202349.548 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:12:29.549Z,1557202349.549 [Default:CheckIn:D] Running Loop=1
2019-05-07T04:12:29.945Z,1557202349.945 [Default:CheckIn:D] Stopped
2019-05-07T04:12:29.945Z,1557202349.945 [Default:CheckIn:E] Running Loop=1
2019-05-07T04:12:30.422Z,1557202350.422 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 164.236344 min 
2019-05-07T04:12:30.422Z,1557202350.422 [Default:CheckIn:E] Stopped
2019-05-07T04:12:30.423Z,1557202350.423 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T04:12:30.423Z,1557202350.423 [Default:CheckIn] Stopped
2019-05-07T04:12:30.423Z,1557202350.423 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:12:30.423Z,1557202350.423 [Default:CheckIn](INFO): Running loop #31
2019-05-07T04:12:30.423Z,1557202350.423 [Default:CheckIn] Running Loop=31
2019-05-07T04:12:30.423Z,1557202350.423 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T04:12:30.423Z,1557202350.423 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T04:12:31.946Z,1557202351.946 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:34.764Z,1557202354.764 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-07T04:12:35.599Z,1557202355.599 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:38.022Z,1557202358.022 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:40.834Z,1557202360.834 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:44.070Z,1557202364.070 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:46.906Z,1557202366.906 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:50.139Z,1557202370.139 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:52.959Z,1557202372.959 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:56.210Z,1557202376.210 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:12:59.014Z,1557202379.014 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:13:02.246Z,1557202382.246 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:13:02.638Z,1557202382.638 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,041135.00,A,3648.16591,N,12147.28489,W,0.369,0.00,070519,,,A*75
2019-05-07T04:13:02.640Z,1557202382.640 [NAL9602](INFO): GPS fix at 20190507T041135: (36.802765, -121.788082)
2019-05-07T04:13:02.669Z,1557202382.669 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T04:13:02.669Z,1557202382.669 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T04:13:08.598Z,1557202388.598 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190507T012400/Courier0094.lzma
2019-05-07T04:13:09.404Z,1557202389.404 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0094.lzma.bak
2019-05-07T04:13:09.404Z,1557202389.404 [DataOverHttps](INFO): SBD MOMSN=10949616
2019-05-07T04:13:19.622Z,1557202399.622 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T04:13:19.623Z,1557202399.623 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  89.27,  93.26,   0.00
2019-05-07T04:13:21.987Z,1557202401.987 [DataOverHttps](INFO): Sending 863 bytes from file Logs/20190507T012400/Express0095.lzma
2019-05-07T04:13:22.792Z,1557202402.792 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0095.lzma.bak
2019-05-07T04:13:22.792Z,1557202402.792 [DataOverHttps](INFO): SBD MOMSN=10949619
2019-05-07T04:13:23.669Z,1557202403.669 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T04:13:23.670Z,1557202403.670 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T04:13:23.670Z,1557202403.670 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:13:34.956Z,1557202414.956 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-07T04:14:56.583Z,1557202496.583 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-07T04:14:56.583Z,1557202496.583 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-07T04:18:12.146Z,1557202692.146 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-05-07T04:18:24.253Z,1557202704.253 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-07T04:18:24.253Z,1557202704.253 [Default:CheckIn:C.Wait] Stopped
2019-05-07T04:18:24.253Z,1557202704.253 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:18:24.254Z,1557202704.254 [Default:CheckIn:D] Running Loop=1
2019-05-07T04:18:24.653Z,1557202704.653 [Default:CheckIn:D] Stopped
2019-05-07T04:18:24.653Z,1557202704.653 [Default:CheckIn:E] Running Loop=1
2019-05-07T04:18:25.057Z,1557202705.057 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 170.148145 min 
2019-05-07T04:18:25.058Z,1557202705.058 [Default:CheckIn:E] Stopped
2019-05-07T04:18:25.058Z,1557202705.058 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-07T04:18:25.058Z,1557202705.058 [Default:CheckIn] Stopped
2019-05-07T04:18:25.058Z,1557202705.058 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:18:25.058Z,1557202705.058 [Default:CheckIn](INFO): Running loop #32
2019-05-07T04:18:25.058Z,1557202705.058 [Default:CheckIn] Running Loop=32
2019-05-07T04:18:25.058Z,1557202705.058 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-07T04:18:25.059Z,1557202705.059 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-07T04:18:26.662Z,1557202706.662 [NAL9602](DEBUG): Fix Requested
2019-05-07T04:18:27.054Z,1557202707.054 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,041700.00,A,3648.15700,N,12147.28826,W,1.341,334.64,070519,,,A*78
2019-05-07T04:18:27.056Z,1557202707.056 [NAL9602](INFO): GPS fix at 20190507T041700: (36.802617, -121.788138)
2019-05-07T04:18:27.100Z,1557202707.100 [Default:CheckIn:Read_GPS] Stopped
2019-05-07T04:18:27.100Z,1557202707.100 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-07T04:18:32.906Z,1557202712.906 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190507T012400/Courier0097.lzma
2019-05-07T04:18:33.712Z,1557202713.712 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Courier0097.lzma.bak
2019-05-07T04:18:33.712Z,1557202713.712 [DataOverHttps](INFO): SBD MOMSN=10949665
2019-05-07T04:18:45.599Z,1557202725.599 [DataOverHttps](INFO): Sending 657 bytes from file Logs/20190507T012400/Express0098.lzma
2019-05-07T04:18:46.404Z,1557202726.404 [DataOverHttps](INFO): Moved sent file to Logs/20190507T012400/Express0098.lzma.bak
2019-05-07T04:18:46.404Z,1557202726.404 [DataOverHttps](INFO): SBD MOMSN=10949668
2019-05-07T04:18:47.361Z,1557202727.361 [Default:CheckIn:Read_Iridium] Stopped
2019-05-07T04:18:47.361Z,1557202727.361 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-07T04:18:47.362Z,1557202727.362 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-07T04:19:49.553Z,1557202789.553 [NAL9602](INFO): SBD MO Status=2, MOMSN=3828, MT Status=2, MTMSN=0
2019-05-07T04:19:49.553Z,1557202789.553 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-07T04:20:47.924Z,1557202847.924 [CommandLine](IMPORTANT): got command restart application
2019-05-07T04:20:48.934Z,1557202848.934 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:48.935Z,1557202848.935 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.062Z,1557202849.062 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-07T04:20:49.062Z,1557202849.062 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.063Z,1557202849.063 [CommandLine](INFO): Join timeout helper Thread ID is 1695
2019-05-07T04:20:49.070Z,1557202849.070 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-07T04:20:49.070Z,1557202849.070 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.071Z,1557202849.071 [NavChartDb](INFO): Join timeout helper Thread ID is 1696
2019-05-07T04:20:49.130Z,1557202849.130 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:49.131Z,1557202849.131 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.138Z,1557202849.138 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-07T04:20:49.138Z,1557202849.138 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.139Z,1557202849.139 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1697
2019-05-07T04:20:49.159Z,1557202849.159 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:49.159Z,1557202849.159 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-07T04:20:49.159Z,1557202849.159 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.178Z,1557202849.178 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-07T04:20:49.178Z,1557202849.178 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.179Z,1557202849.179 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1698
2019-05-07T04:20:49.347Z,1557202849.347 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:49.347Z,1557202849.347 [CTD_NeilBrown](INFO): Powering down
2019-05-07T04:20:49.358Z,1557202849.358 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.362Z,1557202849.362 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-07T04:20:49.363Z,1557202849.363 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.363Z,1557202849.363 [Radio_Surface](INFO): Join timeout helper Thread ID is 1699
2019-05-07T04:20:49.506Z,1557202849.506 [Radio_Surface](INFO): Powering down
2019-05-07T04:20:49.507Z,1557202849.507 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:49.508Z,1557202849.508 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.527Z,1557202849.527 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-07T04:20:49.527Z,1557202849.527 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.528Z,1557202849.528 [DataOverHttps](INFO): Join timeout helper Thread ID is 1700
2019-05-07T04:20:49.774Z,1557202849.774 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:49.775Z,1557202849.775 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.777Z,1557202849.777 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-07T04:20:49.777Z,1557202849.777 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.778Z,1557202849.778 [logger](INFO): Join timeout helper Thread ID is 1701
2019-05-07T04:20:49.866Z,1557202849.866 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:49.866Z,1557202849.866 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.887Z,1557202849.887 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-07T04:20:49.887Z,1557202849.887 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.887Z,1557202849.887 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-07T04:20:49.887Z,1557202849.887 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:49.888Z,1557202849.888 [controlThread](INFO): Join timeout helper Thread ID is 1702
2019-05-07T04:20:50.131Z,1557202850.131 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-07T04:20:50.132Z,1557202850.132 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-07T04:20:50.133Z,1557202850.133 [AHRS_M2](INFO): Powering down
2019-05-07T04:20:50.207Z,1557202850.207 [DUSBL_Hydroid](INFO): Powering down
2019-05-07T04:20:50.279Z,1557202850.279 [Micromodem](INFO): Powering down
2019-05-07T04:20:50.375Z,1557202850.375 [NAL9602](INFO): Powering down
2019-05-07T04:20:50.446Z,1557202850.446 [RDI_Pathfinder](INFO): Powering down
2019-05-07T04:20:50.448Z,1557202850.448 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-07T04:20:50.449Z,1557202850.449 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-07T04:20:50.449Z,1557202850.449 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-07T04:20:50.450Z,1557202850.450 [MissionManager](INFO): Uninitializing Mission Default
2019-05-07T04:20:50.450Z,1557202850.450 [Default] Stopped
2019-05-07T04:20:50.450Z,1557202850.450 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-07T04:20:50.450Z,1557202850.450 [Default:B.GoToSurface] Stopped
2019-05-07T04:20:50.450Z,1557202850.450 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-07T04:20:50.450Z,1557202850.450 [Default:CheckIn] Stopped
2019-05-07T04:20:50.450Z,1557202850.450 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-07T04:20:50.450Z,1557202850.450 [Default:CheckIn:C.Wait] Stopped
2019-05-07T04:20:50.450Z,1557202850.450 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-07T04:20:50.453Z,1557202850.453 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-07T04:20:50.453Z,1557202850.453 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-07T04:20:50.453Z,1557202850.453 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-07T04:20:50.453Z,1557202850.453 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-07T04:20:50.454Z,1557202850.454 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-07T04:20:50.454Z,1557202850.454 [BuoyancyServo](INFO): Powering down
2019-05-07T04:20:50.466Z,1557202850.466 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-07T04:20:50.466Z,1557202850.466 [ElevatorServo](INFO): Powering down
2019-05-07T04:20:50.467Z,1557202850.467 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-07T04:20:50.467Z,1557202850.467 [MassServo](INFO): Powering down
2019-05-07T04:20:50.468Z,1557202850.468 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-07T04:20:50.468Z,1557202850.468 [RudderServo](INFO): Powering down
2019-05-07T04:20:50.469Z,1557202850.469 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-07T04:20:50.469Z,1557202850.469 [ThrusterServo](INFO): Powering down
2019-05-07T04:20:50.470Z,1557202850.470 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-07T04:20:50.470Z,1557202850.470 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-07T04:20:50.471Z,1557202850.471 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-07T04:20:50.471Z,1557202850.471 [CBIT](DEBUG): Powering off loads.
2019-05-07T04:20:50.482Z,1557202850.482 [CBIT](DEBUG): Disabling WDT.
2019-05-07T04:20:50.494Z,1557202850.494 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-07T04:20:50.495Z,1557202850.495 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:50.542Z,1557202850.542 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:50.551Z,1557202850.551 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:50.595Z,1557202850.595 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:50.597Z,1557202850.597 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:50.651Z,1557202850.651 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-07T04:20:50.718Z,1557202850.718 [logger ThreadHandler](INFO): Thread cancelled.