2019-05-06T17:57:44.926Z,1557165464.926 [Supervisor](DEBUG): Initializing supervisor.
2019-05-06T17:57:44.929Z,1557165464.929 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-06T17:57:44.929Z,1557165464.929 [SyncHandler](INFO): Protected caller Thread ID is 3215
2019-05-06T17:57:44.930Z,1557165464.930 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-06T17:57:44.931Z,1557165464.931 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-06T17:57:44.931Z,1557165464.931 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3216
2019-05-06T17:57:44.934Z,1557165464.934 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-06T17:57:44.946Z,1557165464.946 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-06T17:57:44.947Z,1557165464.947 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-06T17:57:44.948Z,1557165464.948 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3217
2019-05-06T17:57:44.948Z,1557165464.948 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-06T17:57:44.949Z,1557165464.949 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-06T17:57:44.950Z,1557165464.950 [logger ThreadHandler](INFO): Protected caller Thread ID is 3218
2019-05-06T17:57:44.952Z,1557165464.952 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-06T17:57:44.952Z,1557165464.952 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-06T17:57:44.954Z,1557165464.954 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-06T17:57:45.372Z,1557165465.372 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-06T17:57:45.372Z,1557165465.372 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-06T17:57:45.469Z,1557165465.469 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-06T17:57:45.470Z,1557165465.470 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-06T17:57:45.791Z,1557165465.791 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-06T17:57:45.792Z,1557165465.792 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-06T17:57:45.932Z,1557165465.932 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-06T17:57:45.933Z,1557165465.933 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-06T17:57:46.123Z,1557165466.123 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-06T17:57:46.123Z,1557165466.123 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-06T17:57:46.746Z,1557165466.746 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-06T17:57:46.746Z,1557165466.746 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-06T17:57:46.954Z,1557165466.954 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-06T17:57:46.955Z,1557165466.955 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-06T17:57:47.099Z,1557165467.099 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-06T17:57:47.100Z,1557165467.100 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-06T17:57:47.291Z,1557165467.291 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-06T17:57:47.292Z,1557165467.292 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-06T17:57:47.386Z,1557165467.386 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-06T17:57:47.387Z,1557165467.387 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-06T17:57:47.707Z,1557165467.707 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-06T17:57:47.707Z,1557165467.707 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-06T17:57:47.787Z,1557165467.787 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-06T17:57:47.889Z,1557165467.889 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-06T17:57:47.889Z,1557165467.889 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-06T17:57:48.461Z,1557165468.461 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-06T17:57:48.462Z,1557165468.462 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-06T17:57:48.852Z,1557165468.852 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-06T17:57:48.854Z,1557165468.854 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-06T17:57:48.855Z,1557165468.855 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-06T17:57:49.061Z,1557165469.061 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-06T17:57:49.160Z,1557165469.160 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-06T17:57:49.258Z,1557165469.258 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-06T17:57:49.482Z,1557165469.482 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-06T17:57:49.482Z,1557165469.482 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-06T17:57:49.566Z,1557165469.566 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-06T17:57:49.657Z,1557165469.657 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-06T17:57:49.753Z,1557165469.753 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-06T17:57:49.835Z,1557165469.835 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-06T17:57:49.942Z,1557165469.942 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-06T17:57:50.110Z,1557165470.110 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-06T17:57:50.240Z,1557165470.240 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-05-06T17:57:50.241Z,1557165470.241 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-06T17:57:50.254Z,1557165470.254 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-06T17:57:50.632Z,1557165470.632 [AHRS_M2] Loaded
2019-05-06T17:57:50.633Z,1557165470.633 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-06T17:57:50.705Z,1557165470.705 [DataOverHttps] Loaded
2019-05-06T17:57:50.706Z,1557165470.706 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-06T17:57:50.707Z,1557165470.707 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-06T17:57:50.707Z,1557165470.707 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3297
2019-05-06T17:57:50.720Z,1557165470.720 [Depth_Keller] Loaded
2019-05-06T17:57:50.720Z,1557165470.720 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-06T17:57:50.725Z,1557165470.725 [DropWeight] Loaded
2019-05-06T17:57:50.725Z,1557165470.725 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-06T17:57:50.781Z,1557165470.781 [DUSBL_Hydroid] Loaded
2019-05-06T17:57:50.782Z,1557165470.782 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-06T17:57:50.821Z,1557165470.821 [Micromodem] Loaded
2019-05-06T17:57:50.821Z,1557165470.821 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-06T17:57:50.919Z,1557165470.919 [NAL9602] Loaded
2019-05-06T17:57:50.919Z,1557165470.919 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-06T17:57:50.935Z,1557165470.935 [Onboard] Loaded
2019-05-06T17:57:50.935Z,1557165470.935 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-06T17:57:50.941Z,1557165470.941 [PowerOnly] Loaded
2019-05-06T17:57:50.941Z,1557165470.941 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-06T17:57:50.948Z,1557165470.948 [Radio_Surface] Loaded
2019-05-06T17:57:50.948Z,1557165470.948 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-06T17:57:50.949Z,1557165470.949 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-06T17:57:50.949Z,1557165470.949 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3298
2019-05-06T17:57:50.993Z,1557165470.993 [RDI_Pathfinder] Loaded
2019-05-06T17:57:50.993Z,1557165470.993 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-06T17:57:52.853Z,1557165472.853 [BPC1] Loaded
2019-05-06T17:57:52.854Z,1557165472.854 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-06T17:57:52.854Z,1557165472.854 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-06T17:57:52.855Z,1557165472.855 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-06T17:57:52.876Z,1557165472.876 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-06T17:57:52.885Z,1557165472.885 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-06T17:57:53.094Z,1557165473.094 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-06T17:57:53.094Z,1557165473.094 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-06T17:57:53.114Z,1557165473.114 [NavChart] Loaded
2019-05-06T17:57:53.114Z,1557165473.114 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-06T17:57:53.118Z,1557165473.118 [UniversalFixResidualReporter] Loaded
2019-05-06T17:57:53.118Z,1557165473.118 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-06T17:57:53.119Z,1557165473.119 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-06T17:57:53.119Z,1557165473.119 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-06T17:57:53.231Z,1557165473.231 [BuoyancyServo] Loaded
2019-05-06T17:57:53.231Z,1557165473.231 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-06T17:57:53.246Z,1557165473.246 [ElevatorServo] Loaded
2019-05-06T17:57:53.247Z,1557165473.247 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-06T17:57:53.261Z,1557165473.261 [MassServo] Loaded
2019-05-06T17:57:53.262Z,1557165473.262 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-06T17:57:53.276Z,1557165473.276 [RudderServo] Loaded
2019-05-06T17:57:53.277Z,1557165473.277 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-06T17:57:53.291Z,1557165473.291 [ThrusterServo] Loaded
2019-05-06T17:57:53.291Z,1557165473.291 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-06T17:57:53.292Z,1557165473.292 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-06T17:57:53.292Z,1557165473.292 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-06T17:57:53.537Z,1557165473.537 [CTD_NeilBrown] Loaded
2019-05-06T17:57:53.537Z,1557165473.537 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-06T17:57:53.538Z,1557165473.538 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-06T17:57:53.538Z,1557165473.538 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3299
2019-05-06T17:57:53.583Z,1557165473.583 [WetLabsSeaOWL_UV_A] Loaded
2019-05-06T17:57:53.583Z,1557165473.583 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-06T17:57:53.584Z,1557165473.584 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-06T17:57:53.584Z,1557165473.584 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3300
2019-05-06T17:57:53.585Z,1557165473.585 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-06T17:57:53.585Z,1557165473.585 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-06T17:57:53.872Z,1557165473.872 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-06T17:57:53.872Z,1557165473.872 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-06T17:57:53.912Z,1557165473.912 [DepthRateCalculator] Loaded
2019-05-06T17:57:53.912Z,1557165473.912 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-06T17:57:53.918Z,1557165473.918 [PitchRateCalculator] Loaded
2019-05-06T17:57:53.918Z,1557165473.918 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-06T17:57:53.931Z,1557165473.931 [SpeedCalculator] Loaded
2019-05-06T17:57:53.932Z,1557165473.932 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-06T17:57:53.952Z,1557165473.952 [TempGradientCalculator] Loaded
2019-05-06T17:57:53.952Z,1557165473.952 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-06T17:57:53.958Z,1557165473.958 [YawRateCalculator] Loaded
2019-05-06T17:57:53.958Z,1557165473.958 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-06T17:57:53.998Z,1557165473.998 [ElevatorOffsetCalculator] Loaded
2019-05-06T17:57:53.998Z,1557165473.998 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-06T17:57:53.999Z,1557165473.999 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-06T17:57:53.999Z,1557165473.999 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-06T17:57:54.133Z,1557165474.133 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-06T17:57:54.155Z,1557165474.155 [SBIT] Loaded
2019-05-06T17:57:54.155Z,1557165474.155 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-06T17:57:54.156Z,1557165474.156 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-06T17:57:54.167Z,1557165474.167 [IBIT] Loaded
2019-05-06T17:57:54.167Z,1557165474.167 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-06T17:57:54.170Z,1557165474.170 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-06T17:57:54.307Z,1557165474.307 [CBIT] Loaded
2019-05-06T17:57:54.307Z,1557165474.307 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-06T17:57:54.308Z,1557165474.308 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-06T17:57:54.308Z,1557165474.308 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-06T17:57:54.378Z,1557165474.378 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-06T17:57:54.378Z,1557165474.378 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-06T17:57:54.475Z,1557165474.475 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-06T17:57:54.476Z,1557165474.476 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-06T17:57:54.542Z,1557165474.542 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-06T17:57:54.625Z,1557165474.625 [VerticalControl] Loaded
2019-05-06T17:57:54.626Z,1557165474.626 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-06T17:57:54.626Z,1557165474.626 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-06T17:57:54.684Z,1557165474.684 [HorizontalControl] Loaded
2019-05-06T17:57:54.684Z,1557165474.684 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-06T17:57:54.684Z,1557165474.684 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-06T17:57:54.686Z,1557165474.686 [SpeedControl] Loaded
2019-05-06T17:57:54.687Z,1557165474.687 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-06T17:57:54.687Z,1557165474.687 [LoopControl](DEBUG): Construct LoopControl.
2019-05-06T17:57:54.688Z,1557165474.688 [LoopControl] Loaded
2019-05-06T17:57:54.688Z,1557165474.688 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-06T17:57:54.688Z,1557165474.688 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-06T17:57:54.689Z,1557165474.689 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-06T17:57:54.715Z,1557165474.715 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-06T17:57:54.719Z,1557165474.719 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-06T17:57:54.720Z,1557165474.720 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-06T17:57:54.727Z,1557165474.727 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-06T17:57:54.728Z,1557165474.728 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2019-05-06T17:57:54.728Z,1557165474.728 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3301
2019-05-06T17:57:54.732Z,1557165474.732 [Supervisor](INFO): Main Thread ID is 2877
2019-05-06T17:57:54.733Z,1557165474.733 [Supervisor](DEBUG): Running supervisor.
2019-05-06T17:57:54.733Z,1557165474.733 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3302
2019-05-06T17:57:54.736Z,1557165474.736 [controlThread ThreadHandler](INFO): Handler Thread ID is 3303
2019-05-06T17:57:54.736Z,1557165474.736 [controlThread](DEBUG): Initializing ControlThread
2019-05-06T17:57:54.744Z,1557165474.744 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-06T17:57:54.744Z,1557165474.744 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-06T17:57:54.746Z,1557165474.746 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-06T17:57:54.746Z,1557165474.746 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-06T17:57:54.746Z,1557165474.746 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-06T17:57:54.746Z,1557165474.746 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-06T17:57:54.747Z,1557165474.747 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-06T17:57:54.747Z,1557165474.747 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-06T17:57:54.748Z,1557165474.748 [SBIT](INFO): Initialize SBIT Component.
2019-05-06T17:57:54.748Z,1557165474.748 [SBIT](IMPORTANT): git: 2019-04-10-23-g672f59b
2019-05-06T17:57:54.748Z,1557165474.748 [SBIT](INFO): git hash: 672f59b3bb9ba34f4915fd4dcb9119316785292f
2019-05-06T17:57:54.749Z,1557165474.749 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-06T17:57:54.750Z,1557165474.750 [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-06T17:57:54.751Z,1557165474.751 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-05-06T17:57:54.752Z,1557165474.752 [IBIT](INFO): Initialize IBIT Component.
2019-05-06T17:57:54.752Z,1557165474.752 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-06T17:57:54.754Z,1557165474.754 [logger ThreadHandler](INFO): Handler Thread ID is 3304
2019-05-06T17:57:54.765Z,1557165474.765 [CBIT](DEBUG): Initialized mux pins.
2019-05-06T17:57:54.765Z,1557165474.765 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-06T17:57:54.773Z,1557165474.773 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3305
2019-05-06T17:57:54.774Z,1557165474.774 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-06T17:57:54.785Z,1557165474.785 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3306
2019-05-06T17:57:54.789Z,1557165474.789 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-06T17:57:54.789Z,1557165474.789 [CBIT](DEBUG): Initializing heartbeat.
2019-05-06T17:57:54.805Z,1557165474.805 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3307
2019-05-06T17:57:54.806Z,1557165474.806 [CTD_NeilBrown](INFO): Powering down
2019-05-06T17:57:54.841Z,1557165474.841 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3308
2019-05-06T17:57:54.842Z,1557165474.842 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-06T17:57:54.861Z,1557165474.861 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-06T17:57:54.861Z,1557165474.861 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-06T17:57:54.862Z,1557165474.862 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3309
2019-05-06T17:57:54.865Z,1557165474.865 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-06T17:57:54.865Z,1557165474.865 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-06T17:57:54.865Z,1557165474.865 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-06T17:57:54.865Z,1557165474.865 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-06T17:57:54.866Z,1557165474.866 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-06T17:57:54.866Z,1557165474.866 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-06T17:57:54.866Z,1557165474.866 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-06T17:57:54.866Z,1557165474.866 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-06T17:57:54.866Z,1557165474.866 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-06T17:57:54.867Z,1557165474.867 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-06T17:57:54.867Z,1557165474.867 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-06T17:57:54.867Z,1557165474.867 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-06T17:57:54.867Z,1557165474.867 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-06T17:57:54.867Z,1557165474.867 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-06T17:57:54.868Z,1557165474.868 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-06T17:57:54.868Z,1557165474.868 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-06T17:57:54.897Z,1557165474.897 [CBIT](DEBUG): Backplane powered.
2019-05-06T17:57:54.897Z,1557165474.897 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-06T17:57:54.899Z,1557165474.899 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-06T17:57:54.900Z,1557165474.900 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-06T17:57:54.900Z,1557165474.900 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-06T17:57:54.901Z,1557165474.901 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-06T17:57:54.910Z,1557165474.910 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-06T17:57:54.941Z,1557165474.941 [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-06T17:57:54.942Z,1557165474.942 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-06T17:57:55.013Z,1557165475.013 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-06T17:57:55.014Z,1557165475.014 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-06T17:57:55.016Z,1557165475.016 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-06T17:57:55.054Z,1557165475.054 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-06T17:57:55.056Z,1557165475.056 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-06T17:57:55.078Z,1557165475.078 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-06T17:57:55.092Z,1557165475.092 [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-06T17:57:55.097Z,1557165475.097 [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-06T17:57:55.118Z,1557165475.118 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-06T17:57:55.158Z,1557165475.158 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-06T17:57:55.159Z,1557165475.159 [DUSBL_Hydroid](INFO): Powering up
2019-05-06T17:57:55.159Z,1557165475.159 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-06T17:57:55.190Z,1557165475.190 [Radio_Surface](INFO): Powering up
2019-05-06T17:57:55.233Z,1557165475.233 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-06T17:57:55.259Z,1557165475.259 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-06T17:57:55.269Z,1557165475.269 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-06T17:57:55.270Z,1557165475.270 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-06T17:57:55.277Z,1557165475.277 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-06T17:57:55.278Z,1557165475.278 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-06T17:57:55.289Z,1557165475.289 [MassServo](DEBUG): Initializing MassServo.
2019-05-06T17:57:55.290Z,1557165475.290 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-06T17:57:55.297Z,1557165475.297 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-06T17:57:55.298Z,1557165475.298 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-06T17:57:55.305Z,1557165475.305 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-06T17:57:55.523Z,1557165475.523 [Micromodem](INFO): Powering up
2019-05-06T17:57:55.523Z,1557165475.523 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-06T17:57:55.557Z,1557165475.557 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-06T17:57:56.241Z,1557165476.241 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-06T17:57:56.241Z,1557165476.241 [RudderServo](FAULT): Rudder failed to initialize
2019-05-06T17:57:56.241Z,1557165476.241 [RudderServo] Communications Fault, FailCount= 1
2019-05-06T17:57:56.241Z,1557165476.241 [RudderServo](ERROR): Communications Fault
2019-05-06T17:57:56.353Z,1557165476.353 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-06T17:57:56.526Z,1557165476.526 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-06T17:57:56.526Z,1557165476.526 [RudderServo](INFO): Powering down
2019-05-06T17:57:57.197Z,1557165477.197 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-06T17:57:57.318Z,1557165477.318 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-06T17:57:57.322Z,1557165477.322 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-06T17:57:57.322Z,1557165477.322 [RudderServo] No Fault, FailCount= 1
2019-05-06T17:58:08.556Z,1557165488.556 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-06T17:58:12.978Z,1557165492.978 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-06T17:58:21.056Z,1557165501.056 [NAL9602](INFO): Powering up NAL9602
2019-05-06T17:58:25.091Z,1557165505.091 [Micromodem](ERROR): Response from modem unexpected: $CADQF,195,1*5D

2019-05-06T17:58:25.502Z,1557165505.502 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-06T17:58:25.904Z,1557165505.904 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190506175822.933204,05,665,16,0129,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,195,0.00,-999,9760,4000*5B

2019-05-06T17:58:30.771Z,1557165510.771 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,   +14,   -38,    +8,A
2019-05-06T17:58:31.967Z,1557165511.967 [NAL9602](INFO): NAL9602 initialized
2019-05-06T17:58:32.781Z,1557165512.781 [NAL9602](DEBUG): Fix Requested
2019-05-06T17:58:39.267Z,1557165519.267 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-06T17:58:39.276Z,1557165519.276 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-06T17:58:50.446Z,1557165530.446 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.021902
CHAN A1 (24V): -0.026606
CHAN A2 (12V): -0.006773
CHAN A3 (5V): -0.001980
CHAN B0 (3.3V): 0.000193
CHAN B1 (3.15aV): -0.000014
CHAN B2 (3.15bV): -0.000076
CHAN B3 (GND): 0.001824
OPEN: 0.006466
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-06T17:59:23.762Z,1557165563.762 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-06T17:59:23.762Z,1557165563.762 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-06T17:59:32.684Z,1557165572.684 [SBIT](IMPORTANT): SBIT PASSED
2019-05-06T17:59:32.726Z,1557165572.726 [CommandLine](IMPORTANT): got command configSet list
2019-05-06T17:59:32.727Z,1557165572.727 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=10 count;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-06T17:59:32.728Z,1557165572.728 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-06T17:59:32.729Z,1557165572.729 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-06T17:59:32.729Z,1557165572.729 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-06T17:59:32.729Z,1557165572.729 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-06T17:59:32.729Z,1557165572.729 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-05-06T17:59:33.067Z,1557165573.067 [MissionManager](IMPORTANT): Started mission Startup
2019-05-06T17:59:33.067Z,1557165573.067 [Startup] Running Loop=1
2019-05-06T17:59:33.067Z,1557165573.067 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-06T17:59:33.067Z,1557165573.067 [Startup:A.GoToSurface] Running Loop=1
2019-05-06T17:59:33.067Z,1557165573.067 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-06T17:59:33.068Z,1557165573.068 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-06T17:59:33.068Z,1557165573.068 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-06T17:59:33.068Z,1557165573.068 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-06T17:59:33.069Z,1557165573.069 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-06T17:59:33.070Z,1557165573.070 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-06T17:59:33.071Z,1557165573.071 [Startup:StartupSatComms] Running Loop=1
2019-05-06T17:59:33.071Z,1557165573.071 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-06T17:59:33.071Z,1557165573.071 [Startup:StartupSatComms:A] Running Loop=1
2019-05-06T17:59:33.471Z,1557165573.471 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-06T18:00:20.951Z,1557165620.951 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004932
2019-05-06T18:00:27.177Z,1557165627.177 [NAL9602](INFO): SBD MO Status=2, MOMSN=3807, MT Status=2, MTMSN=0
2019-05-06T18:00:27.177Z,1557165627.177 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T18:00:33.254Z,1557165633.254 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-06T17:59:33.1Z
2019-05-06T18:00:33.254Z,1557165633.254 [Startup:StartupSatComms:A] Stopped
2019-05-06T18:00:33.254Z,1557165633.254 [Startup:StartupSatComms:B] Running Loop=1
2019-05-06T18:00:33.663Z,1557165633.663 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-06T18:00:38.981Z,1557165638.981 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20190506T174744/Courier0007.lzma
2019-05-06T18:00:39.786Z,1557165639.786 [DataOverHttps](INFO): Moved sent file to Logs/20190506T174744/Courier0007.lzma.bak
2019-05-06T18:00:39.787Z,1557165639.787 [DataOverHttps](INFO): SBD MOMSN=10942609
2019-05-06T18:00:50.989Z,1557165650.989 [DataOverHttps](INFO): Sending 427 bytes from file Logs/20190506T174744/Express0008.lzma
2019-05-06T18:00:51.794Z,1557165651.794 [DataOverHttps](INFO): Moved sent file to Logs/20190506T174744/Express0008.lzma.bak
2019-05-06T18:00:51.795Z,1557165651.795 [DataOverHttps](INFO): SBD MOMSN=10942611
2019-05-06T18:00:55.069Z,1557165655.069 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-06T18:00:55.069Z,1557165655.069 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-06T18:00:55.084Z,1557165655.084 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-06T18:00:55.513Z,1557165655.513 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-06T18:00:55.513Z,1557165655.513 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-06T18:01:04.143Z,1557165664.143 [DataOverHttps](INFO): Sending 1340 bytes from file Logs/20190506T175744/Express0001.lzma
2019-05-06T18:01:04.947Z,1557165664.947 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0001.lzma.bak
2019-05-06T18:01:04.947Z,1557165664.947 [DataOverHttps](INFO): SBD MOMSN=10942615
2019-05-06T18:01:06.022Z,1557165666.022 [Startup:StartupSatComms:B] Stopped
2019-05-06T18:01:06.022Z,1557165666.022 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-06T18:01:06.022Z,1557165666.022 [Startup:StartupSatComms] Stopped
2019-05-06T18:01:06.022Z,1557165666.022 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-06T18:01:06.023Z,1557165666.023 [Startup](INFO): Completed Startup
2019-05-06T18:01:06.023Z,1557165666.023 [MissionManager](INFO): Startup is completed.
2019-05-06T18:01:06.023Z,1557165666.023 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-06T18:01:06.023Z,1557165666.023 [Startup] Stopped
2019-05-06T18:01:06.023Z,1557165666.023 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-06T18:01:06.023Z,1557165666.023 [Startup:A.GoToSurface] Stopped
2019-05-06T18:01:06.023Z,1557165666.023 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-06T18:01:06.442Z,1557165666.442 [MissionManager](IMPORTANT): Started mission Default
2019-05-06T18:01:06.443Z,1557165666.443 [Default] Running Loop=1
2019-05-06T18:01:06.443Z,1557165666.443 [Default](DEBUG): Aggregate::initialize Default
2019-05-06T18:01:06.443Z,1557165666.443 [Default:B.GoToSurface] Running Loop=1
2019-05-06T18:01:06.443Z,1557165666.443 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-06T18:01:06.443Z,1557165666.443 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-06T18:01:06.444Z,1557165666.444 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-06T18:01:06.444Z,1557165666.444 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-06T18:01:06.444Z,1557165666.444 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-06T18:01:06.444Z,1557165666.444 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-06T18:01:06.449Z,1557165666.449 [Default:A.Wait] Running Loop=1
2019-05-06T18:01:06.449Z,1557165666.449 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:01:19.757Z,1557165679.757 [Default:A.Wait](INFO): Done Waiting.
2019-05-06T18:01:19.758Z,1557165679.758 [Default:A.Wait] Stopped
2019-05-06T18:01:19.758Z,1557165679.758 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:01:20.146Z,1557165680.146 [Default:CheckIn] Running Loop=1
2019-05-06T18:01:20.146Z,1557165680.146 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:01:20.146Z,1557165680.146 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:01:20.551Z,1557165680.551 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-06T18:03:02.761Z,1557165782.761 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,   -22,   +12,    +6,A
2019-05-06T18:03:35.455Z,1557165815.455 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T18:03:36.281Z,1557165816.281 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:03:36.668Z,1557165816.668 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180304.00,A,3648.16147,N,12147.28280,W,0.194,17.64,060519,,,A*4C
2019-05-06T18:03:36.672Z,1557165816.672 [NAL9602](INFO): GPS fix at 20190506T180304: (36.802691, -121.788047)
2019-05-06T18:03:36.740Z,1557165816.740 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:03:36.740Z,1557165816.740 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:03:37.132Z,1557165817.132 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-06T18:03:41.624Z,1557165821.624 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190506T175744/Courier0004.lzma
2019-05-06T18:03:42.074Z,1557165822.074 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0004.lzma.bak
2019-05-06T18:03:42.075Z,1557165822.075 [DataOverHttps](INFO): SBD MOMSN=10942642
2019-05-06T18:03:55.470Z,1557165835.470 [DataOverHttps](INFO): Sending 692 bytes from file Logs/20190506T175744/Express0005.lzma
2019-05-06T18:03:56.274Z,1557165836.274 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0005.lzma.bak
2019-05-06T18:03:56.275Z,1557165836.275 [DataOverHttps](INFO): SBD MOMSN=10942645
2019-05-06T18:03:57.072Z,1557165837.072 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:03:57.072Z,1557165837.072 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:03:57.072Z,1557165837.072 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:04:08.775Z,1557165848.775 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:04:21.647Z,1557165861.647 [CommandLine](IMPORTANT): got command show variable range
2019-05-06T18:04:21.650Z,1557165861.650 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-05-06T18:04:21.848Z,1557165861.848 [CommandLine](IMPORTANT): BR_Ping1D.minrange (meter)
2019-05-06T18:04:21.862Z,1557165861.862 [CommandLine](IMPORTANT): BR_Ping1D.maxrange (meter)
2019-05-06T18:04:21.945Z,1557165861.945 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-05-06T18:04:21.946Z,1557165861.946 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-05-06T18:04:21.947Z,1557165861.947 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-05-06T18:04:21.950Z,1557165861.950 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-05-06T18:04:21.950Z,1557165861.950 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-05-06T18:04:21.951Z,1557165861.951 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-05-06T18:04:21.951Z,1557165861.951 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-05-06T18:04:30.394Z,1557165870.394 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-05-06T18:04:34.430Z,1557165874.430 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-05-06T18:04:34.430Z,1557165874.430 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-05-06T18:04:34.456Z,1557165874.456 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-05-06T18:04:34.492Z,1557165874.492 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-05-06T18:04:34.496Z,1557165874.496 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-05-06T18:04:34.499Z,1557165874.499 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-05-06T18:04:34.527Z,1557165874.527 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-05-06T18:04:34.528Z,1557165874.528 [DUSBL:A.Pitch](DEBUG): Construct.
2019-05-06T18:04:34.562Z,1557165874.562 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-05-06T18:04:34.591Z,1557165874.591 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-05-06T18:04:34.632Z,1557165874.632 [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-06T18:04:34.651Z,1557165874.651 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-05-06T18:04:34.706Z,1557165874.706 [Default] Stopped
2019-05-06T18:04:34.706Z,1557165874.706 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-06T18:04:34.706Z,1557165874.706 [Default:B.GoToSurface] Stopped
2019-05-06T18:04:34.706Z,1557165874.706 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-06T18:04:34.706Z,1557165874.706 [Default:CheckIn] Stopped
2019-05-06T18:04:34.706Z,1557165874.706 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:04:34.707Z,1557165874.707 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:04:34.707Z,1557165874.707 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:04:34.707Z,1557165874.707 [MissionManager](IMPORTANT): Started mission DUSBL
2019-05-06T18:04:34.707Z,1557165874.707 [DUSBL] Running Loop=1
2019-05-06T18:04:34.707Z,1557165874.707 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-05-06T18:04:34.707Z,1557165874.707 [DUSBL:A.Pitch] Running Loop=1
2019-05-06T18:04:34.707Z,1557165874.707 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:C] Running Loop=1
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:RequestRepeater] Running Loop=1
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:04:34.708Z,1557165874.708 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:04:34.717Z,1557165874.717 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:04:34.717Z,1557165874.717 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:04:34.718Z,1557165874.718 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-05-06T18:04:34.719Z,1557165874.719 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-05-06T18:04:34.719Z,1557165874.719 [DUSBL:B.SetSpeed] Running Loop=1
2019-05-06T18:04:34.719Z,1557165874.719 [DUSBL:A.Pitch] Running Loop=1
2019-05-06T18:04:36.230Z,1557165876.230 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:04:36.230Z,1557165876.230 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:04:36.231Z,1557165876.231 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:04:36.232Z,1557165876.232 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:36.642Z,1557165876.642 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:36.642Z,1557165876.642 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:04:36.642Z,1557165876.642 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:04:36.643Z,1557165876.643 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:04:37.072Z,1557165877.072 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:37.442Z,1557165877.442 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:37.850Z,1557165877.850 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:37.850Z,1557165877.850 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:04:37.851Z,1557165877.851 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:04:38.258Z,1557165878.258 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:38.654Z,1557165878.654 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:39.058Z,1557165879.058 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:39.462Z,1557165879.462 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:39.870Z,1557165879.870 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:40.270Z,1557165880.270 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:40.674Z,1557165880.674 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:41.082Z,1557165881.082 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:41.497Z,1557165881.497 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.265899
2019-05-06T18:04:41.497Z,1557165881.497 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:04:41.497Z,1557165881.497 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:04:41.498Z,1557165881.498 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:04:41.499Z,1557165881.499 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:41.890Z,1557165881.890 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:41.890Z,1557165881.890 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:04:41.891Z,1557165881.891 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:04:41.891Z,1557165881.891 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:04:42.294Z,1557165882.294 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:42.698Z,1557165882.698 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:42.698Z,1557165882.698 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:04:42.698Z,1557165882.698 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:04:43.098Z,1557165883.098 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:43.512Z,1557165883.512 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:43.906Z,1557165883.906 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:44.314Z,1557165884.314 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:44.718Z,1557165884.718 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:44.775Z,1557165884.775 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:04:44.775Z,1557165884.775 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:04:44.775Z,1557165884.775 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:04:44.776Z,1557165884.776 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:04:44.776Z,1557165884.776 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:04:44.776Z,1557165884.776 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:04:44.776Z,1557165884.776 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:04:44.776Z,1557165884.776 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:04:44.776Z,1557165884.776 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-05-06T18:04:44.776Z,1557165884.776 [DUSBL:RequestRepeater] Running Loop=2
2019-05-06T18:04:44.777Z,1557165884.777 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:04:44.781Z,1557165884.781 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:04:44.781Z,1557165884.781 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:04:44.781Z,1557165884.781 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:04:44.781Z,1557165884.781 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:04:45.122Z,1557165885.122 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:45.520Z,1557165885.520 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:45.942Z,1557165885.942 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:46.336Z,1557165886.336 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:46.757Z,1557165886.757 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.258965
2019-05-06T18:04:46.757Z,1557165886.757 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:04:46.757Z,1557165886.757 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:04:46.758Z,1557165886.758 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:04:46.760Z,1557165886.760 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:47.146Z,1557165887.146 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:47.146Z,1557165887.146 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:04:47.146Z,1557165887.146 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:04:47.148Z,1557165887.148 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:04:47.550Z,1557165887.550 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:47.556Z,1557165887.556 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190506180445.246264,06,157,15,0103,0150,246,00,00,01,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,201,0.00,-999,9760,4000*53

2019-05-06T18:04:47.954Z,1557165887.954 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:47.954Z,1557165887.954 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:04:47.955Z,1557165887.955 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:04:48.356Z,1557165888.356 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:48.758Z,1557165888.758 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:49.158Z,1557165889.158 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:49.566Z,1557165889.566 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:49.974Z,1557165889.974 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:50.392Z,1557165890.392 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:50.778Z,1557165890.778 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:51.182Z,1557165891.182 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:51.586Z,1557165891.586 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:51.997Z,1557165891.997 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.238986
2019-05-06T18:04:51.997Z,1557165891.997 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:04:51.997Z,1557165891.997 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:04:51.998Z,1557165891.998 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:04:51.999Z,1557165891.999 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:52.397Z,1557165892.397 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:52.397Z,1557165892.397 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:04:52.397Z,1557165892.397 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:04:52.398Z,1557165892.398 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:04:52.798Z,1557165892.798 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:53.205Z,1557165893.205 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:53.205Z,1557165893.205 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:04:53.205Z,1557165893.205 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:04:53.602Z,1557165893.602 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:54.010Z,1557165894.010 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:54.414Z,1557165894.414 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:54.818Z,1557165894.818 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:55.222Z,1557165895.222 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:55.246Z,1557165895.246 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:04:55.246Z,1557165895.246 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:04:55.246Z,1557165895.246 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater] Running Loop=3
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:04:55.247Z,1557165895.247 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:04:55.248Z,1557165895.248 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:04:55.248Z,1557165895.248 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:04:55.248Z,1557165895.248 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:04:55.622Z,1557165895.622 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:56.030Z,1557165896.030 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:56.438Z,1557165896.438 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:56.838Z,1557165896.838 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:57.253Z,1557165897.253 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.254923
2019-05-06T18:04:57.253Z,1557165897.253 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:04:57.253Z,1557165897.253 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:04:57.254Z,1557165897.254 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:04:57.255Z,1557165897.255 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:57.646Z,1557165897.646 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:57.646Z,1557165897.646 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:04:57.647Z,1557165897.647 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:04:57.647Z,1557165897.647 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:04:58.047Z,1557165898.047 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:58.454Z,1557165898.454 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:58.454Z,1557165898.454 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:04:58.454Z,1557165898.454 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:04:58.852Z,1557165898.852 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:59.262Z,1557165899.262 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:04:59.662Z,1557165899.662 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:00.070Z,1557165900.070 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:00.470Z,1557165900.470 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:00.878Z,1557165900.878 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:01.276Z,1557165901.276 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:01.686Z,1557165901.686 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:02.084Z,1557165902.084 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:02.505Z,1557165902.505 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.250953
2019-05-06T18:05:02.505Z,1557165902.505 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:02.505Z,1557165902.505 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:02.506Z,1557165902.506 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:02.508Z,1557165902.508 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:02.894Z,1557165902.894 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:02.894Z,1557165902.894 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:02.895Z,1557165902.895 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:02.895Z,1557165902.895 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:03.306Z,1557165903.306 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:03.702Z,1557165903.702 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:03.703Z,1557165903.703 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:03.703Z,1557165903.703 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:04.106Z,1557165904.106 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:04.514Z,1557165904.514 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:04.918Z,1557165904.918 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:05.318Z,1557165905.318 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:05.726Z,1557165905.726 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:05.847Z,1557165905.847 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:05:05.847Z,1557165905.847 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:05:05.847Z,1557165905.847 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:05:05.847Z,1557165905.847 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater] Running Loop=4
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:05:05.848Z,1557165905.848 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:05:06.126Z,1557165906.126 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:06.538Z,1557165906.538 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:06.934Z,1557165906.934 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:07.349Z,1557165907.349 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:07.757Z,1557165907.757 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.250947
2019-05-06T18:05:07.757Z,1557165907.757 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:07.757Z,1557165907.757 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:07.758Z,1557165907.758 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:07.759Z,1557165907.759 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:08.146Z,1557165908.146 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:08.146Z,1557165908.146 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:08.146Z,1557165908.146 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:08.149Z,1557165908.149 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:08.550Z,1557165908.550 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:08.552Z,1557165908.552 [Micromodem](ERROR): Response from modem unexpected: $CADQF,202,1*50

2019-05-06T18:05:08.553Z,1557165908.553 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-06T18:05:08.954Z,1557165908.954 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:08.954Z,1557165908.954 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:08.954Z,1557165908.954 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:08.975Z,1557165908.975 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190506180506.602672,06,416,14,0099,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,202,-0.10,-999,9760,4000*7E

2019-05-06T18:05:09.393Z,1557165909.393 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:09.762Z,1557165909.762 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:10.170Z,1557165910.170 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:10.570Z,1557165910.570 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:10.974Z,1557165910.974 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:11.401Z,1557165911.401 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:11.782Z,1557165911.782 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:12.186Z,1557165912.186 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:12.594Z,1557165912.594 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:13.005Z,1557165913.005 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.246972
2019-05-06T18:05:13.005Z,1557165913.005 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:13.005Z,1557165913.005 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:13.006Z,1557165913.006 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:13.007Z,1557165913.007 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:13.406Z,1557165913.406 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:13.406Z,1557165913.406 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:13.407Z,1557165913.407 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:13.407Z,1557165913.407 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:13.802Z,1557165913.802 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:14.210Z,1557165914.210 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:14.210Z,1557165914.210 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:14.210Z,1557165914.210 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:14.614Z,1557165914.614 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:15.018Z,1557165915.018 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:15.422Z,1557165915.422 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:15.823Z,1557165915.823 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:16.230Z,1557165916.230 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:16.254Z,1557165916.254 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:05:16.254Z,1557165916.254 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:05:16.254Z,1557165916.254 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:05:16.255Z,1557165916.255 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:05:16.255Z,1557165916.255 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:05:16.255Z,1557165916.255 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:05:16.255Z,1557165916.255 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:05:16.255Z,1557165916.255 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:05:16.255Z,1557165916.255 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-05-06T18:05:16.256Z,1557165916.256 [DUSBL:RequestRepeater] Running Loop=5
2019-05-06T18:05:16.256Z,1557165916.256 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:05:16.256Z,1557165916.256 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:05:16.256Z,1557165916.256 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:05:16.256Z,1557165916.256 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:05:16.256Z,1557165916.256 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:05:16.630Z,1557165916.630 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:17.038Z,1557165917.038 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:17.442Z,1557165917.442 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:17.846Z,1557165917.846 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:18.257Z,1557165918.257 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.250852
2019-05-06T18:05:18.257Z,1557165918.257 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:18.257Z,1557165918.257 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:18.258Z,1557165918.258 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:18.260Z,1557165918.260 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:18.659Z,1557165918.659 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:18.659Z,1557165918.659 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:18.659Z,1557165918.659 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:18.661Z,1557165918.661 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:19.058Z,1557165919.058 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:19.059Z,1557165919.059 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-06T18:05:19.066Z,1557165919.066 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190506180517.176941,06,451,14,0090,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,191,0.00,-999,9760,4000*5A

2019-05-06T18:05:19.462Z,1557165919.462 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:19.462Z,1557165919.462 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:19.463Z,1557165919.463 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:19.479Z,1557165919.479 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CARV,80518,COPROC,0.10.0.6*45

2019-05-06T18:05:19.514Z,1557165919.514 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-06T18:05:19.517Z,1557165919.517 [BPC1](INFO): Received data from all battery sticks.
2019-05-06T18:05:19.878Z,1557165919.878 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:20.274Z,1557165920.274 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:20.690Z,1557165920.690 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:21.071Z,1557165921.071 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:21.478Z,1557165921.478 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:21.898Z,1557165921.898 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:22.289Z,1557165922.289 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:22.698Z,1557165922.698 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:23.098Z,1557165923.098 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:23.517Z,1557165923.517 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.258942
2019-05-06T18:05:23.517Z,1557165923.517 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:23.517Z,1557165923.517 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:23.518Z,1557165923.518 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:23.519Z,1557165923.519 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:23.902Z,1557165923.902 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:23.902Z,1557165923.902 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:23.902Z,1557165923.902 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:23.903Z,1557165923.903 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:24.310Z,1557165924.310 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:24.714Z,1557165924.714 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:24.714Z,1557165924.714 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:24.714Z,1557165924.714 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:25.118Z,1557165925.118 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:25.522Z,1557165925.522 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:25.926Z,1557165925.926 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:26.326Z,1557165926.326 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:26.734Z,1557165926.734 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:26.771Z,1557165926.771 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:05:26.771Z,1557165926.771 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:05:26.771Z,1557165926.771 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:05:26.772Z,1557165926.772 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:05:26.772Z,1557165926.772 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:05:26.772Z,1557165926.772 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:05:26.772Z,1557165926.772 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:05:26.772Z,1557165926.772 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:05:26.772Z,1557165926.772 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-05-06T18:05:26.772Z,1557165926.772 [DUSBL:RequestRepeater] Running Loop=6
2019-05-06T18:05:26.773Z,1557165926.773 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:05:26.773Z,1557165926.773 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:05:26.773Z,1557165926.773 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:05:26.773Z,1557165926.773 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:05:26.773Z,1557165926.773 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:05:27.141Z,1557165927.141 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:27.538Z,1557165927.538 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:27.946Z,1557165927.946 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:28.356Z,1557165928.356 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:28.765Z,1557165928.765 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.246981
2019-05-06T18:05:28.765Z,1557165928.765 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:28.765Z,1557165928.765 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:28.766Z,1557165928.766 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:28.767Z,1557165928.767 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:29.158Z,1557165929.158 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:29.158Z,1557165929.158 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:29.158Z,1557165929.158 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:29.159Z,1557165929.159 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:29.562Z,1557165929.562 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:29.966Z,1557165929.966 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:29.966Z,1557165929.966 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:29.966Z,1557165929.966 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:30.391Z,1557165930.391 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:30.770Z,1557165930.770 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:31.178Z,1557165931.178 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:31.582Z,1557165931.582 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:31.986Z,1557165931.986 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:32.395Z,1557165932.395 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:32.790Z,1557165932.790 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:33.194Z,1557165933.194 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:33.598Z,1557165933.598 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:34.017Z,1557165934.017 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.251367
2019-05-06T18:05:34.018Z,1557165934.018 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:34.018Z,1557165934.018 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:34.018Z,1557165934.018 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:34.019Z,1557165934.019 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:34.406Z,1557165934.406 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:34.406Z,1557165934.406 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:34.406Z,1557165934.406 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:34.411Z,1557165934.411 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:34.810Z,1557165934.810 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:35.214Z,1557165935.214 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:35.214Z,1557165935.214 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:35.214Z,1557165935.214 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:35.618Z,1557165935.618 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:36.022Z,1557165936.022 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:36.426Z,1557165936.426 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:36.830Z,1557165936.830 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:37.234Z,1557165937.234 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:37.268Z,1557165937.268 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:05:37.268Z,1557165937.268 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:05:37.268Z,1557165937.268 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:05:37.273Z,1557165937.273 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:05:37.273Z,1557165937.273 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:05:37.273Z,1557165937.273 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:05:37.273Z,1557165937.273 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:05:37.273Z,1557165937.273 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:05:37.274Z,1557165937.274 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-05-06T18:05:37.274Z,1557165937.274 [DUSBL:RequestRepeater] Running Loop=7
2019-05-06T18:05:37.274Z,1557165937.274 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:05:37.274Z,1557165937.274 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:05:37.274Z,1557165937.274 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:05:37.274Z,1557165937.274 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:05:37.274Z,1557165937.274 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:05:37.647Z,1557165937.647 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:38.049Z,1557165938.049 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:38.450Z,1557165938.450 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:38.854Z,1557165938.854 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:39.265Z,1557165939.265 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.246652
2019-05-06T18:05:39.265Z,1557165939.265 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:39.265Z,1557165939.265 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:39.266Z,1557165939.266 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:39.267Z,1557165939.267 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:39.674Z,1557165939.674 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:39.674Z,1557165939.674 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:39.674Z,1557165939.674 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:39.677Z,1557165939.677 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:40.066Z,1557165940.066 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:40.068Z,1557165940.068 [Micromodem](ERROR): Response from modem unexpected: $CADQF,196,1*5E

2019-05-06T18:05:40.069Z,1557165940.069 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-05-06T18:05:40.466Z,1557165940.466 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:40.466Z,1557165940.466 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:40.467Z,1557165940.467 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:40.487Z,1557165940.487 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190506180538.081325,06,393,13,0090,0150,246,00,00,02,01,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,196,0.05,-999,9760,4000*59

2019-05-06T18:05:40.870Z,1557165940.870 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:41.274Z,1557165941.274 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:41.685Z,1557165941.685 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:42.082Z,1557165942.082 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:42.486Z,1557165942.486 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:42.894Z,1557165942.894 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:43.318Z,1557165943.318 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:43.698Z,1557165943.698 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:44.106Z,1557165944.106 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:44.517Z,1557165944.517 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.250858
2019-05-06T18:05:44.517Z,1557165944.517 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:44.517Z,1557165944.517 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:44.518Z,1557165944.518 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:44.518Z,1557165944.518 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:44.910Z,1557165944.910 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:44.910Z,1557165944.910 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:44.911Z,1557165944.911 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:44.911Z,1557165944.911 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:45.318Z,1557165945.318 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:45.718Z,1557165945.718 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:45.718Z,1557165945.718 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:45.718Z,1557165945.718 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:46.122Z,1557165946.122 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:46.526Z,1557165946.526 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:46.930Z,1557165946.930 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:47.338Z,1557165947.338 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:47.742Z,1557165947.742 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:47.774Z,1557165947.774 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:05:47.774Z,1557165947.774 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:05:47.774Z,1557165947.774 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:05:47.775Z,1557165947.775 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:05:47.775Z,1557165947.775 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:05:47.775Z,1557165947.775 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:05:47.775Z,1557165947.775 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:05:47.775Z,1557165947.775 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:05:47.775Z,1557165947.775 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-05-06T18:05:47.775Z,1557165947.775 [DUSBL:RequestRepeater] Running Loop=8
2019-05-06T18:05:47.776Z,1557165947.776 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:05:47.776Z,1557165947.776 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:05:47.776Z,1557165947.776 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:05:47.776Z,1557165947.776 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:05:47.776Z,1557165947.776 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:05:48.142Z,1557165948.142 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:48.553Z,1557165948.553 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:48.954Z,1557165948.954 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:49.375Z,1557165949.375 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:49.769Z,1557165949.769 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.251251
2019-05-06T18:05:49.769Z,1557165949.769 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:49.769Z,1557165949.769 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:49.770Z,1557165949.770 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:49.772Z,1557165949.772 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:50.166Z,1557165950.166 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:50.166Z,1557165950.166 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:50.166Z,1557165950.166 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:50.167Z,1557165950.167 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:50.570Z,1557165950.570 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:50.970Z,1557165950.970 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:50.970Z,1557165950.970 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:50.971Z,1557165950.971 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:51.391Z,1557165951.391 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:51.786Z,1557165951.786 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:52.182Z,1557165952.182 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:52.586Z,1557165952.586 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:52.990Z,1557165952.990 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:53.402Z,1557165953.402 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:53.802Z,1557165953.802 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:54.202Z,1557165954.202 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:54.606Z,1557165954.606 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:55.021Z,1557165955.021 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.250856
2019-05-06T18:05:55.021Z,1557165955.021 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:05:55.021Z,1557165955.021 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:05:55.022Z,1557165955.022 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:05:55.023Z,1557165955.023 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:55.432Z,1557165955.432 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:55.433Z,1557165955.433 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:05:55.433Z,1557165955.433 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:05:55.434Z,1557165955.434 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:05:55.818Z,1557165955.818 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:56.226Z,1557165956.226 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:56.226Z,1557165956.226 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:05:56.226Z,1557165956.226 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:05:56.624Z,1557165956.624 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:57.046Z,1557165957.046 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:57.439Z,1557165957.439 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:57.844Z,1557165957.844 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:58.257Z,1557165958.257 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:58.280Z,1557165958.280 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:05:58.280Z,1557165958.280 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:05:58.280Z,1557165958.280 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:05:58.281Z,1557165958.281 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:05:58.281Z,1557165958.281 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:05:58.281Z,1557165958.281 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:05:58.281Z,1557165958.281 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:05:58.281Z,1557165958.281 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:05:58.282Z,1557165958.282 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-05-06T18:05:58.282Z,1557165958.282 [DUSBL:RequestRepeater] Running Loop=9
2019-05-06T18:05:58.282Z,1557165958.282 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:05:58.282Z,1557165958.282 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:05:58.282Z,1557165958.282 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:05:58.282Z,1557165958.282 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:05:58.282Z,1557165958.282 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:05:58.654Z,1557165958.654 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:59.054Z,1557165959.054 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:59.452Z,1557165959.452 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:05:59.862Z,1557165959.862 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:00.277Z,1557165960.277 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.255099
2019-05-06T18:06:00.277Z,1557165960.277 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:06:00.277Z,1557165960.277 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:06:00.278Z,1557165960.278 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:06:00.279Z,1557165960.279 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:00.666Z,1557165960.666 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:00.667Z,1557165960.667 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:06:00.667Z,1557165960.667 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:06:00.667Z,1557165960.667 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:06:01.074Z,1557165961.074 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:01.482Z,1557165961.482 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:01.482Z,1557165961.482 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:06:01.482Z,1557165961.482 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:06:01.878Z,1557165961.878 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:02.282Z,1557165962.282 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:02.691Z,1557165962.691 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:03.090Z,1557165963.090 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:03.494Z,1557165963.494 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:03.910Z,1557165963.910 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:04.310Z,1557165964.310 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:04.706Z,1557165964.706 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:05.110Z,1557165965.110 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:05.525Z,1557165965.525 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.247146
2019-05-06T18:06:05.525Z,1557165965.525 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:06:05.525Z,1557165965.525 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:06:05.526Z,1557165965.526 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:06:05.526Z,1557165965.526 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:05.922Z,1557165965.922 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:05.922Z,1557165965.922 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:06:05.922Z,1557165965.922 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:06:05.923Z,1557165965.923 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:06:06.383Z,1557165966.383 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:06.734Z,1557165966.734 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:06.734Z,1557165966.734 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:06:06.735Z,1557165966.735 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:06:07.138Z,1557165967.138 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:07.542Z,1557165967.542 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:07.946Z,1557165967.946 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:08.360Z,1557165968.360 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:08.758Z,1557165968.758 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:08.792Z,1557165968.792 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:06:08.792Z,1557165968.792 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:06:08.792Z,1557165968.792 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:06:08.833Z,1557165968.833 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:06:08.833Z,1557165968.833 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:06:08.833Z,1557165968.833 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:06:08.833Z,1557165968.833 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater] Running Loop=10
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater:A] Running Loop=1
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater:B] Running Loop=1
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-05-06T18:06:08.834Z,1557165968.834 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:06:09.158Z,1557165969.158 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:09.568Z,1557165969.568 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:09.970Z,1557165969.970 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:10.392Z,1557165970.392 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:10.785Z,1557165970.785 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.259285
2019-05-06T18:06:10.785Z,1557165970.785 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:06:10.785Z,1557165970.785 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:06:10.786Z,1557165970.786 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:06:10.787Z,1557165970.787 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:11.178Z,1557165971.178 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:11.178Z,1557165971.178 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:06:11.178Z,1557165971.178 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:06:11.179Z,1557165971.179 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:06:11.582Z,1557165971.582 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:11.986Z,1557165971.986 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:11.986Z,1557165971.986 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:06:11.986Z,1557165971.986 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:06:12.398Z,1557165972.398 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:12.794Z,1557165972.794 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:13.202Z,1557165973.202 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:13.606Z,1557165973.606 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:14.010Z,1557165974.010 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:14.410Z,1557165974.410 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:14.818Z,1557165974.818 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:15.218Z,1557165975.218 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:15.626Z,1557165975.626 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:16.037Z,1557165976.037 [DUSBL_Hydroid](INFO): Setting waiting for range response to false due to timeout. Elapsed:5.250651
2019-05-06T18:06:16.037Z,1557165976.037 [DUSBL_Hydroid](INFO): ****** received transponder code query ******
2019-05-06T18:06:16.037Z,1557165976.037 [DUSBL_Hydroid](INFO): ****** received ping request ******
2019-05-06T18:06:16.038Z,1557165976.038 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-05-06T18:06:16.039Z,1557165976.039 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:16.437Z,1557165976.437 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:16.437Z,1557165976.437 [DUSBL_Hydroid](INFO): Requesting micromodem ping code 2
2019-05-06T18:06:16.438Z,1557165976.438 [DUSBL_Hydroid](INFO): Arming DUSBL
2019-05-06T18:06:16.438Z,1557165976.438 [Micromodem](INFO): **** IS COMMANDED  IN Runnable **** 
2019-05-06T18:06:16.834Z,1557165976.834 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:17.238Z,1557165977.238 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:17.238Z,1557165977.238 [DUSBL_Hydroid](INFO): USBL response received:
2019-05-06T18:06:17.238Z,1557165977.238 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: 
2019-05-06T18:06:17.642Z,1557165977.642 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:18.053Z,1557165978.053 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:18.470Z,1557165978.470 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:18.854Z,1557165978.854 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:19.258Z,1557165979.258 [DUSBL_Hydroid](INFO): In Read and Parse
2019-05-06T18:06:19.284Z,1557165979.284 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-05-06T18:06:19.284Z,1557165979.284 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-05-06T18:06:19.284Z,1557165979.284 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:06:19.285Z,1557165979.285 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-05-06T18:06:19.285Z,1557165979.285 [DUSBL:RequestRepeater] Stopped
2019-05-06T18:06:19.285Z,1557165979.285 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-05-06T18:06:19.285Z,1557165979.285 [DUSBL:RequestRepeater:A] Stopped
2019-05-06T18:06:19.285Z,1557165979.285 [DUSBL:RequestRepeater:B] Stopped
2019-05-06T18:06:19.286Z,1557165979.286 [DUSBL](INFO): Completed DUSBL
2019-05-06T18:06:19.286Z,1557165979.286 [MissionManager](INFO): DUSBL is completed.
2019-05-06T18:06:19.286Z,1557165979.286 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-05-06T18:06:19.286Z,1557165979.286 [DUSBL] Stopped
2019-05-06T18:06:19.286Z,1557165979.286 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-05-06T18:06:19.287Z,1557165979.287 [DUSBL:A.Pitch] Stopped
2019-05-06T18:06:19.287Z,1557165979.287 [DUSBL:B.SetSpeed] Stopped
2019-05-06T18:06:19.287Z,1557165979.287 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-05-06T18:06:19.287Z,1557165979.287 [DUSBL:C] Stopped
2019-05-06T18:06:19.704Z,1557165979.704 [MissionManager](IMPORTANT): Started mission Default
2019-05-06T18:06:19.704Z,1557165979.704 [Default] Running Loop=1
2019-05-06T18:06:19.704Z,1557165979.704 [Default](DEBUG): Aggregate::initialize Default
2019-05-06T18:06:19.704Z,1557165979.704 [Default:B.GoToSurface] Running Loop=1
2019-05-06T18:06:19.704Z,1557165979.704 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-06T18:06:19.709Z,1557165979.709 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-06T18:06:19.709Z,1557165979.709 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-06T18:06:19.709Z,1557165979.709 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-06T18:06:19.710Z,1557165979.710 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-06T18:06:19.710Z,1557165979.710 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-06T18:06:19.710Z,1557165979.710 [Default:A.Wait] Running Loop=1
2019-05-06T18:06:19.710Z,1557165979.710 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:06:33.079Z,1557165993.079 [Default:A.Wait](INFO): Done Waiting.
2019-05-06T18:06:33.079Z,1557165993.079 [Default:A.Wait] Stopped
2019-05-06T18:06:33.079Z,1557165993.079 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:06:33.444Z,1557165993.444 [Default:CheckIn] Running Loop=1
2019-05-06T18:06:33.444Z,1557165993.444 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:06:33.445Z,1557165993.445 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:06:35.025Z,1557165995.025 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:06:35.425Z,1557165995.425 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180603.00,A,3648.16947,N,12147.28034,W,0.136,17.64,060519,,,A*43
2019-05-06T18:06:35.427Z,1557165995.427 [NAL9602](INFO): GPS fix at 20190506T180603: (36.802824, -121.788006)
2019-05-06T18:06:35.459Z,1557165995.459 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:06:35.460Z,1557165995.460 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:06:41.065Z,1557166001.065 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190506T175744/Courier0007.lzma
2019-05-06T18:06:41.870Z,1557166001.870 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0007.lzma.bak
2019-05-06T18:06:41.870Z,1557166001.870 [DataOverHttps](INFO): SBD MOMSN=10942665
2019-05-06T18:06:53.525Z,1557166013.525 [DataOverHttps](INFO): Sending 660 bytes from file Logs/20190506T175744/Express0008.lzma
2019-05-06T18:06:54.332Z,1557166014.332 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0008.lzma.bak
2019-05-06T18:06:54.332Z,1557166014.332 [DataOverHttps](INFO): SBD MOMSN=10942668
2019-05-06T18:06:55.268Z,1557166015.268 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:06:55.268Z,1557166015.268 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:06:55.268Z,1557166015.268 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:07:06.150Z,1557166026.150 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-06T18:07:06.241Z,1557166026.241 [NAL9602](FAULT): received: 
+CSQ:0

OK07, 2, 0, 0, 0

OK
2019-05-06T18:07:06.241Z,1557166026.241 [NAL9602] Data Fault, FailCount= 1
2019-05-06T18:07:06.241Z,1557166026.241 [NAL9602](ERROR): Data Fault
2019-05-06T18:07:06.326Z,1557166026.326 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-06T18:07:06.556Z,1557166026.556 [NAL9602](INFO): Powering down
2019-05-06T18:07:07.429Z,1557166027.429 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-06T18:07:07.429Z,1557166027.429 [NAL9602] No Fault, FailCount= 1
2019-05-06T18:07:36.851Z,1557166056.851 [NAL9602](INFO): Powering up NAL9602
2019-05-06T18:07:47.759Z,1557166067.759 [NAL9602](INFO): NAL9602 initialized
2019-05-06T18:08:18.863Z,1557166098.863 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:10:08.772Z,1557166208.772 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T18:10:08.773Z,1557166208.773 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050611184636,35.0, -0.1,   0.0,14
2019-05-06T18:11:55.858Z,1557166315.858 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:11:55.858Z,1557166315.858 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:11:55.858Z,1557166315.858 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:11:55.858Z,1557166315.858 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:11:56.261Z,1557166316.261 [Default:CheckIn:D] Stopped
2019-05-06T18:11:56.261Z,1557166316.261 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.609282 min 
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn:E] Stopped
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn] Stopped
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn](INFO): Running loop #2
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn] Running Loop=2
2019-05-06T18:11:56.672Z,1557166316.672 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:11:56.673Z,1557166316.673 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:11:58.273Z,1557166318.273 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:11:58.664Z,1557166318.664 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181125.00,A,3648.16586,N,12147.28195,W,0.097,0.00,060519,,,A*74
2019-05-06T18:11:58.667Z,1557166318.667 [NAL9602](INFO): GPS fix at 20190506T181125: (36.802764, -121.788032)
2019-05-06T18:11:58.699Z,1557166318.699 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:11:58.699Z,1557166318.699 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:12:00.394Z,1557166320.394 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T18:12:04.252Z,1557166324.252 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190506T175744/Courier0010.lzma
2019-05-06T18:12:05.058Z,1557166325.058 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0010.lzma.bak
2019-05-06T18:12:05.058Z,1557166325.058 [DataOverHttps](INFO): SBD MOMSN=10942738
2019-05-06T18:12:16.434Z,1557166336.434 [DataOverHttps](INFO): Sending 842 bytes from file Logs/20190506T175744/Express0011.lzma
2019-05-06T18:12:17.239Z,1557166337.239 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0011.lzma.bak
2019-05-06T18:12:17.239Z,1557166337.239 [DataOverHttps](INFO): SBD MOMSN=10942741
2019-05-06T18:12:18.156Z,1557166338.156 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:12:18.156Z,1557166338.156 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:12:18.156Z,1557166338.156 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:12:31.058Z,1557166351.058 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:14:21.388Z,1557166461.388 [RDI_Pathfinder](ERROR): Failed to parse:768,-32768,-32768,V
2019-05-06T18:15:01.391Z,1557166501.391 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-06T18:15:01.391Z,1557166501.391 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-06T18:15:28.517Z,1557166528.517 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-05-06T18:15:28.517Z,1557166528.517 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-05-06T18:15:28.517Z,1557166528.517 [RDI_Pathfinder](ERROR): Communications Fault
2019-05-06T18:15:28.518Z,1557166528.518 [RDI_Pathfinder](ERROR): Failed to parse:
2019-05-06T18:15:28.546Z,1557166528.546 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-05-06T18:15:28.909Z,1557166528.909 [RDI_Pathfinder](INFO): Powering down
2019-05-06T18:15:29.673Z,1557166529.673 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-05-06T18:15:29.673Z,1557166529.673 [RDI_Pathfinder] No Fault, FailCount= 1
2019-05-06T18:15:42.998Z,1557166542.998 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-06T18:17:18.730Z,1557166638.730 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:17:18.730Z,1557166638.730 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:17:18.730Z,1557166638.730 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:17:18.730Z,1557166638.730 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:17:19.144Z,1557166639.144 [Default:CheckIn:D] Stopped
2019-05-06T18:17:19.144Z,1557166639.144 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:17:19.540Z,1557166639.540 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.990662 min 
2019-05-06T18:17:19.540Z,1557166639.540 [Default:CheckIn:E] Stopped
2019-05-06T18:17:19.540Z,1557166639.540 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:17:19.540Z,1557166639.540 [Default:CheckIn] Stopped
2019-05-06T18:17:19.540Z,1557166639.540 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:17:19.540Z,1557166639.540 [Default:CheckIn](INFO): Running loop #3
2019-05-06T18:17:19.541Z,1557166639.541 [Default:CheckIn] Running Loop=3
2019-05-06T18:17:19.541Z,1557166639.541 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:17:19.541Z,1557166639.541 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:17:21.149Z,1557166641.149 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:17:21.537Z,1557166641.537 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181649.00,A,3648.15908,N,12147.28964,W,0.447,358.35,060519,,,A*77
2019-05-06T18:17:21.539Z,1557166641.539 [NAL9602](INFO): GPS fix at 20190506T181649: (36.802651, -121.788161)
2019-05-06T18:17:21.580Z,1557166641.580 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:17:21.580Z,1557166641.580 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:17:27.300Z,1557166647.300 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0013.lzma
2019-05-06T18:17:28.106Z,1557166648.106 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0013.lzma.bak
2019-05-06T18:17:28.107Z,1557166648.107 [DataOverHttps](INFO): SBD MOMSN=10942760
2019-05-06T18:17:40.014Z,1557166660.014 [DataOverHttps](INFO): Sending 941 bytes from file Logs/20190506T175744/Express0014.lzma
2019-05-06T18:17:40.818Z,1557166660.818 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0014.lzma.bak
2019-05-06T18:17:40.819Z,1557166660.819 [DataOverHttps](INFO): SBD MOMSN=10942763
2019-05-06T18:17:41.836Z,1557166661.836 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:17:41.836Z,1557166661.836 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:17:41.836Z,1557166661.836 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:17:55.968Z,1557166675.968 [NAL9602](INFO): SBD MO Status=2, MOMSN=3807, MT Status=2, MTMSN=0
2019-05-06T18:17:55.968Z,1557166675.968 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T18:19:35.337Z,1557166775.337 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T18:19:35.337Z,1557166775.337 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050611281, -0.1,   0.0,1448.9,  0
2019-05-06T18:19:36.979Z,1557166776.979 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,   -20,   +20,   +11,A
2019-05-06T18:19:56.351Z,1557166796.351 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-06T18:19:56.351Z,1557166796.351 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  96.92,  99.42, 103.91
2019-05-06T18:21:35.323Z,1557166895.323 [RDI_Pathfinder](ERROR): Failed to parse:
91
2019-05-06T18:22:23.791Z,1557166943.791 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T18:22:42.397Z,1557166962.397 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:22:42.398Z,1557166962.398 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:22:42.398Z,1557166962.398 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:22:42.398Z,1557166962.398 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:22:42.812Z,1557166962.812 [Default:CheckIn:D] Stopped
2019-05-06T18:22:42.812Z,1557166962.812 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:22:43.219Z,1557166963.219 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.385130 min 
2019-05-06T18:22:43.219Z,1557166963.219 [Default:CheckIn:E] Stopped
2019-05-06T18:22:43.220Z,1557166963.220 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:22:43.220Z,1557166963.220 [Default:CheckIn] Stopped
2019-05-06T18:22:43.220Z,1557166963.220 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:22:43.220Z,1557166963.220 [Default:CheckIn](INFO): Running loop #4
2019-05-06T18:22:43.220Z,1557166963.220 [Default:CheckIn] Running Loop=4
2019-05-06T18:22:43.220Z,1557166963.220 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:22:43.220Z,1557166963.220 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:22:44.813Z,1557166964.813 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:22:45.205Z,1557166965.205 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182213.00,A,3648.16484,N,12147.28800,W,0.117,25.59,060519,,,A*45
2019-05-06T18:22:45.207Z,1557166965.207 [NAL9602](INFO): GPS fix at 20190506T182213: (36.802747, -121.788133)
2019-05-06T18:22:45.239Z,1557166965.239 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:22:45.240Z,1557166965.240 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:22:51.036Z,1557166971.036 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0016.lzma
2019-05-06T18:22:51.842Z,1557166971.842 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0016.lzma.bak
2019-05-06T18:22:51.843Z,1557166971.843 [DataOverHttps](INFO): SBD MOMSN=10942833
2019-05-06T18:23:03.686Z,1557166983.686 [DataOverHttps](INFO): Sending 773 bytes from file Logs/20190506T175744/Express0017.lzma
2019-05-06T18:23:04.490Z,1557166984.490 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0017.lzma.bak
2019-05-06T18:23:04.491Z,1557166984.491 [DataOverHttps](INFO): SBD MOMSN=10942836
2019-05-06T18:23:05.476Z,1557166985.476 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:23:05.476Z,1557166985.476 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:23:05.476Z,1557166985.476 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:23:17.978Z,1557166997.978 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:28:06.084Z,1557167286.084 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:28:06.084Z,1557167286.084 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:28:06.084Z,1557167286.084 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:28:06.084Z,1557167286.084 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:28:06.505Z,1557167286.505 [Default:CheckIn:D] Stopped
2019-05-06T18:28:06.505Z,1557167286.505 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:28:06.880Z,1557167286.880 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.779942 min 
2019-05-06T18:28:06.880Z,1557167286.880 [Default:CheckIn:E] Stopped
2019-05-06T18:28:06.880Z,1557167286.880 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:28:06.880Z,1557167286.880 [Default:CheckIn] Stopped
2019-05-06T18:28:06.880Z,1557167286.880 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:28:06.881Z,1557167286.881 [Default:CheckIn](INFO): Running loop #5
2019-05-06T18:28:06.881Z,1557167286.881 [Default:CheckIn] Running Loop=5
2019-05-06T18:28:06.882Z,1557167286.882 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:28:06.882Z,1557167286.882 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:28:08.485Z,1557167288.485 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:28:08.876Z,1557167288.876 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182736.00,A,3648.16314,N,12147.28124,W,0.389,25.59,060519,,,A*43
2019-05-06T18:28:08.900Z,1557167288.900 [NAL9602](INFO): GPS fix at 20190506T182736: (36.802719, -121.788021)
2019-05-06T18:28:08.949Z,1557167288.949 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:28:08.950Z,1557167288.950 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:28:14.532Z,1557167294.532 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190506T175744/Courier0019.lzma
2019-05-06T18:28:15.338Z,1557167295.338 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0019.lzma.bak
2019-05-06T18:28:15.338Z,1557167295.338 [DataOverHttps](INFO): SBD MOMSN=10942849
2019-05-06T18:28:27.386Z,1557167307.386 [DataOverHttps](INFO): Sending 811 bytes from file Logs/20190506T175744/Express0020.lzma
2019-05-06T18:28:28.190Z,1557167308.190 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0020.lzma.bak
2019-05-06T18:28:28.191Z,1557167308.191 [DataOverHttps](INFO): SBD MOMSN=10942852
2019-05-06T18:28:29.204Z,1557167309.204 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:28:29.204Z,1557167309.204 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:28:29.204Z,1557167309.204 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:28:39.651Z,1557167319.651 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-06T18:28:39.725Z,1557167319.725 [NAL9602](FAULT): received: 
+CSQ:0

OK07, 2, 0, 0, 0

OK
2019-05-06T18:28:39.725Z,1557167319.725 [NAL9602] Data Fault, FailCount= 1
2019-05-06T18:28:39.725Z,1557167319.725 [NAL9602](ERROR): Data Fault
2019-05-06T18:28:39.765Z,1557167319.765 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-06T18:28:40.054Z,1557167320.054 [NAL9602](INFO): Powering down
2019-05-06T18:28:40.894Z,1557167320.894 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-06T18:28:40.894Z,1557167320.894 [NAL9602] No Fault, FailCount= 1
2019-05-06T18:29:10.355Z,1557167350.355 [NAL9602](INFO): Powering up NAL9602
2019-05-06T18:29:21.265Z,1557167361.265 [NAL9602](INFO): NAL9602 initialized
2019-05-06T18:29:52.371Z,1557167392.371 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:30:07.341Z,1557167407.341 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-06T18:30:07.341Z,1557167407.341 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-06T18:33:03.090Z,1557167583.090 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  96.92,  92.93,  99.91,   0.00
2019-05-06T18:33:29.758Z,1557167609.758 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:33:29.758Z,1557167609.758 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:33:29.758Z,1557167609.758 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:33:29.758Z,1557167609.758 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:33:30.182Z,1557167610.182 [Default:CheckIn:D] Stopped
2019-05-06T18:33:30.182Z,1557167610.182 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:33:30.575Z,1557167610.575 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.174638 min 
2019-05-06T18:33:30.575Z,1557167610.575 [Default:CheckIn:E] Stopped
2019-05-06T18:33:30.575Z,1557167610.575 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:33:30.576Z,1557167610.576 [Default:CheckIn] Stopped
2019-05-06T18:33:30.576Z,1557167610.576 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:33:30.576Z,1557167610.576 [Default:CheckIn](INFO): Running loop #6
2019-05-06T18:33:30.576Z,1557167610.576 [Default:CheckIn] Running Loop=6
2019-05-06T18:33:30.576Z,1557167610.576 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:33:30.576Z,1557167610.576 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:33:32.173Z,1557167612.173 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:33:34.579Z,1557167614.579 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T18:33:35.401Z,1557167615.401 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:33:37.821Z,1557167617.821 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:33:41.061Z,1557167621.061 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:33:41.452Z,1557167621.452 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183308.00,A,3648.17067,N,12147.28419,W,0.253,0.00,060519,,,A*7B
2019-05-06T18:33:41.455Z,1557167621.455 [NAL9602](INFO): GPS fix at 20190506T183308: (36.802844, -121.788070)
2019-05-06T18:33:41.479Z,1557167621.479 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:33:41.479Z,1557167621.479 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:33:47.184Z,1557167627.184 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190506T175744/Courier0022.lzma
2019-05-06T18:33:47.977Z,1557167627.977 [RDI_Pathfinder](ERROR): Failed to parse:
:6,   +24,    +5,A
2019-05-06T18:33:47.991Z,1557167627.991 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0022.lzma.bak
2019-05-06T18:33:47.992Z,1557167627.992 [DataOverHttps](INFO): SBD MOMSN=10942926
2019-05-06T18:33:51.174Z,1557167631.174 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-06T18:33:59.915Z,1557167639.915 [DataOverHttps](INFO): Sending 817 bytes from file Logs/20190506T175744/Express0023.lzma
2019-05-06T18:34:00.718Z,1557167640.718 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0023.lzma.bak
2019-05-06T18:34:00.719Z,1557167640.719 [DataOverHttps](INFO): SBD MOMSN=10942929
2019-05-06T18:34:01.668Z,1557167641.668 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:34:01.668Z,1557167641.668 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:34:01.668Z,1557167641.668 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:34:13.761Z,1557167653.761 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:36:47.318Z,1557167807.318 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-06T18:39:02.276Z,1557167942.276 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:39:02.276Z,1557167942.276 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:39:02.276Z,1557167942.276 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:39:02.277Z,1557167942.277 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:39:02.660Z,1557167942.660 [Default:CheckIn:D] Stopped
2019-05-06T18:39:02.660Z,1557167942.660 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:39:03.071Z,1557167943.071 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.715928 min 
2019-05-06T18:39:03.071Z,1557167943.071 [Default:CheckIn:E] Stopped
2019-05-06T18:39:03.071Z,1557167943.071 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:39:03.072Z,1557167943.072 [Default:CheckIn] Stopped
2019-05-06T18:39:03.072Z,1557167943.072 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:39:03.072Z,1557167943.072 [Default:CheckIn](INFO): Running loop #7
2019-05-06T18:39:03.072Z,1557167943.072 [Default:CheckIn] Running Loop=7
2019-05-06T18:39:03.072Z,1557167943.072 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:39:03.072Z,1557167943.072 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:39:04.673Z,1557167944.673 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:39:05.061Z,1557167945.061 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183831.00,A,3648.16129,N,12147.28632,W,0.292,218.32,060519,,,A*7C
2019-05-06T18:39:05.063Z,1557167945.063 [NAL9602](INFO): GPS fix at 20190506T183831: (36.802688, -121.788105)
2019-05-06T18:39:05.138Z,1557167945.138 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:39:05.138Z,1557167945.138 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:39:10.924Z,1557167950.924 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0025.lzma
2019-05-06T18:39:11.722Z,1557167951.722 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0025.lzma.bak
2019-05-06T18:39:11.722Z,1557167951.722 [DataOverHttps](INFO): SBD MOMSN=10942944
2019-05-06T18:39:23.966Z,1557167963.966 [DataOverHttps](INFO): Sending 729 bytes from file Logs/20190506T175744/Express0026.lzma
2019-05-06T18:39:24.770Z,1557167964.770 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0026.lzma.bak
2019-05-06T18:39:24.771Z,1557167964.771 [DataOverHttps](INFO): SBD MOMSN=10942950
2019-05-06T18:39:25.696Z,1557167965.696 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:39:25.696Z,1557167965.696 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:39:25.696Z,1557167965.696 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:40:49.288Z,1557168049.288 [NAL9602](INFO): SBD MO Status=2, MOMSN=3807, MT Status=2, MTMSN=0
2019-05-06T18:40:49.289Z,1557168049.289 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T18:41:31.358Z,1557168091.358 [RDI_Pathfinder](ERROR): only read -1 of 1 data item for BIT error
2019-05-06T18:41:31.358Z,1557168091.358 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050611500895,35.0, -0.1, 
2019-05-06T18:42:50.092Z,1557168170.092 [NAL9602](INFO): SBD MO Status=2, MOMSN=3807, MT Status=2, MTMSN=0
2019-05-06T18:42:50.093Z,1557168170.093 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T18:43:34.151Z,1557168214.151 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-06T18:44:07.659Z,1557168247.659 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T18:44:14.147Z,1557168254.147 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T18:44:14.147Z,1557168254.147 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050611525095,35.0, -0.1,  .00
2019-05-06T18:44:26.289Z,1557168266.289 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:44:26.289Z,1557168266.289 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:44:26.290Z,1557168266.290 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:44:26.290Z,1557168266.290 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:44:26.674Z,1557168266.674 [Default:CheckIn:D] Stopped
2019-05-06T18:44:26.674Z,1557168266.674 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:44:27.092Z,1557168267.092 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.116166 min 
2019-05-06T18:44:27.092Z,1557168267.092 [Default:CheckIn:E] Stopped
2019-05-06T18:44:27.093Z,1557168267.093 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:44:27.093Z,1557168267.093 [Default:CheckIn] Stopped
2019-05-06T18:44:27.094Z,1557168267.094 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:44:27.094Z,1557168267.094 [Default:CheckIn](INFO): Running loop #8
2019-05-06T18:44:27.094Z,1557168267.094 [Default:CheckIn] Running Loop=8
2019-05-06T18:44:27.094Z,1557168267.094 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:44:27.094Z,1557168267.094 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:44:28.697Z,1557168268.697 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:44:29.081Z,1557168269.081 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184356.00,A,3648.16360,N,12147.28576,W,0.039,218.32,060519,,,A*7E
2019-05-06T18:44:29.083Z,1557168269.083 [NAL9602](INFO): GPS fix at 20190506T184356: (36.802727, -121.788096)
2019-05-06T18:44:29.153Z,1557168269.153 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:44:29.153Z,1557168269.153 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:44:35.073Z,1557168275.073 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190506T175744/Courier0028.lzma
2019-05-06T18:44:35.874Z,1557168275.874 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0028.lzma.bak
2019-05-06T18:44:35.875Z,1557168275.875 [DataOverHttps](INFO): SBD MOMSN=10943006
2019-05-06T18:44:47.582Z,1557168287.582 [DataOverHttps](INFO): Sending 941 bytes from file Logs/20190506T175744/Express0029.lzma
2019-05-06T18:44:48.386Z,1557168288.386 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0029.lzma.bak
2019-05-06T18:44:48.387Z,1557168288.387 [DataOverHttps](INFO): SBD MOMSN=10943009
2019-05-06T18:44:49.342Z,1557168289.342 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:44:49.342Z,1557168289.342 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:44:49.342Z,1557168289.342 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:45:01.800Z,1557168301.800 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:46:32.328Z,1557168392.328 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T18:46:32.328Z,1557168392.328 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050611550995,31,   0.0,1448.9,  0
2019-05-06T18:49:49.882Z,1557168589.882 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:49:49.882Z,1557168589.882 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:49:49.882Z,1557168589.882 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:49:49.883Z,1557168589.883 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:49:50.299Z,1557168590.299 [Default:CheckIn:D] Stopped
2019-05-06T18:49:50.299Z,1557168590.299 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:49:50.691Z,1557168590.691 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.509916 min 
2019-05-06T18:49:50.691Z,1557168590.691 [Default:CheckIn:E] Stopped
2019-05-06T18:49:50.691Z,1557168590.691 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:49:50.691Z,1557168590.691 [Default:CheckIn] Stopped
2019-05-06T18:49:50.692Z,1557168590.692 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:49:50.692Z,1557168590.692 [Default:CheckIn](INFO): Running loop #9
2019-05-06T18:49:50.692Z,1557168590.692 [Default:CheckIn] Running Loop=9
2019-05-06T18:49:50.692Z,1557168590.692 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:49:50.692Z,1557168590.692 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:49:52.301Z,1557168592.301 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:49:52.684Z,1557168592.684 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184920.00,A,3648.16455,N,12147.28635,W,0.117,218.32,060519,,,A*7D
2019-05-06T18:49:52.687Z,1557168592.687 [NAL9602](INFO): GPS fix at 20190506T184920: (36.802743, -121.788106)
2019-05-06T18:49:52.736Z,1557168592.736 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:49:52.736Z,1557168592.736 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:49:58.496Z,1557168598.496 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190506T175744/Courier0031.lzma
2019-05-06T18:49:59.302Z,1557168599.302 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0031.lzma.bak
2019-05-06T18:49:59.303Z,1557168599.303 [DataOverHttps](INFO): SBD MOMSN=10943054
2019-05-06T18:50:11.102Z,1557168611.102 [DataOverHttps](INFO): Sending 736 bytes from file Logs/20190506T175744/Express0032.lzma
2019-05-06T18:50:11.907Z,1557168611.907 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0032.lzma.bak
2019-05-06T18:50:11.907Z,1557168611.907 [DataOverHttps](INFO): SBD MOMSN=10943058
2019-05-06T18:50:12.993Z,1557168612.993 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:50:12.993Z,1557168612.993 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:50:12.993Z,1557168612.993 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:50:23.427Z,1557168623.427 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-06T18:50:23.501Z,1557168623.501 [NAL9602](FAULT): received: 
+CSQ:0

OK07, 2, 0, 0, 0

OK
2019-05-06T18:50:23.501Z,1557168623.501 [NAL9602] Data Fault, FailCount= 1
2019-05-06T18:50:23.501Z,1557168623.501 [NAL9602](ERROR): Data Fault
2019-05-06T18:50:23.589Z,1557168623.589 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-06T18:50:23.823Z,1557168623.823 [NAL9602](INFO): Powering down
2019-05-06T18:50:24.683Z,1557168624.683 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-06T18:50:24.683Z,1557168624.683 [NAL9602] No Fault, FailCount= 1
2019-05-06T18:50:54.123Z,1557168654.123 [NAL9602](INFO): Powering up NAL9602
2019-05-06T18:51:05.031Z,1557168665.031 [NAL9602](INFO): NAL9602 initialized
2019-05-06T18:51:31.321Z,1557168691.321 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T18:51:31.321Z,1557168691.321 [RDI_Pathfinder](ERROR): Failed to parse:
:TS25.0, -0.1,   0.0,1448.9,  0
2019-05-06T18:51:36.143Z,1557168696.143 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T18:53:33.320Z,1557168813.320 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T18:53:33.320Z,1557168813.320 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612021095,31,   0.0,1448.9,  0
2019-05-06T18:54:14.975Z,1557168854.975 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-06T18:54:14.975Z,1557168854.975 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,      -10.  +15.57,        +4.55,   0.00,110.00
2019-05-06T18:55:13.526Z,1557168913.526 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T18:55:13.526Z,1557168913.526 [Default:CheckIn:C.Wait] Stopped
2019-05-06T18:55:13.526Z,1557168913.526 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T18:55:13.526Z,1557168913.526 [Default:CheckIn:D] Running Loop=1
2019-05-06T18:55:13.970Z,1557168913.970 [Default:CheckIn:D] Stopped
2019-05-06T18:55:13.970Z,1557168913.970 [Default:CheckIn:E] Running Loop=1
2019-05-06T18:55:14.332Z,1557168914.332 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.904423 min 
2019-05-06T18:55:14.332Z,1557168914.332 [Default:CheckIn:E] Stopped
2019-05-06T18:55:14.332Z,1557168914.332 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T18:55:14.332Z,1557168914.332 [Default:CheckIn] Stopped
2019-05-06T18:55:14.333Z,1557168914.333 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T18:55:14.333Z,1557168914.333 [Default:CheckIn](INFO): Running loop #10
2019-05-06T18:55:14.333Z,1557168914.333 [Default:CheckIn] Running Loop=10
2019-05-06T18:55:14.333Z,1557168914.333 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T18:55:14.333Z,1557168914.333 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T18:55:15.945Z,1557168915.945 [NAL9602](DEBUG): Fix Requested
2019-05-06T18:55:16.337Z,1557168916.337 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185444.00,A,3648.15928,N,12147.28887,W,0.233,0.00,060519,,,A*7F
2019-05-06T18:55:16.339Z,1557168916.339 [NAL9602](INFO): GPS fix at 20190506T185444: (36.802655, -121.788148)
2019-05-06T18:55:16.368Z,1557168916.368 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T18:55:16.368Z,1557168916.368 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T18:55:18.341Z,1557168918.341 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T18:55:22.276Z,1557168922.276 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190506T175744/Courier0034.lzma
2019-05-06T18:55:23.082Z,1557168923.082 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0034.lzma.bak
2019-05-06T18:55:23.082Z,1557168923.082 [DataOverHttps](INFO): SBD MOMSN=10943164
2019-05-06T18:55:34.958Z,1557168934.958 [DataOverHttps](INFO): Sending 823 bytes from file Logs/20190506T175744/Express0035.lzma
2019-05-06T18:55:35.763Z,1557168935.763 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0035.lzma.bak
2019-05-06T18:55:35.763Z,1557168935.763 [DataOverHttps](INFO): SBD MOMSN=10943167
2019-05-06T18:55:36.542Z,1557168936.542 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T18:55:36.542Z,1557168936.542 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T18:55:36.542Z,1557168936.542 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T18:55:49.051Z,1557168949.051 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:00:37.140Z,1557169237.140 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:00:37.140Z,1557169237.140 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:00:37.140Z,1557169237.140 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:00:37.141Z,1557169237.141 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:00:37.541Z,1557169237.541 [Default:CheckIn:D] Stopped
2019-05-06T19:00:37.541Z,1557169237.541 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:00:37.972Z,1557169237.972 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.297282 min 
2019-05-06T19:00:37.972Z,1557169237.972 [Default:CheckIn:E] Stopped
2019-05-06T19:00:37.972Z,1557169237.972 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:00:37.973Z,1557169237.973 [Default:CheckIn] Stopped
2019-05-06T19:00:37.973Z,1557169237.973 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:00:37.973Z,1557169237.973 [Default:CheckIn](INFO): Running loop #11
2019-05-06T19:00:37.973Z,1557169237.973 [Default:CheckIn] Running Loop=11
2019-05-06T19:00:37.974Z,1557169237.974 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:00:37.974Z,1557169237.974 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:00:39.533Z,1557169239.533 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:00:39.950Z,1557169239.950 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190007.00,A,3648.16149,N,12147.28003,W,0.253,0.00,060519,,,A*76
2019-05-06T19:00:39.952Z,1557169239.952 [NAL9602](INFO): GPS fix at 20190506T190007: (36.802692, -121.788000)
2019-05-06T19:00:39.985Z,1557169239.985 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:00:39.985Z,1557169239.985 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:00:48.420Z,1557169248.420 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0037.lzma
2019-05-06T19:00:49.227Z,1557169249.227 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0037.lzma.bak
2019-05-06T19:00:49.227Z,1557169249.227 [DataOverHttps](INFO): SBD MOMSN=10943207
2019-05-06T19:01:02.786Z,1557169262.786 [DataOverHttps](INFO): Sending 839 bytes from file Logs/20190506T175744/Express0038.lzma
2019-05-06T19:01:03.590Z,1557169263.590 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0038.lzma.bak
2019-05-06T19:01:03.591Z,1557169263.591 [DataOverHttps](INFO): SBD MOMSN=10943230
2019-05-06T19:01:04.268Z,1557169264.268 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:01:04.268Z,1557169264.268 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:01:04.268Z,1557169264.268 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:04:48.448Z,1557169488.448 [NAL9602](INFO): SBD MO Status=2, MOMSN=3807, MT Status=2, MTMSN=0
2019-05-06T19:04:48.448Z,1557169488.448 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:05:13.961Z,1557169513.961 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-06T19:05:13.962Z,1557169513.962 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,      -10.76,       +18.   +5.20,   0.00, 39.00
2019-05-06T19:05:41.775Z,1557169541.775 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T19:06:04.828Z,1557169564.828 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:06:04.828Z,1557169564.828 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:06:04.828Z,1557169564.828 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:06:04.828Z,1557169564.828 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:06:05.295Z,1557169565.295 [Default:CheckIn:D] Stopped
2019-05-06T19:06:05.295Z,1557169565.295 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:06:05.632Z,1557169565.632 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.759847 min 
2019-05-06T19:06:05.632Z,1557169565.632 [Default:CheckIn:E] Stopped
2019-05-06T19:06:05.632Z,1557169565.632 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:06:05.633Z,1557169565.633 [Default:CheckIn] Stopped
2019-05-06T19:06:05.633Z,1557169565.633 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:06:05.633Z,1557169565.633 [Default:CheckIn](INFO): Running loop #12
2019-05-06T19:06:05.633Z,1557169565.633 [Default:CheckIn] Running Loop=12
2019-05-06T19:06:05.633Z,1557169565.633 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:06:05.633Z,1557169565.633 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:06:07.237Z,1557169567.237 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:06:07.629Z,1557169567.629 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190535.00,A,3648.15914,N,12147.28778,W,0.194,0.00,060519,,,A*72
2019-05-06T19:06:07.631Z,1557169567.631 [NAL9602](INFO): GPS fix at 20190506T190535: (36.802652, -121.788130)
2019-05-06T19:06:07.692Z,1557169567.692 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:06:07.692Z,1557169567.692 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:06:15.168Z,1557169575.168 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0040.lzma
2019-05-06T19:06:15.974Z,1557169575.974 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0040.lzma.bak
2019-05-06T19:06:15.975Z,1557169575.975 [DataOverHttps](INFO): SBD MOMSN=10943256
2019-05-06T19:06:34.110Z,1557169594.110 [DataOverHttps](INFO): Sending 909 bytes from file Logs/20190506T175744/Express0041.lzma
2019-05-06T19:06:34.918Z,1557169594.918 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0041.lzma.bak
2019-05-06T19:06:34.919Z,1557169594.919 [DataOverHttps](INFO): SBD MOMSN=10943276
2019-05-06T19:06:35.592Z,1557169595.592 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:06:35.592Z,1557169595.592 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:06:35.592Z,1557169595.592 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:06:39.603Z,1557169599.603 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:11:36.172Z,1557169896.172 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:11:36.172Z,1557169896.172 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:11:36.172Z,1557169896.172 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:11:36.172Z,1557169896.172 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:11:36.572Z,1557169896.572 [Default:CheckIn:D] Stopped
2019-05-06T19:11:36.572Z,1557169896.572 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:11:36.980Z,1557169896.980 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.281128 min 
2019-05-06T19:11:36.980Z,1557169896.980 [Default:CheckIn:E] Stopped
2019-05-06T19:11:36.981Z,1557169896.981 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:11:36.981Z,1557169896.981 [Default:CheckIn] Stopped
2019-05-06T19:11:36.981Z,1557169896.981 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:11:36.981Z,1557169896.981 [Default:CheckIn](INFO): Running loop #13
2019-05-06T19:11:36.981Z,1557169896.981 [Default:CheckIn] Running Loop=13
2019-05-06T19:11:36.981Z,1557169896.981 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:11:36.982Z,1557169896.982 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:11:38.581Z,1557169898.581 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:11:38.969Z,1557169898.969 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191106.00,A,3648.16153,N,12147.28820,W,0.156,0.00,060519,,,A*73
2019-05-06T19:11:38.971Z,1557169898.971 [NAL9602](INFO): GPS fix at 20190506T191106: (36.802692, -121.788137)
2019-05-06T19:11:39.021Z,1557169899.021 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:11:39.021Z,1557169899.021 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:11:45.000Z,1557169905.000 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0043.lzma
2019-05-06T19:11:45.806Z,1557169905.806 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0043.lzma.bak
2019-05-06T19:11:45.807Z,1557169905.807 [DataOverHttps](INFO): SBD MOMSN=10943367
2019-05-06T19:11:57.482Z,1557169917.482 [DataOverHttps](INFO): Sending 715 bytes from file Logs/20190506T175744/Express0044.lzma
2019-05-06T19:11:58.287Z,1557169918.287 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0044.lzma.bak
2019-05-06T19:11:58.287Z,1557169918.287 [DataOverHttps](INFO): SBD MOMSN=10943371
2019-05-06T19:11:59.244Z,1557169919.244 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:11:59.244Z,1557169919.244 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:11:59.244Z,1557169919.244 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:12:09.671Z,1557169929.671 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-06T19:12:09.749Z,1557169929.749 [NAL9602](FAULT): received: 
+CSQ:1

OK07, 2, 0, 0, 0

OK
2019-05-06T19:12:09.749Z,1557169929.749 [NAL9602] Data Fault, FailCount= 1
2019-05-06T19:12:09.749Z,1557169929.749 [NAL9602](ERROR): Data Fault
2019-05-06T19:12:09.797Z,1557169929.797 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-06T19:12:10.076Z,1557169930.076 [NAL9602](INFO): Powering down
2019-05-06T19:12:10.971Z,1557169930.971 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-06T19:12:10.971Z,1557169930.971 [NAL9602] No Fault, FailCount= 1
2019-05-06T19:12:40.379Z,1557169960.379 [NAL9602](INFO): Powering up NAL9602
2019-05-06T19:12:51.292Z,1557169971.292 [NAL9602](INFO): NAL9602 initialized
2019-05-06T19:13:22.392Z,1557170002.392 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:14:53.316Z,1557170093.316 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:14:53.317Z,1557170093.317 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612233095,35.0, -0.1,   0.0, 0
2019-05-06T19:15:34.947Z,1557170134.947 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-06T19:15:34.947Z,1557170134.947 [RDI_Pathfinder](ERROR): Failed to parse:
:BD-7.49,       +16.33,        +7.25,   0.00,299.00
2019-05-06T19:16:34.312Z,1557170194.312 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:16:34.312Z,1557170194.312 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612251195,35.0, -0.,1448.9,  0
2019-05-06T19:16:59.772Z,1557170219.772 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:16:59.772Z,1557170219.772 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:16:59.772Z,1557170219.772 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:16:59.772Z,1557170219.772 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:17:00.184Z,1557170220.184 [Default:CheckIn:D] Stopped
2019-05-06T19:17:00.184Z,1557170220.184 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:17:00.577Z,1557170220.577 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.674658 min 
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn:E] Stopped
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn] Stopped
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn](INFO): Running loop #14
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn] Running Loop=14
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:17:00.578Z,1557170220.578 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:17:02.201Z,1557170222.201 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:17:02.581Z,1557170222.581 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191630.00,A,3648.16255,N,12147.28040,W,0.214,0.00,060519,,,A*7F
2019-05-06T19:17:02.584Z,1557170222.584 [NAL9602](INFO): GPS fix at 20190506T191630: (36.802709, -121.788007)
2019-05-06T19:17:02.628Z,1557170222.628 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:17:02.628Z,1557170222.628 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:17:04.631Z,1557170224.631 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-06T19:17:08.396Z,1557170228.396 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0046.lzma
2019-05-06T19:17:09.204Z,1557170229.204 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0046.lzma.bak
2019-05-06T19:17:09.204Z,1557170229.204 [DataOverHttps](INFO): SBD MOMSN=10943409
2019-05-06T19:17:10.312Z,1557170230.312 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:17:10.313Z,1557170230.313 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612254795,35.0, -0.1,   0.0,1448.RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-05-06T19:17:21.050Z,1557170241.050 [DataOverHttps](INFO): Sending 782 bytes from file Logs/20190506T175744/Express0047.lzma
2019-05-06T19:17:21.854Z,1557170241.854 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0047.lzma.bak
2019-05-06T19:17:21.855Z,1557170241.855 [DataOverHttps](INFO): SBD MOMSN=10943526
2019-05-06T19:17:22.840Z,1557170242.840 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:17:22.840Z,1557170242.840 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:17:22.840Z,1557170242.840 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:17:35.331Z,1557170255.331 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:19:09.939Z,1557170349.939 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:19:09.939Z,1557170349.939 [RDI_Pathfinder](ERROR): Failed to parse:
:TS8,V
2019-05-06T19:21:39.013Z,1557170499.013 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:21:39.013Z,1557170499.013 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,  93.26,  93.26,  93.26,  95.92
2019-05-06T19:22:23.412Z,1557170543.412 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:22:23.412Z,1557170543.412 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:22:23.412Z,1557170543.412 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:22:23.412Z,1557170543.412 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:22:23.824Z,1557170543.824 [Default:CheckIn:D] Stopped
2019-05-06T19:22:23.824Z,1557170543.824 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:22:24.240Z,1557170544.240 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 76.068660 min 
2019-05-06T19:22:24.240Z,1557170544.240 [Default:CheckIn:E] Stopped
2019-05-06T19:22:24.240Z,1557170544.240 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:22:24.245Z,1557170544.245 [Default:CheckIn] Stopped
2019-05-06T19:22:24.245Z,1557170544.245 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:22:24.245Z,1557170544.245 [Default:CheckIn](INFO): Running loop #15
2019-05-06T19:22:24.245Z,1557170544.245 [Default:CheckIn] Running Loop=15
2019-05-06T19:22:24.245Z,1557170544.245 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:22:24.245Z,1557170544.245 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:22:25.825Z,1557170545.825 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:22:26.213Z,1557170546.213 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192154.00,A,3648.16924,N,12147.28605,W,0.253,94.29,060519,,,A*46
2019-05-06T19:22:26.215Z,1557170546.215 [NAL9602](INFO): GPS fix at 20190506T192154: (36.802821, -121.788101)
2019-05-06T19:22:26.248Z,1557170546.248 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:22:26.248Z,1557170546.248 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:22:31.621Z,1557170551.621 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0049.lzma
2019-05-06T19:22:32.422Z,1557170552.422 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0049.lzma.bak
2019-05-06T19:22:32.423Z,1557170552.423 [DataOverHttps](INFO): SBD MOMSN=10943548
2019-05-06T19:22:47.303Z,1557170567.303 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-05-06T19:22:47.304Z,1557170567.304 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-3278,-32768,V
2019-05-06T19:22:50.854Z,1557170570.854 [DataOverHttps](INFO): Sending 803 bytes from file Logs/20190506T175744/Express0050.lzma
2019-05-06T19:22:51.320Z,1557170571.320 [NAL9602](INFO): SBD MO Status=2, MOMSN=3807, MT Status=2, MTMSN=0
2019-05-06T19:22:51.320Z,1557170571.320 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:22:51.658Z,1557170571.658 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0050.lzma.bak
2019-05-06T19:22:51.659Z,1557170571.659 [DataOverHttps](INFO): SBD MOMSN=10943554
2019-05-06T19:22:52.560Z,1557170572.560 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:22:52.560Z,1557170572.560 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:22:52.560Z,1557170572.560 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:23:29.320Z,1557170609.320 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:23:29.320Z,1557170609.320 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612320695,35.0, -0.1,   09,  0
2019-05-06T19:23:35.760Z,1557170615.760 [NAL9602](INFO): SBD MO Status=0, MOMSN=3807, MT Status=0, MTMSN=0
2019-05-06T19:23:35.760Z,1557170615.760 [NAL9602](INFO): No messages in MT queue
2019-05-06T19:24:06.467Z,1557170646.467 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:27:51.940Z,1557170871.940 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-06T19:27:51.940Z,1557170871.940 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,       -4.74,       +13.   +7.32,   9.63,  0.00
2019-05-06T19:27:53.160Z,1557170873.160 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:27:53.160Z,1557170873.160 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:27:53.160Z,1557170873.160 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:27:53.160Z,1557170873.160 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:27:53.548Z,1557170873.548 [Default:CheckIn:D] Stopped
2019-05-06T19:27:53.548Z,1557170873.548 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:27:53.978Z,1557170873.978 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.564071 min 
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn:E] Stopped
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn] Stopped
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn](INFO): Running loop #16
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn] Running Loop=16
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:27:53.979Z,1557170873.979 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:27:55.553Z,1557170875.553 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:27:55.943Z,1557170875.943 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192723.00,A,3648.16337,N,12147.28365,W,0.505,94.29,060519,,,A*4F
2019-05-06T19:27:55.945Z,1557170875.945 [NAL9602](INFO): GPS fix at 20190506T192723: (36.802723, -121.788061)
2019-05-06T19:27:55.977Z,1557170875.977 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:27:55.977Z,1557170875.977 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:28:01.756Z,1557170881.756 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0052.lzma
2019-05-06T19:28:02.563Z,1557170882.563 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0052.lzma.bak
2019-05-06T19:28:02.564Z,1557170882.564 [DataOverHttps](INFO): SBD MOMSN=10943594
2019-05-06T19:28:08.076Z,1557170888.076 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  95.92,  91.93,  99.91,   0.00
2019-05-06T19:28:14.226Z,1557170894.226 [DataOverHttps](INFO): Sending 861 bytes from file Logs/20190506T175744/Express0053.lzma
2019-05-06T19:28:15.031Z,1557170895.031 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0053.lzma.bak
2019-05-06T19:28:15.031Z,1557170895.031 [DataOverHttps](INFO): SBD MOMSN=10943601
2019-05-06T19:28:15.760Z,1557170895.760 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:28:15.760Z,1557170895.760 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:28:15.760Z,1557170895.760 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:28:52.124Z,1557170932.124 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:28:52.124Z,1557170932.124 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612372895,3    +12.03,        +7.27,   9.56,  0.00
2019-05-06T19:30:54.939Z,1557171054.939 [NAL9602](INFO): SBD MO Status=0, MOMSN=3808, MT Status=0, MTMSN=0
2019-05-06T19:30:54.939Z,1557171054.939 [NAL9602](INFO): No messages in MT queue
2019-05-06T19:31:25.615Z,1557171085.615 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:33:16.348Z,1557171196.348 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:33:16.348Z,1557171196.348 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:33:16.348Z,1557171196.348 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:33:16.348Z,1557171196.348 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:33:16.745Z,1557171196.745 [Default:CheckIn:D] Stopped
2019-05-06T19:33:16.745Z,1557171196.745 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:33:17.157Z,1557171197.157 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.950684 min 
2019-05-06T19:33:17.157Z,1557171197.157 [Default:CheckIn:E] Stopped
2019-05-06T19:33:17.158Z,1557171197.158 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:33:17.158Z,1557171197.158 [Default:CheckIn] Stopped
2019-05-06T19:33:17.158Z,1557171197.158 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:33:17.158Z,1557171197.158 [Default:CheckIn](INFO): Running loop #17
2019-05-06T19:33:17.158Z,1557171197.158 [Default:CheckIn] Running Loop=17
2019-05-06T19:33:17.158Z,1557171197.158 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:33:17.158Z,1557171197.158 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:33:18.749Z,1557171198.749 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:33:19.141Z,1557171199.141 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193246.00,A,3648.16640,N,12147.28467,W,0.117,94.29,060519,,,A*4F
2019-05-06T19:33:19.143Z,1557171199.143 [NAL9602](INFO): GPS fix at 20190506T193246: (36.802773, -121.788078)
2019-05-06T19:33:19.175Z,1557171199.175 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:33:19.176Z,1557171199.176 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:33:24.808Z,1557171204.808 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0055.lzma
2019-05-06T19:33:25.614Z,1557171205.614 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0055.lzma.bak
2019-05-06T19:33:25.615Z,1557171205.615 [DataOverHttps](INFO): SBD MOMSN=10943619
2019-05-06T19:33:37.286Z,1557171217.286 [DataOverHttps](INFO): Sending 820 bytes from file Logs/20190506T175744/Express0056.lzma
2019-05-06T19:33:38.091Z,1557171218.091 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0056.lzma.bak
2019-05-06T19:33:38.091Z,1557171218.091 [DataOverHttps](INFO): SBD MOMSN=10943627
2019-05-06T19:33:39.028Z,1557171219.028 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:33:39.028Z,1557171219.028 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:33:39.028Z,1557171219.028 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:33:47.472Z,1557171227.472 [NAL9602](INFO): SBD MO Status=0, MOMSN=3809, MT Status=0, MTMSN=0
2019-05-06T19:33:47.473Z,1557171227.473 [NAL9602](INFO): No messages in MT queue
2019-05-06T19:34:18.172Z,1557171258.172 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:38:28.273Z,1557171508.273 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:38:28.273Z,1557171508.273 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612470595,35.0  0.0,1448.9,  0
2019-05-06T19:38:39.598Z,1557171519.598 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:38:39.598Z,1557171519.598 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:38:39.598Z,1557171519.598 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:38:39.598Z,1557171519.598 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:38:40.023Z,1557171520.023 [Default:CheckIn:D] Stopped
2019-05-06T19:38:40.023Z,1557171520.023 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:38:40.394Z,1557171520.394 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.338656 min 
2019-05-06T19:38:40.394Z,1557171520.394 [Default:CheckIn:E] Stopped
2019-05-06T19:38:40.394Z,1557171520.394 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:38:40.394Z,1557171520.394 [Default:CheckIn] Stopped
2019-05-06T19:38:40.394Z,1557171520.394 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:38:40.395Z,1557171520.395 [Default:CheckIn](INFO): Running loop #18
2019-05-06T19:38:40.395Z,1557171520.395 [Default:CheckIn] Running Loop=18
2019-05-06T19:38:40.395Z,1557171520.395 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:38:40.395Z,1557171520.395 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:38:42.009Z,1557171522.009 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:38:42.396Z,1557171522.396 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193810.00,A,3648.16699,N,12147.28553,W,0.272,0.00,060519,,,A*72
2019-05-06T19:38:42.408Z,1557171522.408 [NAL9602](INFO): GPS fix at 20190506T193810: (36.802783, -121.788092)
2019-05-06T19:38:42.431Z,1557171522.431 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:38:42.431Z,1557171522.431 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:38:48.374Z,1557171528.374 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0058.lzma
2019-05-06T19:38:49.179Z,1557171529.179 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0058.lzma.bak
2019-05-06T19:38:49.179Z,1557171529.179 [DataOverHttps](INFO): SBD MOMSN=10943666
2019-05-06T19:39:06.626Z,1557171546.626 [DataOverHttps](INFO): Sending 854 bytes from file Logs/20190506T175744/Express0059.lzma
2019-05-06T19:39:07.430Z,1557171547.430 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0059.lzma.bak
2019-05-06T19:39:07.431Z,1557171547.431 [DataOverHttps](INFO): SBD MOMSN=10943672
2019-05-06T19:39:08.348Z,1557171548.348 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:39:08.348Z,1557171548.348 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:39:08.348Z,1557171548.348 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:40:25.886Z,1557171625.886 [NAL9602](INFO): SBD MO Status=0, MOMSN=3810, MT Status=0, MTMSN=0
2019-05-06T19:40:25.886Z,1557171625.886 [NAL9602](INFO): No messages in MT queue
2019-05-06T19:40:56.579Z,1557171656.579 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:42:30.343Z,1557171750.343 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:42:30.343Z,1557171750.343 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612510795,35.0, -0.11448.9,  0
2019-05-06T19:44:08.957Z,1557171848.957 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:44:08.958Z,1557171848.958 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:44:08.958Z,1557171848.958 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:44:08.958Z,1557171848.958 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:44:09.316Z,1557171849.316 [Default:CheckIn:D] Stopped
2019-05-06T19:44:09.316Z,1557171849.316 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:44:09.717Z,1557171849.717 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.826864 min 
2019-05-06T19:44:09.717Z,1557171849.717 [Default:CheckIn:E] Stopped
2019-05-06T19:44:09.718Z,1557171849.718 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:44:09.718Z,1557171849.718 [Default:CheckIn] Stopped
2019-05-06T19:44:09.718Z,1557171849.718 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:44:09.718Z,1557171849.718 [Default:CheckIn](INFO): Running loop #19
2019-05-06T19:44:09.718Z,1557171849.718 [Default:CheckIn] Running Loop=19
2019-05-06T19:44:09.718Z,1557171849.718 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:44:09.718Z,1557171849.718 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:44:11.321Z,1557171851.321 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:44:11.716Z,1557171851.716 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194339.00,A,3648.16447,N,12147.28122,W,0.136,0.00,060519,,,A*75
2019-05-06T19:44:11.719Z,1557171851.719 [NAL9602](INFO): GPS fix at 20190506T194339: (36.802741, -121.788020)
2019-05-06T19:44:11.742Z,1557171851.742 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:44:11.742Z,1557171851.742 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:44:17.416Z,1557171857.416 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0061.lzma
2019-05-06T19:44:18.214Z,1557171858.214 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0061.lzma.bak
2019-05-06T19:44:18.215Z,1557171858.215 [DataOverHttps](INFO): SBD MOMSN=10943689
2019-05-06T19:44:29.974Z,1557171869.974 [DataOverHttps](INFO): Sending 866 bytes from file Logs/20190506T175744/Express0062.lzma
2019-05-06T19:44:30.767Z,1557171870.767 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0062.lzma.bak
2019-05-06T19:44:30.767Z,1557171870.767 [DataOverHttps](INFO): SBD MOMSN=10943696
2019-05-06T19:44:31.648Z,1557171871.648 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:44:31.648Z,1557171871.648 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:44:31.648Z,1557171871.648 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:44:36.040Z,1557171876.040 [NAL9602](INFO): SBD MO Status=2, MOMSN=3811, MT Status=2, MTMSN=0
2019-05-06T19:44:36.040Z,1557171876.040 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:45:30.586Z,1557171930.586 [NAL9602](INFO): SBD MO Status=2, MOMSN=3811, MT Status=2, MTMSN=0
2019-05-06T19:45:30.586Z,1557171930.586 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:46:25.928Z,1557171985.928 [NAL9602](INFO): SBD MO Status=2, MOMSN=3811, MT Status=2, MTMSN=0
2019-05-06T19:46:25.933Z,1557171985.933 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:47:03.499Z,1557172023.499 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,194658,COPROC,0.10

2019-05-06T19:48:01.308Z,1557172081.308 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-06T19:48:01.308Z,1557172081.308 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-05-06T19:48:36.432Z,1557172116.432 [NAL9602](INFO): SBD MO Status=0, MOMSN=3811, MT Status=0, MTMSN=0
2019-05-06T19:48:36.433Z,1557172116.433 [NAL9602](INFO): No messages in MT queue
2019-05-06T19:49:07.124Z,1557172147.124 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:49:32.205Z,1557172172.205 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:49:32.205Z,1557172172.205 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:49:32.205Z,1557172172.205 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:49:32.206Z,1557172172.206 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:49:32.604Z,1557172172.604 [Default:CheckIn:D] Stopped
2019-05-06T19:49:32.604Z,1557172172.604 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 103.214998 min 
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn:E] Stopped
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn] Stopped
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn](INFO): Running loop #20
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn] Running Loop=20
2019-05-06T19:49:33.066Z,1557172173.066 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:49:33.067Z,1557172173.067 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:49:34.609Z,1557172174.609 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:49:35.005Z,1557172175.005 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194902.00,A,3648.16634,N,12147.28201,W,0.058,0.00,060519,,,A*7A
2019-05-06T19:49:35.007Z,1557172175.007 [NAL9602](INFO): GPS fix at 20190506T194902: (36.802772, -121.788033)
2019-05-06T19:49:35.080Z,1557172175.080 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:49:35.080Z,1557172175.080 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:49:40.836Z,1557172180.836 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0064.lzma
2019-05-06T19:49:41.642Z,1557172181.642 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0064.lzma.bak
2019-05-06T19:49:41.643Z,1557172181.643 [DataOverHttps](INFO): SBD MOMSN=10943735
2019-05-06T19:50:00.350Z,1557172200.350 [DataOverHttps](INFO): Sending 909 bytes from file Logs/20190506T175744/Express0065.lzma
2019-05-06T19:50:01.155Z,1557172201.155 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0065.lzma.bak
2019-05-06T19:50:01.155Z,1557172201.155 [DataOverHttps](INFO): SBD MOMSN=10943743
2019-05-06T19:50:02.133Z,1557172202.133 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:50:02.133Z,1557172202.133 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:50:02.133Z,1557172202.133 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:50:06.936Z,1557172206.936 [NAL9602](INFO): SBD MO Status=2, MOMSN=3812, MT Status=2, MTMSN=0
2019-05-06T19:50:06.937Z,1557172206.937 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:50:41.266Z,1557172241.266 [NAL9602](INFO): SBD MO Status=2, MOMSN=3812, MT Status=2, MTMSN=0
2019-05-06T19:50:41.266Z,1557172241.266 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:50:43.292Z,1557172243.292 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T19:50:43.293Z,1557172243.293 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050612592095,35.0, -0.1,   0.0, 0
2019-05-06T19:51:05.496Z,1557172265.496 [NAL9602](INFO): SBD MO Status=0, MOMSN=3812, MT Status=0, MTMSN=0
2019-05-06T19:51:05.496Z,1557172265.496 [NAL9602](INFO): No messages in MT queue
2019-05-06T19:51:36.199Z,1557172296.199 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T19:55:02.672Z,1557172502.672 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T19:55:02.672Z,1557172502.672 [Default:CheckIn:C.Wait] Stopped
2019-05-06T19:55:02.672Z,1557172502.672 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T19:55:02.672Z,1557172502.672 [Default:CheckIn:D] Running Loop=1
2019-05-06T19:55:03.084Z,1557172503.084 [Default:CheckIn:D] Stopped
2019-05-06T19:55:03.084Z,1557172503.084 [Default:CheckIn:E] Running Loop=1
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.723006 min 
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn:E] Stopped
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn] Stopped
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn](INFO): Running loop #21
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn] Running Loop=21
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T19:55:03.482Z,1557172503.482 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T19:55:05.085Z,1557172505.085 [NAL9602](DEBUG): Fix Requested
2019-05-06T19:55:05.470Z,1557172505.470 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195433.00,A,3648.16715,N,12147.28293,W,0.058,0.00,060519,,,A*7D
2019-05-06T19:55:05.472Z,1557172505.472 [NAL9602](INFO): GPS fix at 20190506T195433: (36.802786, -121.788049)
2019-05-06T19:55:05.496Z,1557172505.496 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T19:55:05.496Z,1557172505.496 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T19:55:11.420Z,1557172511.420 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190506T175744/Courier0067.lzma
2019-05-06T19:55:12.226Z,1557172512.226 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0067.lzma.bak
2019-05-06T19:55:12.227Z,1557172512.227 [DataOverHttps](INFO): SBD MOMSN=10943754
2019-05-06T19:55:22.036Z,1557172522.036 [NAL9602](INFO): SBD MO Status=2, MOMSN=3813, MT Status=2, MTMSN=0
2019-05-06T19:55:22.036Z,1557172522.036 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:55:23.698Z,1557172523.698 [DataOverHttps](INFO): Sending 876 bytes from file Logs/20190506T175744/Express0068.lzma
2019-05-06T19:55:24.503Z,1557172524.503 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0068.lzma.bak
2019-05-06T19:55:24.503Z,1557172524.503 [DataOverHttps](INFO): SBD MOMSN=10943760
2019-05-06T19:55:25.335Z,1557172525.335 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T19:55:25.335Z,1557172525.335 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T19:55:25.335Z,1557172525.335 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T19:58:44.440Z,1557172724.440 [NAL9602](INFO): SBD MO Status=2, MOMSN=3813, MT Status=2, MTMSN=0
2019-05-06T19:58:44.440Z,1557172724.440 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:58:57.785Z,1557172737.785 [NAL9602](INFO): SBD MO Status=2, MOMSN=3813, MT Status=2, MTMSN=0
2019-05-06T19:58:57.786Z,1557172737.786 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:59:28.914Z,1557172768.914 [NAL9602](INFO): SBD MO Status=2, MOMSN=3813, MT Status=2, MTMSN=0
2019-05-06T19:59:28.914Z,1557172768.914 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T19:59:47.921Z,1557172787.921 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-05-06T19:59:47.921Z,1557172787.921 [RDI_Pathfinder](ERROR): Failed to parse:
:BD +0.93,        +6.74,        +9.38,   0.00,111.00
2019-05-06T20:00:12.112Z,1557172812.112 [NAL9602](INFO): SBD MO Status=0, MOMSN=3813, MT Status=0, MTMSN=0
2019-05-06T20:00:12.112Z,1557172812.112 [NAL9602](INFO): No messages in MT queue
2019-05-06T20:00:25.871Z,1557172825.871 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T20:00:25.871Z,1557172825.871 [Default:CheckIn:C.Wait] Stopped
2019-05-06T20:00:25.871Z,1557172825.871 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T20:00:25.872Z,1557172825.872 [Default:CheckIn:D] Running Loop=1
2019-05-06T20:00:26.292Z,1557172826.292 [Default:CheckIn:D] Stopped
2019-05-06T20:00:26.292Z,1557172826.292 [Default:CheckIn:E] Running Loop=1
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 114.109798 min 
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn:E] Stopped
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn] Stopped
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn](INFO): Running loop #22
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn] Running Loop=22
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T20:00:26.687Z,1557172826.687 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T20:00:28.277Z,1557172828.277 [NAL9602](DEBUG): Fix Requested
2019-05-06T20:00:28.676Z,1557172828.676 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195956.00,A,3648.16304,N,12147.28204,W,0.136,348.27,060519,,,A*7A
2019-05-06T20:00:28.679Z,1557172828.679 [NAL9602](INFO): GPS fix at 20190506T195956: (36.802717, -121.788034)
2019-05-06T20:00:28.708Z,1557172828.708 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T20:00:28.708Z,1557172828.708 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T20:00:34.552Z,1557172834.552 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190506T175744/Courier0070.lzma
2019-05-06T20:00:35.358Z,1557172835.358 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0070.lzma.bak
2019-05-06T20:00:35.359Z,1557172835.359 [DataOverHttps](INFO): SBD MOMSN=10943797
2019-05-06T20:00:53.454Z,1557172853.454 [DataOverHttps](INFO): Sending 761 bytes from file Logs/20190506T175744/Express0071.lzma
2019-05-06T20:00:54.259Z,1557172854.259 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0071.lzma.bak
2019-05-06T20:00:54.259Z,1557172854.259 [DataOverHttps](INFO): SBD MOMSN=10943805
2019-05-06T20:00:55.006Z,1557172855.006 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T20:00:55.007Z,1557172855.007 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T20:00:55.007Z,1557172855.007 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T20:01:00.995Z,1557172860.995 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T20:02:28.277Z,1557172948.277 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-06T20:02:28.277Z,1557172948.277 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19050613110595,35.0, -0.1,   0.0, 0
2019-05-06T20:05:55.548Z,1557173155.548 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T20:05:55.548Z,1557173155.548 [Default:CheckIn:C.Wait] Stopped
2019-05-06T20:05:55.548Z,1557173155.548 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T20:05:55.549Z,1557173155.549 [Default:CheckIn:D] Running Loop=1
2019-05-06T20:05:55.940Z,1557173155.940 [Default:CheckIn:D] Stopped
2019-05-06T20:05:55.940Z,1557173155.940 [Default:CheckIn:E] Running Loop=1
2019-05-06T20:05:56.355Z,1557173156.355 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.603931 min 
2019-05-06T20:05:56.355Z,1557173156.355 [Default:CheckIn:E] Stopped
2019-05-06T20:05:56.355Z,1557173156.355 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-06T20:05:56.356Z,1557173156.356 [Default:CheckIn] Stopped
2019-05-06T20:05:56.356Z,1557173156.356 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-06T20:05:56.356Z,1557173156.356 [Default:CheckIn](INFO): Running loop #23
2019-05-06T20:05:56.356Z,1557173156.356 [Default:CheckIn] Running Loop=23
2019-05-06T20:05:56.356Z,1557173156.356 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-06T20:05:56.356Z,1557173156.356 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-06T20:05:57.949Z,1557173157.949 [NAL9602](DEBUG): Fix Requested
2019-05-06T20:05:58.340Z,1557173158.340 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200526.00,A,3648.16237,N,12147.28042,W,0.272,348.27,060519,,,A*7C
2019-05-06T20:05:58.343Z,1557173158.343 [NAL9602](INFO): GPS fix at 20190506T200526: (36.802706, -121.788007)
2019-05-06T20:05:58.366Z,1557173158.366 [Default:CheckIn:Read_GPS] Stopped
2019-05-06T20:05:58.367Z,1557173158.367 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-06T20:06:04.026Z,1557173164.026 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190506T175744/Courier0073.lzma
2019-05-06T20:06:04.830Z,1557173164.830 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Courier0073.lzma.bak
2019-05-06T20:06:04.831Z,1557173164.831 [DataOverHttps](INFO): SBD MOMSN=10943845
2019-05-06T20:06:16.474Z,1557173176.474 [DataOverHttps](INFO): Sending 715 bytes from file Logs/20190506T175744/Express0074.lzma
2019-05-06T20:06:17.279Z,1557173177.279 [DataOverHttps](INFO): Moved sent file to Logs/20190506T175744/Express0074.lzma.bak
2019-05-06T20:06:17.279Z,1557173177.279 [DataOverHttps](INFO): SBD MOMSN=10943848
2019-05-06T20:06:18.264Z,1557173178.264 [Default:CheckIn:Read_Iridium] Stopped
2019-05-06T20:06:18.264Z,1557173178.264 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-06T20:06:18.264Z,1557173178.264 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-06T20:07:35.364Z,1557173255.364 [NAL9602](INFO): SBD MO Status=2, MOMSN=3814, MT Status=2, MTMSN=0
2019-05-06T20:07:35.364Z,1557173255.364 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-06T20:08:01.218Z,1557173281.218 [NAL9602](INFO): SBD MO Status=0, MOMSN=3814, MT Status=0, MTMSN=0
2019-05-06T20:08:01.218Z,1557173281.218 [NAL9602](INFO): No messages in MT queue
2019-05-06T20:08:31.923Z,1557173311.923 [NAL9602](INFO): Not Powering down - fast GPS
2019-05-06T20:11:18.800Z,1557173478.800 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-06T20:11:18.800Z,1557173478.800 [Default:CheckIn:C.Wait] Stopped
2019-05-06T20:11:18.800Z,1557173478.800 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-06T20:11:18.801Z,1557173478.801 [Default:CheckIn:D] Running Loop=1
2019-05-06T20:11:19.225Z,1557173479.225 [Default:CheckIn:D] Stopped
2019-05-06T20:11:19.225Z,1557173479.225 [Default:CheckIn:E] Running Loop=1
2019-05-06T20:11:19.618Z,1557173479.618 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 124.992017 min 
2019-05-06T20:11:19.618Z,1557173479.618 [Default:CheckIn:E] Stopped
2019-05-06T20:11:19.618Z,1557173479.618 [