2018-11-27T02:00:41.215Z,1543284041.215 [Supervisor](DEBUG): Initializing supervisor.
2018-11-27T02:00:41.218Z,1543284041.218 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-11-27T02:00:41.218Z,1543284041.218 [SyncHandler](INFO): Protected caller Thread ID is 6762
2018-11-27T02:00:41.219Z,1543284041.219 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-11-27T02:00:41.220Z,1543284041.220 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-11-27T02:00:41.220Z,1543284041.220 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 6763
2018-11-27T02:00:41.223Z,1543284041.223 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-11-27T02:00:41.235Z,1543284041.235 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-11-27T02:00:41.236Z,1543284041.236 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-11-27T02:00:41.237Z,1543284041.237 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 6764
2018-11-27T02:00:41.238Z,1543284041.238 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-11-27T02:00:41.239Z,1543284041.239 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-11-27T02:00:41.239Z,1543284041.239 [logger ThreadHandler](INFO): Protected caller Thread ID is 6765
2018-11-27T02:00:41.241Z,1543284041.241 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-11-27T02:00:41.241Z,1543284041.241 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-11-27T02:00:41.243Z,1543284041.243 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-11-27T02:00:41.567Z,1543284041.567 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-11-27T02:00:41.567Z,1543284041.567 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-11-27T02:00:41.758Z,1543284041.758 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-11-27T02:00:41.759Z,1543284041.759 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-11-27T02:00:42.046Z,1543284042.046 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-11-27T02:00:42.047Z,1543284042.047 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-11-27T02:00:42.189Z,1543284042.189 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-11-27T02:00:42.189Z,1543284042.189 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-11-27T02:00:42.295Z,1543284042.295 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-11-27T02:00:42.296Z,1543284042.296 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-11-27T02:00:42.846Z,1543284042.846 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-11-27T02:00:42.847Z,1543284042.847 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-11-27T02:00:43.308Z,1543284043.308 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-11-27T02:00:43.309Z,1543284043.309 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-11-27T02:00:43.767Z,1543284043.767 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-11-27T02:00:43.768Z,1543284043.768 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-11-27T02:00:43.870Z,1543284043.870 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-11-27T02:00:43.870Z,1543284043.870 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-11-27T02:00:43.965Z,1543284043.965 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-11-27T02:00:43.966Z,1543284043.966 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-11-27T02:00:44.183Z,1543284044.183 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-11-27T02:00:44.183Z,1543284044.183 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-11-27T02:00:44.383Z,1543284044.383 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-11-27T02:00:44.384Z,1543284044.384 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-11-27T02:00:44.745Z,1543284044.745 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-11-27T02:00:44.746Z,1543284044.746 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-11-27T02:00:44.888Z,1543284044.888 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-11-27T02:00:44.889Z,1543284044.889 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-11-27T02:00:44.980Z,1543284044.980 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-11-27T02:00:44.981Z,1543284044.981 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-11-27T02:00:45.083Z,1543284045.083 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-11-27T02:00:45.202Z,1543284045.202 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-11-27T02:00:45.296Z,1543284045.296 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-11-27T02:00:45.381Z,1543284045.381 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-11-27T02:00:45.545Z,1543284045.545 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-11-27T02:00:45.729Z,1543284045.729 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-11-27T02:00:45.804Z,1543284045.804 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-11-27T02:00:46.030Z,1543284046.030 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-11-27T02:00:46.031Z,1543284046.031 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-11-27T02:00:46.112Z,1543284046.112 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-11-27T02:00:46.200Z,1543284046.200 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-11-27T02:00:46.298Z,1543284046.298 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-11-27T02:00:46.423Z,1543284046.423 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2018-11-27T02:00:46.423Z,1543284046.423 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-11-27T02:00:46.437Z,1543284046.437 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-11-27T02:00:46.668Z,1543284046.668 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-11-27T02:00:46.669Z,1543284046.669 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-11-27T02:00:46.711Z,1543284046.711 [DepthRateCalculator] Loaded
2018-11-27T02:00:46.711Z,1543284046.711 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-11-27T02:00:46.717Z,1543284046.717 [PitchRateCalculator] Loaded
2018-11-27T02:00:46.717Z,1543284046.717 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-11-27T02:00:46.733Z,1543284046.733 [SpeedCalculator] Loaded
2018-11-27T02:00:46.733Z,1543284046.733 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-11-27T02:00:46.754Z,1543284046.754 [TempGradientCalculator] Loaded
2018-11-27T02:00:46.754Z,1543284046.754 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-11-27T02:00:46.760Z,1543284046.760 [YawRateCalculator] Loaded
2018-11-27T02:00:46.760Z,1543284046.760 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-11-27T02:00:46.799Z,1543284046.799 [ElevatorOffsetCalculator] Loaded
2018-11-27T02:00:46.799Z,1543284046.799 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-11-27T02:00:46.800Z,1543284046.800 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-11-27T02:00:46.800Z,1543284046.800 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-11-27T02:00:46.864Z,1543284046.864 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-11-27T02:00:46.865Z,1543284046.865 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-11-27T02:00:46.987Z,1543284046.987 [BuoyancyServo] Loaded
2018-11-27T02:00:46.987Z,1543284046.987 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-11-27T02:00:47.002Z,1543284047.002 [ElevatorServo] Loaded
2018-11-27T02:00:47.002Z,1543284047.002 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-11-27T02:00:47.016Z,1543284047.016 [MassServo] Loaded
2018-11-27T02:00:47.017Z,1543284047.017 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-11-27T02:00:47.032Z,1543284047.032 [RudderServo] Loaded
2018-11-27T02:00:47.032Z,1543284047.032 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-11-27T02:00:47.045Z,1543284047.046 [ThrusterServo] Loaded
2018-11-27T02:00:47.046Z,1543284047.046 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-11-27T02:00:47.046Z,1543284047.046 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-11-27T02:00:47.047Z,1543284047.047 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-11-27T02:00:47.060Z,1543284047.060 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-11-27T02:00:47.060Z,1543284047.060 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-11-27T02:00:47.158Z,1543284047.158 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-11-27T02:00:47.158Z,1543284047.158 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-11-27T02:00:47.440Z,1543284047.440 [DataOverHttps] Loaded
2018-11-27T02:00:47.441Z,1543284047.441 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-11-27T02:00:47.455Z,1543284047.455 [Depth_Keller] Loaded
2018-11-27T02:00:47.455Z,1543284047.455 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-11-27T02:00:47.460Z,1543284047.460 [DropWeight] Loaded
2018-11-27T02:00:47.460Z,1543284047.460 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-11-27T02:00:47.557Z,1543284047.557 [NAL9602] Loaded
2018-11-27T02:00:47.558Z,1543284047.558 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-11-27T02:00:47.573Z,1543284047.573 [Onboard] Loaded
2018-11-27T02:00:47.573Z,1543284047.573 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-11-27T02:00:47.583Z,1543284047.583 [Radio_Surface] Loaded
2018-11-27T02:00:47.584Z,1543284047.584 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-11-27T02:00:47.585Z,1543284047.585 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4088F4E0
2018-11-27T02:00:47.585Z,1543284047.585 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6847
2018-11-27T02:00:47.631Z,1543284047.631 [PNI_TCM] Loaded
2018-11-27T02:00:47.631Z,1543284047.631 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-11-27T02:00:47.632Z,1543284047.632 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-11-27T02:00:47.632Z,1543284047.632 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-11-27T02:00:47.864Z,1543284047.864 [SBIT](DEBUG): Construct Startup Built In Test.
2018-11-27T02:00:47.928Z,1543284047.928 [SBIT] Loaded
2018-11-27T02:00:47.928Z,1543284047.928 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-11-27T02:00:47.929Z,1543284047.929 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-11-27T02:00:47.965Z,1543284047.965 [IBIT] Loaded
2018-11-27T02:00:47.970Z,1543284047.970 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-11-27T02:00:47.991Z,1543284047.991 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-11-27T02:00:48.646Z,1543284048.646 [CBIT] Loaded
2018-11-27T02:00:48.646Z,1543284048.646 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-11-27T02:00:48.647Z,1543284048.647 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-11-27T02:00:48.647Z,1543284048.647 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-11-27T02:00:48.889Z,1543284048.889 [CTD_NeilBrown] Loaded
2018-11-27T02:00:48.889Z,1543284048.889 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-11-27T02:00:48.891Z,1543284048.891 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4096E4E0
2018-11-27T02:00:48.891Z,1543284048.891 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 6848
2018-11-27T02:00:48.964Z,1543284048.964 [CTD_Seabird] Loaded
2018-11-27T02:00:48.964Z,1543284048.964 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-11-27T02:00:48.965Z,1543284048.965 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4099E4E0
2018-11-27T02:00:48.965Z,1543284048.965 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 6849
2018-11-27T02:00:48.979Z,1543284048.979 [PAR_Licor] Loaded
2018-11-27T02:00:48.980Z,1543284048.980 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-11-27T02:00:49.028Z,1543284049.028 [WetLabsBB2FL] Loaded
2018-11-27T02:00:49.028Z,1543284049.028 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-11-27T02:00:49.029Z,1543284049.029 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409CE4E0
2018-11-27T02:00:49.030Z,1543284049.030 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 6850
2018-11-27T02:00:49.030Z,1543284049.030 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-11-27T02:00:49.031Z,1543284049.031 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-11-27T02:00:49.097Z,1543284049.097 [VerticalControl](DEBUG): Construct VerticalControl.
2018-11-27T02:00:49.180Z,1543284049.180 [VerticalControl] Loaded
2018-11-27T02:00:49.180Z,1543284049.180 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-11-27T02:00:49.181Z,1543284049.181 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-11-27T02:00:49.237Z,1543284049.237 [HorizontalControl] Loaded
2018-11-27T02:00:49.237Z,1543284049.237 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-11-27T02:00:49.238Z,1543284049.238 [SpeedControl](DEBUG): Construct SpeedControl.
2018-11-27T02:00:49.239Z,1543284049.239 [SpeedControl] Loaded
2018-11-27T02:00:49.240Z,1543284049.240 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-11-27T02:00:49.240Z,1543284049.240 [LoopControl](DEBUG): Construct LoopControl.
2018-11-27T02:00:49.241Z,1543284049.241 [LoopControl] Loaded
2018-11-27T02:00:49.241Z,1543284049.241 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-11-27T02:00:49.241Z,1543284049.241 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-11-27T02:00:49.242Z,1543284049.242 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-11-27T02:00:49.266Z,1543284049.266 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-11-27T02:00:49.266Z,1543284049.266 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-11-27T02:00:49.355Z,1543284049.355 [DeadReckonUsingSpeedCalculator] Loaded
2018-11-27T02:00:49.356Z,1543284049.356 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-11-27T02:00:49.372Z,1543284049.372 [NavChart] Loaded
2018-11-27T02:00:49.372Z,1543284049.372 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-11-27T02:00:49.376Z,1543284049.376 [UniversalFixResidualReporter] Loaded
2018-11-27T02:00:49.376Z,1543284049.376 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-11-27T02:00:49.377Z,1543284049.377 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-11-27T02:00:49.380Z,1543284049.380 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-11-27T02:00:49.381Z,1543284049.381 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-11-27T02:00:49.388Z,1543284049.388 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-11-27T02:00:49.389Z,1543284049.389 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A5A4E0
2018-11-27T02:00:49.389Z,1543284049.389 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6851
2018-11-27T02:00:49.394Z,1543284049.394 [Supervisor](INFO): Main Thread ID is 6473
2018-11-27T02:00:49.394Z,1543284049.394 [Supervisor](DEBUG): Running supervisor.
2018-11-27T02:00:49.395Z,1543284049.395 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6852
2018-11-27T02:00:49.397Z,1543284049.397 [controlThread ThreadHandler](INFO): Handler Thread ID is 6853
2018-11-27T02:00:49.397Z,1543284049.397 [controlThread](DEBUG): Initializing ControlThread
2018-11-27T02:00:49.398Z,1543284049.398 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-11-27T02:00:49.399Z,1543284049.399 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-11-27T02:00:49.399Z,1543284049.399 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-11-27T02:00:49.399Z,1543284049.399 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-11-27T02:00:49.400Z,1543284049.400 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-11-27T02:00:49.400Z,1543284049.400 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-11-27T02:00:49.408Z,1543284049.408 [SBIT](INFO): Initialize SBIT Component.
2018-11-27T02:00:49.408Z,1543284049.408 [SBIT](IMPORTANT): git: 2018-11-05-23-gc670f65
2018-11-27T02:00:49.408Z,1543284049.408 [SBIT](INFO): git hash: c670f65e90afb3cd45868fc8f56def32ffac7cef
2018-11-27T02:00:49.409Z,1543284049.409 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-11-27T02:00:49.409Z,1543284049.409 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-11-27T02:00:49.410Z,1543284049.410 [SBIT](INFO): Beginning SBIT in 36.000000 seconds.
2018-11-27T02:00:49.411Z,1543284049.411 [IBIT](INFO): Initialize IBIT Component.
2018-11-27T02:00:49.412Z,1543284049.412 [CBIT](DEBUG): Initialize CBIT Component.
2018-11-27T02:00:49.412Z,1543284049.412 [logger ThreadHandler](INFO): Handler Thread ID is 6854
2018-11-27T02:00:49.425Z,1543284049.425 [CBIT](DEBUG): Initialized mux pins.
2018-11-27T02:00:49.426Z,1543284049.426 [CBIT](DEBUG): Initializing the watchdog timer.
2018-11-27T02:00:49.430Z,1543284049.430 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6855
2018-11-27T02:00:49.435Z,1543284049.435 [Radio_Surface](INFO): Powering up
2018-11-27T02:00:49.446Z,1543284049.446 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 6856
2018-11-27T02:00:49.447Z,1543284049.447 [CTD_NeilBrown](INFO): Powering down
2018-11-27T02:00:49.453Z,1543284049.453 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-11-27T02:00:49.454Z,1543284049.454 [CBIT](DEBUG): Initializing heartbeat.
2018-11-27T02:00:49.474Z,1543284049.474 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 6857
2018-11-27T02:00:49.475Z,1543284049.475 [CTD_Seabird](INFO): Start
2018-11-27T02:00:49.475Z,1543284049.475 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2018-11-27T02:00:49.479Z,1543284049.479 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 6859
2018-11-27T02:00:49.480Z,1543284049.480 [WetLabsBB2FL](INFO): Powering down
2018-11-27T02:00:49.498Z,1543284049.498 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2018-11-27T02:00:49.514Z,1543284049.514 [CTD_Seabird](INFO): Starting
2018-11-27T02:00:49.516Z,1543284049.516 [CTD_Seabird](INFO): Pause
2018-11-27T02:00:49.525Z,1543284049.525 [CBIT](DEBUG): Deactivating GF circuits.
2018-11-27T02:00:49.526Z,1543284049.526 [CBIT](DEBUG): Deactivating emergency mode.
2018-11-27T02:00:49.526Z,1543284049.526 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6860
2018-11-27T02:00:49.530Z,1543284049.530 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-11-27T02:00:49.530Z,1543284049.530 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-11-27T02:00:49.530Z,1543284049.530 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-11-27T02:00:49.530Z,1543284049.530 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-11-27T02:00:49.530Z,1543284049.530 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-11-27T02:00:49.531Z,1543284049.531 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-11-27T02:00:49.531Z,1543284049.531 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-11-27T02:00:49.531Z,1543284049.531 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-11-27T02:00:49.531Z,1543284049.531 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-11-27T02:00:49.531Z,1543284049.531 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-11-27T02:00:49.532Z,1543284049.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-11-27T02:00:49.532Z,1543284049.532 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-11-27T02:00:49.532Z,1543284049.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-11-27T02:00:49.532Z,1543284049.532 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-11-27T02:00:49.532Z,1543284049.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-11-27T02:00:49.533Z,1543284049.533 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-11-27T02:00:49.566Z,1543284049.566 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-11-27T02:00:49.568Z,1543284049.568 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-11-27T02:00:49.568Z,1543284049.568 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-11-27T02:00:49.569Z,1543284049.569 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-11-27T02:00:49.569Z,1543284049.569 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-27T02:00:49.570Z,1543284049.570 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-27T02:00:49.570Z,1543284049.570 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-27T02:00:49.571Z,1543284049.571 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-11-27T02:00:49.571Z,1543284049.571 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-11-27T02:00:49.574Z,1543284049.574 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-11-27T02:00:49.592Z,1543284049.592 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-27T02:00:49.624Z,1543284049.624 [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>


2018-11-27T02:00:49.625Z,1543284049.625 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-11-27T02:00:49.698Z,1543284049.698 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-11-27T02:00:49.699Z,1543284049.699 [Default:A.Wait](DEBUG): Construct Wait.
2018-11-27T02:00:49.701Z,1543284049.701 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-27T02:00:49.752Z,1543284049.752 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-11-27T02:00:49.754Z,1543284049.754 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-11-27T02:00:49.776Z,1543284049.776 [Default:E.Execute](DEBUG): Construct Execute.
2018-11-27T02:00:49.779Z,1543284049.779 [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>


2018-11-27T02:00:49.789Z,1543284049.789 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-11-27T02:00:49.814Z,1543284049.814 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-11-27T02:00:49.827Z,1543284049.827 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2018-11-27T02:00:50.023Z,1543284050.023 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-11-27T02:00:50.250Z,1543284050.250 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-27T02:00:50.258Z,1543284050.258 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-27T02:00:50.272Z,1543284050.272 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-11-27T02:00:50.278Z,1543284050.278 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-11-27T02:00:50.300Z,1543284050.300 [MassServo](DEBUG): Initializing EZServoServo.
2018-11-27T02:00:50.306Z,1543284050.306 [MassServo](DEBUG): Initializing MassServo.
2018-11-27T02:00:50.319Z,1543284050.319 [RudderServo](DEBUG): Initializing EZServoServo.
2018-11-27T02:00:50.326Z,1543284050.326 [RudderServo](DEBUG): Initializing RudderServo.
2018-11-27T02:00:50.332Z,1543284050.332 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-11-27T02:00:50.338Z,1543284050.338 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-11-27T02:00:51.174Z,1543284051.174 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-11-27T02:00:51.174Z,1543284051.174 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-11-27T02:00:51.174Z,1543284051.174 [BuoyancyServo] Communications Fault, FailCount= 1
2018-11-27T02:00:51.174Z,1543284051.174 [BuoyancyServo](ERROR): Communications Fault
2018-11-27T02:00:51.381Z,1543284051.381 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-11-27T02:00:53.547Z,1543284053.547 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-11-27T02:00:53.547Z,1543284053.547 [BuoyancyServo] No Fault, FailCount= 1
2018-11-27T02:00:53.893Z,1543284053.893 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-27T02:00:54.014Z,1543284054.014 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-27T02:01:17.795Z,1543284077.795 [NAL9602](INFO): Powering up NAL9602
2018-11-27T02:01:25.879Z,1543284085.879 [SBIT](IMPORTANT): Beginning Startup BIT
2018-11-27T02:01:25.892Z,1543284085.892 [CBIT](IMPORTANT): Beginning ground fault scan
2018-11-27T02:01:29.123Z,1543284089.123 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:01:36.829Z,1543284096.829 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.002491
CHAN A1 (24V): -0.006746
CHAN A2 (12V): -0.001762
CHAN A3 (5V): -0.001389
CHAN B0 (3.3V): -0.000040
CHAN B1 (3.15aV): -0.000393
CHAN B2 (3.15bV): -0.000023
CHAN B3 (GND): 0.000026
OPEN: -0.000158
Full Scale Calc: 4.765 mA, -1.589 mA
2018-11-27T02:02:19.895Z,1543284139.895 [SBIT](IMPORTANT): SBIT PASSED
2018-11-27T02:02:19.974Z,1543284139.974 [CommandLine](IMPORTANT): got command configSet list
2018-11-27T02:02:19.975Z,1543284139.975 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=28 count;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): BPC1.batteryMuxCycleTime=10 minute;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_salinity;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_temperature 0.150000 kelvin;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): Express linearApproximation CTD_NeilBrown.bin_median_sea_water_salinity 0.020000 practical_salinity_unit;

2018-11-27T02:02:19.976Z,1543284139.976 [CommandLine](IMPORTANT): Express linearApproximation CTD_NeilBrown.bin_median_sea_water_temperature 0.150000 kelvin;

2018-11-27T02:02:19.977Z,1543284139.977 [CommandLine](IMPORTANT): Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index;

2018-11-27T02:02:19.977Z,1543284139.977 [CommandLine](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;

2018-11-27T02:02:19.977Z,1543284139.977 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool;

2018-11-27T02:02:19.977Z,1543284139.977 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=213 cubic_centimeter;

2018-11-27T02:02:19.977Z,1543284139.977 [CommandLine](IMPORTANT): VerticalControl.massDefault=4 millimeter;

2018-11-27T02:02:20.293Z,1543284140.293 [MissionManager](IMPORTANT): Started mission Startup
2018-11-27T02:02:20.293Z,1543284140.293 [Startup] Running Loop=1
2018-11-27T02:02:20.294Z,1543284140.294 [Startup](DEBUG): Aggregate::initialize Startup
2018-11-27T02:02:20.294Z,1543284140.294 [Startup:A.GoToSurface] Running Loop=1
2018-11-27T02:02:20.294Z,1543284140.294 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-27T02:02:20.294Z,1543284140.294 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-27T02:02:20.295Z,1543284140.295 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-27T02:02:20.295Z,1543284140.295 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-27T02:02:20.296Z,1543284140.296 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-27T02:02:20.296Z,1543284140.296 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-27T02:02:20.302Z,1543284140.302 [Startup:StartupSatComms] Running Loop=1
2018-11-27T02:02:20.302Z,1543284140.302 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-11-27T02:02:20.302Z,1543284140.302 [Startup:StartupSatComms:A] Running Loop=1
2018-11-27T02:02:20.681Z,1543284140.681 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-11-27T02:03:12.249Z,1543284192.249 [NAL9602](INFO): SBD MO Status=2, MOMSN=10762, MT Status=2, MTMSN=0
2018-11-27T02:03:12.249Z,1543284192.249 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T02:03:20.689Z,1543284200.689 [Startup:StartupSatComms:A](INFO): Timed out from 2018-11-27T02:02:20.3Z
2018-11-27T02:03:20.689Z,1543284200.689 [Startup:StartupSatComms:A] Stopped
2018-11-27T02:03:20.693Z,1543284200.693 [Startup:StartupSatComms:B] Running Loop=1
2018-11-27T02:03:21.095Z,1543284201.095 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-11-27T02:03:49.884Z,1543284229.884 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-11-27T02:03:49.884Z,1543284229.884 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2018-11-27T02:03:49.884Z,1543284229.884 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-27T02:03:49.896Z,1543284229.896 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-27T02:03:50.299Z,1543284230.299 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-27T02:03:50.299Z,1543284230.299 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2018-11-27T02:03:50.703Z,1543284230.703 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-27T02:03:50.704Z,1543284230.704 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-27T02:03:50.704Z,1543284230.704 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-27T02:03:54.632Z,1543284234.632 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.008515
2018-11-27T02:03:58.615Z,1543284238.615 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T014304/Courier0007.lzma
2018-11-27T02:03:59.416Z,1543284239.416 [DataOverHttps](INFO): Moved sent file to Logs/20181127T014304/Courier0007.lzma.bak
2018-11-27T02:03:59.416Z,1543284239.416 [DataOverHttps](INFO): SBD MOMSN=8924345
2018-11-27T02:04:08.236Z,1543284248.236 [DataOverHttps](INFO): Sending 177 bytes from file Logs/20181127T014304/Express0008.lzma
2018-11-27T02:04:09.036Z,1543284249.036 [DataOverHttps](INFO): Moved sent file to Logs/20181127T014304/Express0008.lzma.bak
2018-11-27T02:04:09.036Z,1543284249.036 [DataOverHttps](INFO): SBD MOMSN=8924347
2018-11-27T02:04:17.865Z,1543284257.865 [DataOverHttps](INFO): Sending 1011 bytes from file Logs/20181127T020041/Express0001.lzma
2018-11-27T02:04:18.661Z,1543284258.661 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0001.lzma.bak
2018-11-27T02:04:18.661Z,1543284258.661 [DataOverHttps](INFO): SBD MOMSN=8924351
2018-11-27T02:04:19.206Z,1543284259.206 [Startup:StartupSatComms:B] Stopped
2018-11-27T02:04:19.207Z,1543284259.207 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-11-27T02:04:19.207Z,1543284259.207 [Startup:StartupSatComms] Stopped
2018-11-27T02:04:19.207Z,1543284259.207 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-11-27T02:04:19.208Z,1543284259.208 [Startup](INFO): Completed Startup
2018-11-27T02:04:19.208Z,1543284259.208 [MissionManager](INFO): Startup is completed.
2018-11-27T02:04:19.208Z,1543284259.208 [MissionManager](INFO): Uninitializing Mission Startup
2018-11-27T02:04:19.208Z,1543284259.208 [Startup] Stopped
2018-11-27T02:04:19.208Z,1543284259.208 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-11-27T02:04:19.208Z,1543284259.208 [Startup:A.GoToSurface] Stopped
2018-11-27T02:04:19.208Z,1543284259.208 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-27T02:04:19.511Z,1543284259.511 [MissionManager](IMPORTANT): Started mission Default
2018-11-27T02:04:19.511Z,1543284259.511 [Default] Running Loop=1
2018-11-27T02:04:19.511Z,1543284259.511 [Default](DEBUG): Aggregate::initialize Default
2018-11-27T02:04:19.511Z,1543284259.511 [Default:B.GoToSurface] Running Loop=1
2018-11-27T02:04:19.512Z,1543284259.512 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-27T02:04:19.512Z,1543284259.512 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-27T02:04:19.512Z,1543284259.512 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-27T02:04:19.512Z,1543284259.512 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-27T02:04:19.513Z,1543284259.513 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-27T02:04:19.513Z,1543284259.513 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-27T02:04:19.513Z,1543284259.513 [Default:A.Wait] Running Loop=1
2018-11-27T02:04:19.514Z,1543284259.514 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-11-27T02:04:32.684Z,1543284272.684 [Default:A.Wait](INFO): Done Waiting.
2018-11-27T02:04:32.684Z,1543284272.684 [Default:A.Wait] Stopped
2018-11-27T02:04:32.684Z,1543284272.684 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T02:04:33.087Z,1543284273.087 [Default:CheckIn] Running Loop=1
2018-11-27T02:04:33.087Z,1543284273.087 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T02:04:33.087Z,1543284273.087 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T02:04:33.489Z,1543284273.489 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-11-27T02:06:32.216Z,1543284392.216 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T02:06:51.058Z,1543284411.058 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-11-27T02:06:51.058Z,1543284411.058 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2018-11-27T02:06:51.058Z,1543284411.058 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-27T02:06:51.091Z,1543284411.091 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-27T02:06:51.465Z,1543284411.465 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-27T02:06:51.465Z,1543284411.465 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2018-11-27T02:06:51.857Z,1543284411.857 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-27T02:06:51.857Z,1543284411.857 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-27T02:06:51.858Z,1543284411.858 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-27T02:09:33.463Z,1543284573.463 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T02:04:33.1Z
2018-11-27T02:09:33.463Z,1543284573.463 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T02:09:33.463Z,1543284573.463 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T02:09:33.858Z,1543284573.858 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-11-27T02:09:37.791Z,1543284577.791 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0004.lzma
2018-11-27T02:09:38.584Z,1543284578.584 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0004.lzma.bak
2018-11-27T02:09:38.584Z,1543284578.584 [DataOverHttps](INFO): SBD MOMSN=8924382
2018-11-27T02:09:47.404Z,1543284587.404 [DataOverHttps](INFO): Sending 176 bytes from file Logs/20181127T020041/Express0005.lzma
2018-11-27T02:09:48.204Z,1543284588.204 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0005.lzma.bak
2018-11-27T02:09:48.204Z,1543284588.204 [DataOverHttps](INFO): SBD MOMSN=8924384
2018-11-27T02:09:48.761Z,1543284588.761 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T02:09:48.761Z,1543284588.761 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T02:09:48.761Z,1543284588.761 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T02:09:52.162Z,1543284592.162 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-11-27T02:09:52.162Z,1543284592.162 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2018-11-27T02:09:52.162Z,1543284592.162 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-27T02:09:52.174Z,1543284592.174 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-27T02:09:52.312Z,1543284592.312 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-27T02:09:52.312Z,1543284592.312 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2018-11-27T02:09:52.637Z,1543284592.637 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-27T02:09:52.638Z,1543284592.638 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-27T02:09:52.638Z,1543284592.638 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-27T02:11:30.183Z,1543284690.183 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T02:11:30.183Z,1543284690.183 [NAL9602] Data Fault, FailCount= 1
2018-11-27T02:11:30.183Z,1543284690.183 [NAL9602](ERROR): Data Fault
2018-11-27T02:11:30.267Z,1543284690.267 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T02:11:30.580Z,1543284690.580 [NAL9602](INFO): Powering down
2018-11-27T02:11:31.427Z,1543284691.427 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T02:11:31.428Z,1543284691.428 [NAL9602] No Fault, FailCount= 1
2018-11-27T02:12:00.947Z,1543284720.947 [NAL9602](INFO): Powering up NAL9602
2018-11-27T02:12:12.147Z,1543284732.147 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:12:53.295Z,1543284773.295 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-11-27T02:12:53.295Z,1543284773.295 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2018-11-27T02:12:53.295Z,1543284773.295 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-27T02:12:53.308Z,1543284773.308 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-27T02:12:53.454Z,1543284773.454 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-27T02:12:53.455Z,1543284773.455 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2018-11-27T02:12:53.762Z,1543284773.762 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-27T02:12:53.763Z,1543284773.763 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-27T02:12:53.763Z,1543284773.763 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-27T02:14:49.351Z,1543284889.351 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T02:14:49.351Z,1543284889.351 [Default:CheckIn:C.Wait] Stopped
2018-11-27T02:14:49.351Z,1543284889.351 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T02:14:49.351Z,1543284889.351 [Default:CheckIn:D] Running Loop=1
2018-11-27T02:14:49.756Z,1543284889.756 [Default:CheckIn:D] Stopped
2018-11-27T02:14:49.757Z,1543284889.757 [Default:CheckIn:E] Running Loop=1
2018-11-27T02:14:50.164Z,1543284890.164 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.504056 min 
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn:E] Stopped
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn] Stopped
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn](INFO): Running loop #2
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn] Running Loop=2
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T02:14:50.167Z,1543284890.167 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T02:15:54.472Z,1543284954.472 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-11-27T02:15:54.472Z,1543284954.472 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 5
2018-11-27T02:15:54.472Z,1543284954.472 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-27T02:15:54.485Z,1543284954.485 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-27T02:15:54.618Z,1543284954.618 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-27T02:15:54.618Z,1543284954.618 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 5
2018-11-27T02:15:54.937Z,1543284954.937 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-27T02:15:54.937Z,1543284954.937 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-27T02:15:54.942Z,1543284954.942 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-27T02:16:47.704Z,1543285007.704 [NAL9602](INFO): GPS fix at 20181127T021312: (36.803278, -121.787572)
2018-11-27T02:16:47.771Z,1543285007.771 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T02:16:47.771Z,1543285007.771 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T02:16:54.307Z,1543285014.307 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20181127T020041/Courier0007.lzma
2018-11-27T02:16:55.096Z,1543285015.096 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0007.lzma.bak
2018-11-27T02:16:55.096Z,1543285015.096 [DataOverHttps](INFO): SBD MOMSN=8924388
2018-11-27T02:17:04.886Z,1543285024.886 [DataOverHttps](INFO): Sending 296 bytes from file Logs/20181127T020041/Express0008.lzma
2018-11-27T02:17:05.648Z,1543285025.648 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0008.lzma.bak
2018-11-27T02:17:05.648Z,1543285025.648 [DataOverHttps](INFO): SBD MOMSN=8924391
2018-11-27T02:17:06.251Z,1543285026.251 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T02:17:06.251Z,1543285026.251 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T02:17:06.251Z,1543285026.251 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T02:17:24.619Z,1543285044.619 [NAL9602](INFO): Powering down
2018-11-27T02:22:06.520Z,1543285326.520 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T02:22:06.520Z,1543285326.520 [Default:CheckIn:C.Wait] Stopped
2018-11-27T02:22:06.520Z,1543285326.520 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T02:22:06.521Z,1543285326.521 [Default:CheckIn:D] Running Loop=1
2018-11-27T02:22:06.913Z,1543285326.913 [Default:CheckIn:D] Stopped
2018-11-27T02:22:06.913Z,1543285326.913 [Default:CheckIn:E] Running Loop=1
2018-11-27T02:22:07.334Z,1543285327.334 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.790025 min 
2018-11-27T02:22:07.334Z,1543285327.334 [Default:CheckIn:E] Stopped
2018-11-27T02:22:07.335Z,1543285327.335 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T02:22:07.335Z,1543285327.335 [Default:CheckIn] Stopped
2018-11-27T02:22:07.335Z,1543285327.335 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T02:22:07.335Z,1543285327.335 [Default:CheckIn](INFO): Running loop #3
2018-11-27T02:22:07.335Z,1543285327.335 [Default:CheckIn] Running Loop=3
2018-11-27T02:22:07.335Z,1543285327.335 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T02:22:07.335Z,1543285327.335 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T02:22:10.671Z,1543285330.671 [NAL9602](INFO): Powering up
2018-11-27T02:22:21.848Z,1543285341.848 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:22:47.440Z,1543285367.440 [NAL9602](INFO): SBD MO Status=0, MOMSN=10762, MT Status=0, MTMSN=0
2018-11-27T02:22:47.440Z,1543285367.440 [NAL9602](INFO): No messages in MT queue
2018-11-27T02:27:07.722Z,1543285627.722 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T02:22:07.3Z
2018-11-27T02:27:07.722Z,1543285627.722 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T02:27:07.722Z,1543285627.722 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T02:27:11.332Z,1543285631.332 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0010.lzma
2018-11-27T02:27:12.120Z,1543285632.120 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0010.lzma.bak
2018-11-27T02:27:12.120Z,1543285632.120 [DataOverHttps](INFO): SBD MOMSN=8924396
2018-11-27T02:27:20.997Z,1543285640.997 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181127T020041/Express0011.lzma
2018-11-27T02:27:21.772Z,1543285641.772 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0011.lzma.bak
2018-11-27T02:27:21.772Z,1543285641.772 [DataOverHttps](INFO): SBD MOMSN=8924398
2018-11-27T02:27:22.318Z,1543285642.318 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T02:27:22.318Z,1543285642.318 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T02:27:22.318Z,1543285642.318 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T02:27:41.379Z,1543285661.379 [NAL9602](INFO): Powering down
2018-11-27T02:32:22.691Z,1543285942.691 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T02:32:22.691Z,1543285942.691 [Default:CheckIn:C.Wait] Stopped
2018-11-27T02:32:22.691Z,1543285942.691 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T02:32:22.691Z,1543285942.691 [Default:CheckIn:D] Running Loop=1
2018-11-27T02:32:23.098Z,1543285943.098 [Default:CheckIn:D] Stopped
2018-11-27T02:32:23.098Z,1543285943.098 [Default:CheckIn:E] Running Loop=1
2018-11-27T02:32:23.488Z,1543285943.488 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.059768 min 
2018-11-27T02:32:23.488Z,1543285943.488 [Default:CheckIn:E] Stopped
2018-11-27T02:32:23.488Z,1543285943.488 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T02:32:23.489Z,1543285943.489 [Default:CheckIn] Stopped
2018-11-27T02:32:23.489Z,1543285943.489 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T02:32:23.489Z,1543285943.489 [Default:CheckIn](INFO): Running loop #4
2018-11-27T02:32:23.489Z,1543285943.489 [Default:CheckIn] Running Loop=4
2018-11-27T02:32:23.489Z,1543285943.489 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T02:32:23.489Z,1543285943.489 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T02:32:27.128Z,1543285947.128 [NAL9602](INFO): Powering up
2018-11-27T02:32:38.023Z,1543285958.023 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:32:38.815Z,1543285958.815 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T02:32:38.815Z,1543285958.815 [NAL9602] Data Fault, FailCount= 1
2018-11-27T02:32:38.815Z,1543285958.815 [NAL9602](ERROR): Data Fault
2018-11-27T02:32:38.905Z,1543285958.905 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T02:32:39.215Z,1543285959.215 [NAL9602](INFO): Powering down
2018-11-27T02:32:40.068Z,1543285960.068 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T02:32:40.068Z,1543285960.068 [NAL9602] No Fault, FailCount= 1
2018-11-27T02:33:09.615Z,1543285989.615 [NAL9602](INFO): Powering up NAL9602
2018-11-27T02:33:20.415Z,1543286000.415 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:36:34.288Z,1543286194.288 [NAL9602](INFO): SBD MO Status=2, MOMSN=10763, MT Status=2, MTMSN=0
2018-11-27T02:36:34.289Z,1543286194.289 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T02:36:55.884Z,1543286215.884 [NAL9602](INFO): SBD MO Status=2, MOMSN=10763, MT Status=2, MTMSN=0
2018-11-27T02:36:55.884Z,1543286215.884 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T02:37:23.545Z,1543286243.545 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T02:32:23.5Z
2018-11-27T02:37:23.545Z,1543286243.545 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T02:37:23.545Z,1543286243.545 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T02:37:27.564Z,1543286247.564 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0013.lzma
2018-11-27T02:37:28.356Z,1543286248.356 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0013.lzma.bak
2018-11-27T02:37:28.356Z,1543286248.356 [DataOverHttps](INFO): SBD MOMSN=8924401
2018-11-27T02:37:28.366Z,1543286248.366 [NAL9602](INFO): SBD MO Status=2, MOMSN=10763, MT Status=2, MTMSN=0
2018-11-27T02:37:28.366Z,1543286248.366 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T02:37:37.289Z,1543286257.289 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20181127T020041/Express0014.lzma
2018-11-27T02:37:38.088Z,1543286258.088 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0014.lzma.bak
2018-11-27T02:37:38.088Z,1543286258.088 [DataOverHttps](INFO): SBD MOMSN=8924403
2018-11-27T02:37:38.699Z,1543286258.699 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T02:37:38.700Z,1543286258.700 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T02:37:38.700Z,1543286258.700 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T02:37:44.980Z,1543286264.980 [NAL9602](INFO): SBD MO Status=2, MOMSN=10763, MT Status=2, MTMSN=0
2018-11-27T02:37:44.980Z,1543286264.980 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T02:38:23.775Z,1543286303.775 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T02:38:54.307Z,1543286334.307 [NAL9602](INFO): Powering down
2018-11-27T02:42:39.225Z,1543286559.225 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T02:42:39.225Z,1543286559.225 [Default:CheckIn:C.Wait] Stopped
2018-11-27T02:42:39.225Z,1543286559.225 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T02:42:39.225Z,1543286559.225 [Default:CheckIn:D] Running Loop=1
2018-11-27T02:42:39.641Z,1543286559.641 [Default:CheckIn:D] Stopped
2018-11-27T02:42:39.641Z,1543286559.641 [Default:CheckIn:E] Running Loop=1
2018-11-27T02:42:42.920Z,1543286562.920 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.335494 min 
2018-11-27T02:42:42.920Z,1543286562.920 [Default:CheckIn:E] Stopped
2018-11-27T02:42:42.920Z,1543286562.920 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T02:42:42.920Z,1543286562.920 [Default:CheckIn] Stopped
2018-11-27T02:42:42.920Z,1543286562.920 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T02:42:42.920Z,1543286562.920 [Default:CheckIn](INFO): Running loop #5
2018-11-27T02:42:42.921Z,1543286562.921 [Default:CheckIn] Running Loop=5
2018-11-27T02:42:42.921Z,1543286562.921 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T02:42:42.921Z,1543286562.921 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T02:42:43.371Z,1543286563.371 [NAL9602](INFO): Powering up
2018-11-27T02:42:54.571Z,1543286574.571 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:43:26.571Z,1543286606.571 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-27T02:43:26.646Z,1543286606.646 [NAL9602](FAULT): received: 
+CSQ:0

OK763, 2, 0, 0, 0

OK
2018-11-27T02:43:26.646Z,1543286606.646 [NAL9602] Data Fault, FailCount= 2
2018-11-27T02:43:26.646Z,1543286606.646 [NAL9602](ERROR): Data Fault
2018-11-27T02:43:26.754Z,1543286606.754 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T02:43:26.971Z,1543286606.971 [NAL9602](INFO): Powering down
2018-11-27T02:43:27.839Z,1543286607.839 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T02:43:27.839Z,1543286607.839 [NAL9602] No Fault, FailCount= 2
2018-11-27T02:43:57.351Z,1543286637.351 [NAL9602](INFO): Powering up NAL9602
2018-11-27T02:44:08.551Z,1543286648.551 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:44:09.351Z,1543286649.351 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T02:44:09.351Z,1543286649.351 [NAL9602] Data Fault, FailCount= 3
2018-11-27T02:44:09.351Z,1543286649.351 [NAL9602](ERROR): Data Fault
2018-11-27T02:44:09.459Z,1543286649.459 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T02:44:09.751Z,1543286649.751 [NAL9602](INFO): Powering down
2018-11-27T02:44:10.625Z,1543286650.625 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T02:44:10.625Z,1543286650.625 [NAL9602] No Fault, FailCount= 3
2018-11-27T02:44:40.151Z,1543286680.151 [NAL9602](INFO): Powering up NAL9602
2018-11-27T02:44:50.999Z,1543286690.999 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:46:43.367Z,1543286803.367 [NAL9602](INFO): SBD MO Status=2, MOMSN=10763, MT Status=2, MTMSN=0
2018-11-27T02:46:43.368Z,1543286803.368 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T02:46:49.425Z,1543286809.425 [NAL9602](INFO): SBD MO Status=0, MOMSN=10763, MT Status=0, MTMSN=0
2018-11-27T02:46:49.425Z,1543286809.425 [NAL9602](INFO): No messages in MT queue
2018-11-27T02:47:43.787Z,1543286863.787 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T02:42:42.9Z
2018-11-27T02:47:43.788Z,1543286863.788 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T02:47:43.788Z,1543286863.788 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T02:47:48.734Z,1543286868.734 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0016.lzma
2018-11-27T02:47:49.508Z,1543286869.508 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0016.lzma.bak
2018-11-27T02:47:49.508Z,1543286869.508 [DataOverHttps](INFO): SBD MOMSN=8924407
2018-11-27T02:47:58.405Z,1543286878.405 [DataOverHttps](INFO): Sending 254 bytes from file Logs/20181127T020041/Express0017.lzma
2018-11-27T02:47:59.196Z,1543286879.196 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0017.lzma.bak
2018-11-27T02:47:59.196Z,1543286879.196 [DataOverHttps](INFO): SBD MOMSN=8924409
2018-11-27T02:47:59.744Z,1543286879.744 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T02:47:59.744Z,1543286879.744 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T02:47:59.744Z,1543286879.744 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T02:48:18.775Z,1543286898.775 [NAL9602](INFO): Powering down
2018-11-27T02:53:00.225Z,1543287180.225 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T02:53:00.225Z,1543287180.225 [Default:CheckIn:C.Wait] Stopped
2018-11-27T02:53:00.225Z,1543287180.225 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T02:53:00.225Z,1543287180.225 [Default:CheckIn:D] Running Loop=1
2018-11-27T02:53:00.640Z,1543287180.640 [Default:CheckIn:D] Stopped
2018-11-27T02:53:00.640Z,1543287180.640 [Default:CheckIn:E] Running Loop=1
2018-11-27T02:53:01.027Z,1543287181.027 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.685474 min 
2018-11-27T02:53:01.027Z,1543287181.027 [Default:CheckIn:E] Stopped
2018-11-27T02:53:01.027Z,1543287181.027 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T02:53:01.027Z,1543287181.027 [Default:CheckIn] Stopped
2018-11-27T02:53:01.027Z,1543287181.027 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T02:53:01.028Z,1543287181.028 [Default:CheckIn](INFO): Running loop #6
2018-11-27T02:53:01.028Z,1543287181.028 [Default:CheckIn] Running Loop=6
2018-11-27T02:53:01.028Z,1543287181.028 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T02:53:01.028Z,1543287181.028 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T02:53:04.493Z,1543287184.493 [NAL9602](INFO): Powering up
2018-11-27T02:53:15.367Z,1543287195.367 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:55:43.544Z,1543287343.544 [NAL9602](INFO): SBD MO Status=2, MOMSN=10764, MT Status=2, MTMSN=0
2018-11-27T02:55:43.544Z,1543287343.544 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T02:56:09.524Z,1543287369.524 [NAL9602](INFO): SBD MO Status=0, MOMSN=10764, MT Status=0, MTMSN=0
2018-11-27T02:56:09.525Z,1543287369.525 [NAL9602](INFO): No messages in MT queue
2018-11-27T02:56:10.331Z,1543287370.331 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T02:56:10.331Z,1543287370.331 [NAL9602] Data Fault, FailCount= 1
2018-11-27T02:56:10.331Z,1543287370.331 [NAL9602](ERROR): Data Fault
2018-11-27T02:56:10.437Z,1543287370.437 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T02:56:10.727Z,1543287370.727 [NAL9602](INFO): Powering down
2018-11-27T02:56:11.604Z,1543287371.604 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T02:56:11.604Z,1543287371.604 [NAL9602] No Fault, FailCount= 1
2018-11-27T02:56:41.123Z,1543287401.123 [NAL9602](INFO): Powering up NAL9602
2018-11-27T02:56:52.323Z,1543287412.323 [NAL9602](INFO): NAL9602 initialized
2018-11-27T02:58:01.168Z,1543287481.168 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T02:53:01.0Z
2018-11-27T02:58:01.168Z,1543287481.168 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T02:58:01.168Z,1543287481.168 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T02:58:05.578Z,1543287485.578 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0019.lzma
2018-11-27T02:58:06.380Z,1543287486.380 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0019.lzma.bak
2018-11-27T02:58:06.380Z,1543287486.380 [DataOverHttps](INFO): SBD MOMSN=8924417
2018-11-27T02:58:15.180Z,1543287495.180 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20181127T020041/Express0020.lzma
2018-11-27T02:58:15.928Z,1543287495.928 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0020.lzma.bak
2018-11-27T02:58:15.928Z,1543287495.928 [DataOverHttps](INFO): SBD MOMSN=8924419
2018-11-27T02:58:16.474Z,1543287496.474 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T02:58:16.474Z,1543287496.474 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T02:58:16.474Z,1543287496.474 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T02:58:32.107Z,1543287512.107 [NAL9602](INFO): Powering down
2018-11-27T03:03:17.077Z,1543287797.077 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T03:03:17.077Z,1543287797.077 [Default:CheckIn:C.Wait] Stopped
2018-11-27T03:03:17.077Z,1543287797.077 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T03:03:17.077Z,1543287797.077 [Default:CheckIn:D] Running Loop=1
2018-11-27T03:03:17.477Z,1543287797.477 [Default:CheckIn:D] Stopped
2018-11-27T03:03:17.477Z,1543287797.477 [Default:CheckIn:E] Running Loop=1
2018-11-27T03:03:20.584Z,1543287800.584 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.966089 min 
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn:E] Stopped
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn] Stopped
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn](INFO): Running loop #7
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn] Running Loop=7
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T03:03:20.585Z,1543287800.585 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T03:03:21.007Z,1543287801.007 [NAL9602](INFO): Powering up
2018-11-27T03:03:32.211Z,1543287812.211 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:05:41.512Z,1543287941.512 [NAL9602](INFO): SBD MO Status=2, MOMSN=10765, MT Status=2, MTMSN=0
2018-11-27T03:05:41.512Z,1543287941.512 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T03:08:21.468Z,1543288101.468 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T03:03:20.6Z
2018-11-27T03:08:21.468Z,1543288101.468 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T03:08:21.468Z,1543288101.468 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T03:08:26.431Z,1543288106.431 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0022.lzma
2018-11-27T03:08:28.024Z,1543288108.024 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0022.lzma.bak
2018-11-27T03:08:28.024Z,1543288108.024 [DataOverHttps](INFO): SBD MOMSN=8924424
2018-11-27T03:08:37.329Z,1543288117.329 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T03:08:37.491Z,1543288117.491 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181127T020041/Express0023.lzma
2018-11-27T03:08:38.276Z,1543288118.276 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0023.lzma.bak
2018-11-27T03:08:38.276Z,1543288118.276 [DataOverHttps](INFO): SBD MOMSN=8924426
2018-11-27T03:08:38.938Z,1543288118.938 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T03:08:38.938Z,1543288118.938 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T03:08:38.938Z,1543288118.938 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T03:09:07.883Z,1543288147.883 [NAL9602](INFO): Powering down
2018-11-27T03:13:39.347Z,1543288419.347 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T03:13:39.347Z,1543288419.347 [Default:CheckIn:C.Wait] Stopped
2018-11-27T03:13:39.347Z,1543288419.347 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T03:13:39.347Z,1543288419.347 [Default:CheckIn:D] Running Loop=1
2018-11-27T03:13:39.763Z,1543288419.763 [Default:CheckIn:D] Stopped
2018-11-27T03:13:39.763Z,1543288419.763 [Default:CheckIn:E] Running Loop=1
2018-11-27T03:13:40.167Z,1543288420.167 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.337524 min 
2018-11-27T03:13:40.167Z,1543288420.167 [Default:CheckIn:E] Stopped
2018-11-27T03:13:40.167Z,1543288420.167 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T03:13:40.167Z,1543288420.167 [Default:CheckIn] Stopped
2018-11-27T03:13:40.168Z,1543288420.168 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T03:13:40.168Z,1543288420.168 [Default:CheckIn](INFO): Running loop #8
2018-11-27T03:13:40.168Z,1543288420.168 [Default:CheckIn] Running Loop=8
2018-11-27T03:13:40.168Z,1543288420.168 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T03:13:40.168Z,1543288420.168 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T03:13:43.467Z,1543288423.467 [NAL9602](INFO): Powering up
2018-11-27T03:13:54.611Z,1543288434.611 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:13:55.411Z,1543288435.411 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T03:13:55.411Z,1543288435.411 [NAL9602] Data Fault, FailCount= 2
2018-11-27T03:13:55.411Z,1543288435.411 [NAL9602](ERROR): Data Fault
2018-11-27T03:13:55.510Z,1543288435.510 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T03:13:55.811Z,1543288435.811 [NAL9602](INFO): Powering down
2018-11-27T03:13:56.682Z,1543288436.682 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T03:13:56.683Z,1543288436.683 [NAL9602] No Fault, FailCount= 2
2018-11-27T03:14:26.211Z,1543288466.211 [NAL9602](INFO): Powering up NAL9602
2018-11-27T03:14:37.411Z,1543288477.411 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:18:40.295Z,1543288720.295 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T03:13:40.2Z
2018-11-27T03:18:40.295Z,1543288720.295 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T03:18:40.296Z,1543288720.296 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T03:18:48.031Z,1543288728.031 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0025.lzma
2018-11-27T03:18:48.832Z,1543288728.832 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0025.lzma.bak
2018-11-27T03:18:48.832Z,1543288728.832 [DataOverHttps](INFO): SBD MOMSN=8924429
2018-11-27T03:18:58.114Z,1543288738.114 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20181127T020041/Express0026.lzma
2018-11-27T03:18:58.904Z,1543288738.904 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0026.lzma.bak
2018-11-27T03:18:58.904Z,1543288738.904 [DataOverHttps](INFO): SBD MOMSN=8924431
2018-11-27T03:18:59.456Z,1543288739.456 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T03:18:59.456Z,1543288739.456 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T03:18:59.456Z,1543288739.456 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T03:19:43.695Z,1543288783.695 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T03:20:14.223Z,1543288814.223 [NAL9602](INFO): Powering down
2018-11-27T03:23:59.886Z,1543289039.886 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T03:23:59.886Z,1543289039.886 [Default:CheckIn:C.Wait] Stopped
2018-11-27T03:23:59.886Z,1543289039.886 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T03:23:59.886Z,1543289039.886 [Default:CheckIn:D] Running Loop=1
2018-11-27T03:24:00.298Z,1543289040.298 [Default:CheckIn:D] Stopped
2018-11-27T03:24:00.298Z,1543289040.298 [Default:CheckIn:E] Running Loop=1
2018-11-27T03:24:00.695Z,1543289040.695 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 79.679777 min 
2018-11-27T03:24:00.695Z,1543289040.695 [Default:CheckIn:E] Stopped
2018-11-27T03:24:00.695Z,1543289040.695 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T03:24:00.695Z,1543289040.695 [Default:CheckIn] Stopped
2018-11-27T03:24:00.695Z,1543289040.695 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T03:24:00.696Z,1543289040.696 [Default:CheckIn](INFO): Running loop #9
2018-11-27T03:24:00.696Z,1543289040.696 [Default:CheckIn] Running Loop=9
2018-11-27T03:24:00.696Z,1543289040.696 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T03:24:00.696Z,1543289040.696 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T03:24:04.332Z,1543289044.332 [NAL9602](INFO): Powering up
2018-11-27T03:24:15.215Z,1543289055.215 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:24:47.215Z,1543289087.215 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-27T03:24:47.296Z,1543289087.296 [NAL9602](FAULT): received: 
+CSQ:0

OK765, 2, 0, 0, 0

OK
2018-11-27T03:24:47.296Z,1543289087.296 [NAL9602] Data Fault, FailCount= 3
2018-11-27T03:24:47.296Z,1543289087.296 [NAL9602](ERROR): Data Fault
2018-11-27T03:24:47.382Z,1543289087.382 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T03:24:47.615Z,1543289087.615 [NAL9602](INFO): Powering down
2018-11-27T03:24:48.456Z,1543289088.456 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T03:24:48.456Z,1543289088.456 [NAL9602] No Fault, FailCount= 3
2018-11-27T03:25:18.011Z,1543289118.011 [NAL9602](INFO): Powering up NAL9602
2018-11-27T03:25:29.211Z,1543289129.211 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:25:30.007Z,1543289130.007 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T03:25:30.007Z,1543289130.007 [NAL9602] Data Fault, FailCount= 4
2018-11-27T03:25:30.007Z,1543289130.007 [NAL9602](ERROR): Data Fault
2018-11-27T03:25:30.106Z,1543289130.106 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T03:25:30.407Z,1543289130.407 [NAL9602](INFO): Powering down
2018-11-27T03:25:31.289Z,1543289131.289 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T03:25:31.289Z,1543289131.289 [NAL9602] No Fault, FailCount= 4
2018-11-27T03:26:00.807Z,1543289160.807 [NAL9602](INFO): Powering up NAL9602
2018-11-27T03:26:14.163Z,1543289174.163 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:29:01.089Z,1543289341.089 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T03:24:00.7Z
2018-11-27T03:29:01.089Z,1543289341.089 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T03:29:01.089Z,1543289341.089 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T03:29:05.475Z,1543289345.475 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0028.lzma
2018-11-27T03:29:06.272Z,1543289346.272 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0028.lzma.bak
2018-11-27T03:29:06.272Z,1543289346.272 [DataOverHttps](INFO): SBD MOMSN=8924436
2018-11-27T03:29:15.206Z,1543289355.206 [DataOverHttps](INFO): Sending 254 bytes from file Logs/20181127T020041/Express0029.lzma
2018-11-27T03:29:16.008Z,1543289356.008 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0029.lzma.bak
2018-11-27T03:29:16.008Z,1543289356.008 [DataOverHttps](INFO): SBD MOMSN=8924438
2018-11-27T03:29:16.555Z,1543289356.555 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T03:29:16.555Z,1543289356.555 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T03:29:16.555Z,1543289356.555 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T03:29:19.940Z,1543289359.940 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T03:29:50.395Z,1543289390.395 [NAL9602](INFO): Powering down
2018-11-27T03:34:17.116Z,1543289657.116 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T03:34:17.116Z,1543289657.116 [Default:CheckIn:C.Wait] Stopped
2018-11-27T03:34:17.116Z,1543289657.116 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T03:34:17.116Z,1543289657.116 [Default:CheckIn:D] Running Loop=1
2018-11-27T03:34:17.523Z,1543289657.523 [Default:CheckIn:D] Stopped
2018-11-27T03:34:17.524Z,1543289657.524 [Default:CheckIn:E] Running Loop=1
2018-11-27T03:34:17.917Z,1543289657.917 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 89.966870 min 
2018-11-27T03:34:17.917Z,1543289657.917 [Default:CheckIn:E] Stopped
2018-11-27T03:34:17.917Z,1543289657.917 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T03:34:17.917Z,1543289657.917 [Default:CheckIn] Stopped
2018-11-27T03:34:17.918Z,1543289657.918 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T03:34:17.918Z,1543289657.918 [Default:CheckIn](INFO): Running loop #10
2018-11-27T03:34:17.918Z,1543289657.918 [Default:CheckIn] Running Loop=10
2018-11-27T03:34:17.918Z,1543289657.918 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T03:34:17.918Z,1543289657.918 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T03:34:21.514Z,1543289661.514 [NAL9602](INFO): Powering up
2018-11-27T03:34:32.406Z,1543289672.406 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:35:04.403Z,1543289704.403 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-27T03:35:04.479Z,1543289704.479 [NAL9602](FAULT): received: 
+CSQ:0

OK765, 2, 0, 0, 0

OK
2018-11-27T03:35:04.479Z,1543289704.479 [NAL9602] Data Fault, FailCount= 5
2018-11-27T03:35:04.479Z,1543289704.479 [NAL9602](ERROR): Data Fault
2018-11-27T03:35:04.521Z,1543289704.521 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T03:35:04.522Z,1543289704.522 [CBIT](CRITICAL): Data Fault in component: NAL9602
2018-11-27T03:35:04.807Z,1543289704.807 [NAL9602](INFO): Powering down
2018-11-27T03:35:04.875Z,1543289704.875 [CommandLine](FAULT): Scheduling is paused
2018-11-27T03:35:04.875Z,1543289704.875 [CBIT](INFO): Critical error at 20181127T033504
2018-11-27T03:35:04.876Z,1543289704.876 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-11-27T03:37:04.653Z,1543289824.653 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T03:37:04.653Z,1543289824.653 [NAL9602] No Fault, FailCount= 5
2018-11-27T03:37:05.007Z,1543289825.007 [NAL9602](INFO): Powering up NAL9602
2018-11-27T03:37:16.203Z,1543289836.203 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:37:17.003Z,1543289837.003 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T03:37:17.003Z,1543289837.003 [NAL9602] Data Fault, FailCount= 1
2018-11-27T03:37:17.003Z,1543289837.003 [NAL9602](ERROR): Data Fault
2018-11-27T03:37:17.100Z,1543289837.100 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T03:37:17.403Z,1543289837.403 [NAL9602](INFO): Powering down
2018-11-27T03:37:18.273Z,1543289838.273 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T03:37:18.277Z,1543289838.277 [NAL9602] No Fault, FailCount= 1
2018-11-27T03:37:47.483Z,1543289867.483 [NAL9602](INFO): Powering up NAL9602
2018-11-27T03:37:58.679Z,1543289878.679 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:39:18.063Z,1543289958.063 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T03:34:17.9Z
2018-11-27T03:39:18.063Z,1543289958.063 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T03:39:18.063Z,1543289958.063 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T03:39:22.037Z,1543289962.037 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20181127T020041/Courier0031.lzma
2018-11-27T03:39:22.836Z,1543289962.836 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0031.lzma.bak
2018-11-27T03:39:22.836Z,1543289962.836 [DataOverHttps](INFO): SBD MOMSN=8924445
2018-11-27T03:39:31.948Z,1543289971.948 [DataOverHttps](INFO): Sending 277 bytes from file Logs/20181127T020041/Express0032.lzma
2018-11-27T03:39:32.720Z,1543289972.720 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0032.lzma.bak
2018-11-27T03:39:32.720Z,1543289972.720 [DataOverHttps](INFO): SBD MOMSN=8924448
2018-11-27T03:39:33.271Z,1543289973.271 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T03:39:33.271Z,1543289973.271 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T03:39:33.271Z,1543289973.271 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T03:39:36.846Z,1543289976.846 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T03:40:07.343Z,1543290007.343 [NAL9602](INFO): Powering down
2018-11-27T03:44:33.655Z,1543290273.655 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T03:44:33.655Z,1543290273.655 [Default:CheckIn:C.Wait] Stopped
2018-11-27T03:44:33.655Z,1543290273.655 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T03:44:33.655Z,1543290273.655 [Default:CheckIn:D] Running Loop=1
2018-11-27T03:44:34.044Z,1543290274.044 [Default:CheckIn:D] Stopped
2018-11-27T03:44:34.044Z,1543290274.044 [Default:CheckIn:E] Running Loop=1
2018-11-27T03:44:34.458Z,1543290274.458 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 100.242212 min 
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn:E] Stopped
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn] Stopped
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn](INFO): Running loop #11
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn] Running Loop=11
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T03:44:34.459Z,1543290274.459 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T03:44:37.767Z,1543290277.767 [NAL9602](INFO): Powering up
2018-11-27T03:44:48.923Z,1543290288.923 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:45:20.915Z,1543290320.915 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-27T03:45:21.002Z,1543290321.002 [NAL9602](FAULT): received: 
+CSQ:0

OK765, 2, 0, 0, 0

OK
2018-11-27T03:45:21.002Z,1543290321.002 [NAL9602] Data Fault, FailCount= 2
2018-11-27T03:45:21.002Z,1543290321.002 [NAL9602](ERROR): Data Fault
2018-11-27T03:45:21.114Z,1543290321.114 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T03:45:21.315Z,1543290321.315 [NAL9602](INFO): Powering down
2018-11-27T03:45:22.169Z,1543290322.169 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T03:45:22.169Z,1543290322.169 [NAL9602] No Fault, FailCount= 2
2018-11-27T03:45:51.455Z,1543290351.455 [NAL9602](INFO): Powering up NAL9602
2018-11-27T03:46:02.655Z,1543290362.655 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:49:34.477Z,1543290574.477 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T03:44:34.5Z
2018-11-27T03:49:34.477Z,1543290574.477 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T03:49:34.477Z,1543290574.477 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T03:49:38.086Z,1543290578.086 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0034.lzma
2018-11-27T03:49:38.868Z,1543290578.868 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0034.lzma.bak
2018-11-27T03:49:38.868Z,1543290578.868 [DataOverHttps](INFO): SBD MOMSN=8924455
2018-11-27T03:49:47.748Z,1543290587.748 [DataOverHttps](INFO): Sending 236 bytes from file Logs/20181127T020041/Express0035.lzma
2018-11-27T03:49:48.540Z,1543290588.540 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0035.lzma.bak
2018-11-27T03:49:48.540Z,1543290588.540 [DataOverHttps](INFO): SBD MOMSN=8924457
2018-11-27T03:49:49.135Z,1543290589.135 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T03:49:49.135Z,1543290589.135 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T03:49:49.135Z,1543290589.135 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T03:49:52.461Z,1543290592.461 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T03:50:22.923Z,1543290622.923 [NAL9602](INFO): Powering down
2018-11-27T03:54:49.820Z,1543290889.820 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T03:54:49.820Z,1543290889.820 [Default:CheckIn:C.Wait] Stopped
2018-11-27T03:54:49.820Z,1543290889.820 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T03:54:49.821Z,1543290889.821 [Default:CheckIn:D] Running Loop=1
2018-11-27T03:54:53.092Z,1543290893.092 [Default:CheckIn:D] Stopped
2018-11-27T03:54:53.092Z,1543290893.092 [Default:CheckIn:E] Running Loop=1
2018-11-27T03:54:53.227Z,1543290893.227 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 110.559676 min 
2018-11-27T03:54:53.227Z,1543290893.227 [Default:CheckIn:E] Stopped
2018-11-27T03:54:53.227Z,1543290893.227 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T03:54:53.227Z,1543290893.227 [Default:CheckIn] Stopped
2018-11-27T03:54:53.227Z,1543290893.227 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T03:54:53.228Z,1543290893.228 [Default:CheckIn](INFO): Running loop #12
2018-11-27T03:54:53.228Z,1543290893.228 [Default:CheckIn] Running Loop=12
2018-11-27T03:54:53.228Z,1543290893.228 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T03:54:53.228Z,1543290893.228 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T03:54:53.951Z,1543290893.951 [NAL9602](INFO): Powering up
2018-11-27T03:55:05.147Z,1543290905.147 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:55:05.947Z,1543290905.947 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T03:55:05.947Z,1543290905.947 [NAL9602] Data Fault, FailCount= 3
2018-11-27T03:55:05.947Z,1543290905.947 [NAL9602](ERROR): Data Fault
2018-11-27T03:55:06.029Z,1543290906.029 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T03:55:06.347Z,1543290906.347 [NAL9602](INFO): Powering down
2018-11-27T03:55:07.196Z,1543290907.196 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T03:55:07.196Z,1543290907.196 [NAL9602] No Fault, FailCount= 3
2018-11-27T03:55:36.750Z,1543290936.750 [NAL9602](INFO): Powering up NAL9602
2018-11-27T03:55:47.951Z,1543290947.951 [NAL9602](INFO): NAL9602 initialized
2018-11-27T03:59:53.388Z,1543291193.388 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T03:54:53.2Z
2018-11-27T03:59:53.388Z,1543291193.388 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T03:59:53.389Z,1543291193.389 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T03:59:59.190Z,1543291199.190 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0037.lzma
2018-11-27T03:59:59.956Z,1543291199.956 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0037.lzma.bak
2018-11-27T03:59:59.956Z,1543291199.956 [DataOverHttps](INFO): SBD MOMSN=8924462
2018-11-27T04:00:03.893Z,1543291203.893 [NAL9602](INFO): SBD MO Status=2, MOMSN=10765, MT Status=2, MTMSN=0
2018-11-27T04:00:03.893Z,1543291203.893 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:00:08.821Z,1543291208.821 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20181127T020041/Express0038.lzma
2018-11-27T04:00:09.612Z,1543291209.612 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0038.lzma.bak
2018-11-27T04:00:09.612Z,1543291209.612 [DataOverHttps](INFO): SBD MOMSN=8924464
2018-11-27T04:00:10.184Z,1543291210.184 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T04:00:10.184Z,1543291210.184 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T04:00:10.184Z,1543291210.184 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T04:01:02.224Z,1543291262.224 [NAL9602](INFO): SBD MO Status=2, MOMSN=10765, MT Status=2, MTMSN=0
2018-11-27T04:01:02.224Z,1543291262.224 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:01:02.596Z,1543291262.596 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T04:01:33.367Z,1543291293.367 [NAL9602](INFO): Powering down
2018-11-27T04:05:10.533Z,1543291510.533 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T04:05:10.534Z,1543291510.534 [Default:CheckIn:C.Wait] Stopped
2018-11-27T04:05:10.534Z,1543291510.534 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T04:05:10.534Z,1543291510.534 [Default:CheckIn:D] Running Loop=1
2018-11-27T04:05:10.935Z,1543291510.935 [Default:CheckIn:D] Stopped
2018-11-27T04:05:10.935Z,1543291510.935 [Default:CheckIn:E] Running Loop=1
2018-11-27T04:05:11.347Z,1543291511.347 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 120.857064 min 
2018-11-27T04:05:11.347Z,1543291511.347 [Default:CheckIn:E] Stopped
2018-11-27T04:05:11.348Z,1543291511.348 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T04:05:11.348Z,1543291511.348 [Default:CheckIn] Stopped
2018-11-27T04:05:11.348Z,1543291511.348 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T04:05:11.348Z,1543291511.348 [Default:CheckIn](INFO): Running loop #13
2018-11-27T04:05:11.348Z,1543291511.348 [Default:CheckIn] Running Loop=13
2018-11-27T04:05:11.348Z,1543291511.348 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T04:05:11.348Z,1543291511.348 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T04:05:14.522Z,1543291514.522 [NAL9602](INFO): Powering up
2018-11-27T04:05:25.675Z,1543291525.675 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:08:44.820Z,1543291724.820 [NAL9602](INFO): SBD MO Status=0, MOMSN=10765, MT Status=0, MTMSN=0
2018-11-27T04:08:44.820Z,1543291724.820 [NAL9602](INFO): No messages in MT queue
2018-11-27T04:08:45.623Z,1543291725.623 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T04:08:45.623Z,1543291725.623 [NAL9602] Data Fault, FailCount= 1
2018-11-27T04:08:45.623Z,1543291725.623 [NAL9602](ERROR): Data Fault
2018-11-27T04:08:45.691Z,1543291725.691 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T04:08:46.023Z,1543291726.023 [NAL9602](INFO): Powering down
2018-11-27T04:08:46.873Z,1543291726.873 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T04:08:46.873Z,1543291726.873 [NAL9602] No Fault, FailCount= 1
2018-11-27T04:09:16.419Z,1543291756.419 [NAL9602](INFO): Powering up NAL9602
2018-11-27T04:09:27.619Z,1543291767.619 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:10:11.661Z,1543291811.661 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T04:05:11.3Z
2018-11-27T04:10:11.662Z,1543291811.662 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T04:10:11.662Z,1543291811.662 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T04:10:15.690Z,1543291815.690 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0040.lzma
2018-11-27T04:10:16.476Z,1543291816.476 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0040.lzma.bak
2018-11-27T04:10:16.476Z,1543291816.476 [DataOverHttps](INFO): SBD MOMSN=8924469
2018-11-27T04:10:25.305Z,1543291825.305 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20181127T020041/Express0041.lzma
2018-11-27T04:10:26.072Z,1543291826.072 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0041.lzma.bak
2018-11-27T04:10:26.072Z,1543291826.072 [DataOverHttps](INFO): SBD MOMSN=8924472
2018-11-27T04:10:26.622Z,1543291826.622 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T04:10:26.622Z,1543291826.622 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T04:10:26.622Z,1543291826.622 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T04:10:45.930Z,1543291845.930 [NAL9602](INFO): Powering down
2018-11-27T04:15:26.956Z,1543292126.956 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T04:15:26.956Z,1543292126.956 [Default:CheckIn:C.Wait] Stopped
2018-11-27T04:15:26.956Z,1543292126.956 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T04:15:26.956Z,1543292126.956 [Default:CheckIn:D] Running Loop=1
2018-11-27T04:15:27.364Z,1543292127.364 [Default:CheckIn:D] Stopped
2018-11-27T04:15:27.364Z,1543292127.364 [Default:CheckIn:E] Running Loop=1
2018-11-27T04:15:30.463Z,1543292130.463 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 131.130868 min 
2018-11-27T04:15:30.463Z,1543292130.463 [Default:CheckIn:E] Stopped
2018-11-27T04:15:30.463Z,1543292130.463 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T04:15:30.463Z,1543292130.463 [Default:CheckIn] Stopped
2018-11-27T04:15:30.464Z,1543292130.464 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T04:15:30.464Z,1543292130.464 [Default:CheckIn](INFO): Running loop #14
2018-11-27T04:15:30.464Z,1543292130.464 [Default:CheckIn] Running Loop=14
2018-11-27T04:15:30.464Z,1543292130.464 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T04:15:30.464Z,1543292130.464 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T04:15:30.887Z,1543292130.887 [NAL9602](INFO): Powering up
2018-11-27T04:15:42.087Z,1543292142.087 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:17:48.948Z,1543292268.948 [NAL9602](INFO): SBD MO Status=2, MOMSN=10766, MT Status=2, MTMSN=0
2018-11-27T04:17:48.948Z,1543292268.948 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:18:19.756Z,1543292299.756 [NAL9602](INFO): SBD MO Status=2, MOMSN=10766, MT Status=2, MTMSN=0
2018-11-27T04:18:19.756Z,1543292299.756 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:18:59.124Z,1543292339.124 [NAL9602](INFO): SBD MO Status=2, MOMSN=10766, MT Status=2, MTMSN=0
2018-11-27T04:18:59.124Z,1543292339.124 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:19:17.124Z,1543292357.124 [NAL9602](INFO): SBD MO Status=0, MOMSN=10766, MT Status=0, MTMSN=0
2018-11-27T04:19:17.124Z,1543292357.124 [NAL9602](INFO): No messages in MT queue
2018-11-27T04:19:31.927Z,1543292371.927 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T04:19:31.927Z,1543292371.927 [NAL9602] Data Fault, FailCount= 1
2018-11-27T04:19:31.927Z,1543292371.927 [NAL9602](ERROR): Data Fault
2018-11-27T04:19:32.022Z,1543292372.022 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T04:19:32.327Z,1543292372.327 [NAL9602](INFO): Powering down
2018-11-27T04:19:33.200Z,1543292373.200 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T04:19:33.201Z,1543292373.201 [NAL9602] No Fault, FailCount= 1
2018-11-27T04:20:02.723Z,1543292402.723 [NAL9602](INFO): Powering up NAL9602
2018-11-27T04:20:13.923Z,1543292413.923 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:20:31.886Z,1543292431.886 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T04:15:30.5Z
2018-11-27T04:20:31.886Z,1543292431.886 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T04:20:31.886Z,1543292431.886 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T04:20:36.717Z,1543292436.717 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0043.lzma
2018-11-27T04:20:37.516Z,1543292437.516 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0043.lzma.bak
2018-11-27T04:20:37.516Z,1543292437.516 [DataOverHttps](INFO): SBD MOMSN=8924477
2018-11-27T04:20:46.378Z,1543292446.378 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20181127T020041/Express0044.lzma
2018-11-27T04:20:47.152Z,1543292447.152 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0044.lzma.bak
2018-11-27T04:20:47.152Z,1543292447.152 [DataOverHttps](INFO): SBD MOMSN=8924479
2018-11-27T04:20:47.705Z,1543292447.705 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T04:20:47.705Z,1543292447.705 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T04:20:47.705Z,1543292447.705 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T04:21:03.927Z,1543292463.927 [NAL9602](INFO): Powering down
2018-11-27T04:25:48.241Z,1543292748.241 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T04:25:48.241Z,1543292748.241 [Default:CheckIn:C.Wait] Stopped
2018-11-27T04:25:48.241Z,1543292748.241 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T04:25:48.242Z,1543292748.242 [Default:CheckIn:D] Running Loop=1
2018-11-27T04:25:48.644Z,1543292748.644 [Default:CheckIn:D] Stopped
2018-11-27T04:25:48.644Z,1543292748.644 [Default:CheckIn:E] Running Loop=1
2018-11-27T04:25:49.019Z,1543292749.019 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 141.485531 min 
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn:E] Stopped
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn] Stopped
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn](INFO): Running loop #15
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn] Running Loop=15
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T04:25:49.020Z,1543292749.020 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T04:25:52.638Z,1543292752.638 [NAL9602](INFO): Powering up
2018-11-27T04:26:03.495Z,1543292763.495 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:26:52.776Z,1543292812.776 [NAL9602](INFO): SBD MO Status=2, MOMSN=10767, MT Status=2, MTMSN=0
2018-11-27T04:26:52.776Z,1543292812.776 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:27:36.864Z,1543292856.864 [NAL9602](INFO): SBD MO Status=0, MOMSN=10767, MT Status=0, MTMSN=0
2018-11-27T04:27:36.864Z,1543292856.864 [NAL9602](INFO): No messages in MT queue
2018-11-27T04:28:34.454Z,1543292914.454 [NAL9602](INFO): GPS fix at 20181127T042459: (36.802751, -121.787993)
2018-11-27T04:28:34.510Z,1543292914.510 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T04:28:34.511Z,1543292914.511 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T04:28:39.963Z,1543292919.963 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181127T020041/Courier0046.lzma
2018-11-27T04:28:40.750Z,1543292920.750 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0046.lzma.bak
2018-11-27T04:28:40.750Z,1543292920.750 [DataOverHttps](INFO): SBD MOMSN=8924484
2018-11-27T04:28:53.683Z,1543292933.683 [DataOverHttps](INFO): Sending 136 bytes from file Logs/20181127T020041/Express0047.lzma
2018-11-27T04:28:54.484Z,1543292934.484 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0047.lzma.bak
2018-11-27T04:28:54.484Z,1543292934.484 [DataOverHttps](INFO): SBD MOMSN=8924487
2018-11-27T04:28:55.043Z,1543292935.043 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T04:28:55.043Z,1543292935.043 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T04:28:55.043Z,1543292935.043 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T04:29:10.163Z,1543292950.163 [NAL9602](INFO): Powering down
2018-11-27T04:33:55.658Z,1543293235.658 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T04:33:55.659Z,1543293235.659 [Default:CheckIn:C.Wait] Stopped
2018-11-27T04:33:55.659Z,1543293235.659 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T04:33:55.659Z,1543293235.659 [Default:CheckIn:D] Running Loop=1
2018-11-27T04:33:56.068Z,1543293236.068 [Default:CheckIn:D] Stopped
2018-11-27T04:33:56.068Z,1543293236.068 [Default:CheckIn:E] Running Loop=1
2018-11-27T04:33:56.464Z,1543293236.464 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 149.609261 min 
2018-11-27T04:33:56.464Z,1543293236.464 [Default:CheckIn:E] Stopped
2018-11-27T04:33:56.464Z,1543293236.464 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T04:33:56.464Z,1543293236.464 [Default:CheckIn] Stopped
2018-11-27T04:33:56.465Z,1543293236.465 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T04:33:56.465Z,1543293236.465 [Default:CheckIn](INFO): Running loop #16
2018-11-27T04:33:56.465Z,1543293236.465 [Default:CheckIn] Running Loop=16
2018-11-27T04:33:56.465Z,1543293236.465 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T04:33:56.465Z,1543293236.465 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T04:33:59.815Z,1543293239.815 [NAL9602](INFO): Powering up
2018-11-27T04:34:10.993Z,1543293250.993 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:36:51.929Z,1543293411.929 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:36:51.929Z,1543293411.929 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:37:37.692Z,1543293457.692 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:37:37.692Z,1543293457.692 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:37:54.892Z,1543293474.892 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:37:54.892Z,1543293474.892 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:38:08.112Z,1543293488.112 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:38:08.112Z,1543293488.112 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:38:52.116Z,1543293532.116 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:38:52.116Z,1543293532.116 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:38:56.571Z,1543293536.571 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T04:33:56.5Z
2018-11-27T04:38:56.571Z,1543293536.571 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T04:38:56.571Z,1543293536.571 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T04:39:00.670Z,1543293540.670 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0049.lzma
2018-11-27T04:39:01.448Z,1543293541.448 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0049.lzma.bak
2018-11-27T04:39:01.448Z,1543293541.448 [DataOverHttps](INFO): SBD MOMSN=8924491
2018-11-27T04:39:07.060Z,1543293547.060 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:39:07.060Z,1543293547.060 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:39:10.279Z,1543293550.279 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181127T020041/Express0050.lzma
2018-11-27T04:39:11.060Z,1543293551.060 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0050.lzma.bak
2018-11-27T04:39:11.060Z,1543293551.060 [DataOverHttps](INFO): SBD MOMSN=8924493
2018-11-27T04:39:11.627Z,1543293551.627 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T04:39:11.627Z,1543293551.627 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T04:39:11.627Z,1543293551.627 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T04:39:15.054Z,1543293555.054 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T04:39:45.543Z,1543293585.543 [NAL9602](INFO): Powering down
2018-11-27T04:44:12.183Z,1543293852.183 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T04:44:12.183Z,1543293852.183 [Default:CheckIn:C.Wait] Stopped
2018-11-27T04:44:12.183Z,1543293852.183 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T04:44:12.183Z,1543293852.183 [Default:CheckIn:D] Running Loop=1
2018-11-27T04:44:12.581Z,1543293852.581 [Default:CheckIn:D] Stopped
2018-11-27T04:44:12.581Z,1543293852.581 [Default:CheckIn:E] Running Loop=1
2018-11-27T04:44:12.986Z,1543293852.986 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 159.884489 min 
2018-11-27T04:44:12.986Z,1543293852.986 [Default:CheckIn:E] Stopped
2018-11-27T04:44:12.986Z,1543293852.986 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T04:44:12.986Z,1543293852.986 [Default:CheckIn] Stopped
2018-11-27T04:44:12.986Z,1543293852.986 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T04:44:12.986Z,1543293852.986 [Default:CheckIn](INFO): Running loop #17
2018-11-27T04:44:12.987Z,1543293852.987 [Default:CheckIn] Running Loop=17
2018-11-27T04:44:12.987Z,1543293852.987 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T04:44:12.987Z,1543293852.987 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T04:44:16.175Z,1543293856.175 [NAL9602](INFO): Powering up
2018-11-27T04:44:27.323Z,1543293867.323 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:44:28.123Z,1543293868.123 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T04:44:28.123Z,1543293868.123 [NAL9602] Data Fault, FailCount= 1
2018-11-27T04:44:28.123Z,1543293868.123 [NAL9602](ERROR): Data Fault
2018-11-27T04:44:28.208Z,1543293868.208 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T04:44:28.523Z,1543293868.523 [NAL9602](INFO): Powering down
2018-11-27T04:44:29.401Z,1543293869.401 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T04:44:29.402Z,1543293869.402 [NAL9602] No Fault, FailCount= 1
2018-11-27T04:44:58.923Z,1543293898.923 [NAL9602](INFO): Powering up NAL9602
2018-11-27T04:45:10.123Z,1543293910.123 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:46:18.972Z,1543293978.972 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:46:18.972Z,1543293978.972 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:47:05.372Z,1543294025.372 [NAL9602](INFO): SBD MO Status=2, MOMSN=10768, MT Status=2, MTMSN=0
2018-11-27T04:47:05.372Z,1543294025.372 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:47:34.548Z,1543294054.548 [NAL9602](INFO): SBD MO Status=0, MOMSN=10768, MT Status=0, MTMSN=0
2018-11-27T04:47:34.548Z,1543294054.548 [NAL9602](INFO): No messages in MT queue
2018-11-27T04:47:38.560Z,1543294058.560 [NAL9602](INFO): GPS fix at 20181127T044403: (36.802738, -121.788029)
2018-11-27T04:47:38.623Z,1543294058.623 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T04:47:38.623Z,1543294058.623 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T04:47:51.779Z,1543294071.779 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181127T020041/Courier0052.lzma
2018-11-27T04:47:52.556Z,1543294072.556 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0052.lzma.bak
2018-11-27T04:47:52.556Z,1543294072.556 [DataOverHttps](INFO): SBD MOMSN=8924496
2018-11-27T04:48:01.465Z,1543294081.465 [DataOverHttps](INFO): Sending 217 bytes from file Logs/20181127T020041/Express0053.lzma
2018-11-27T04:48:02.244Z,1543294082.244 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0053.lzma.bak
2018-11-27T04:48:02.244Z,1543294082.244 [DataOverHttps](INFO): SBD MOMSN=8924499
2018-11-27T04:48:02.790Z,1543294082.790 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T04:48:02.790Z,1543294082.790 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T04:48:02.790Z,1543294082.790 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T04:48:10.627Z,1543294090.627 [NAL9602](INFO): Powering down
2018-11-27T04:53:03.135Z,1543294383.135 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T04:53:03.135Z,1543294383.135 [Default:CheckIn:C.Wait] Stopped
2018-11-27T04:53:03.135Z,1543294383.135 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T04:53:03.135Z,1543294383.135 [Default:CheckIn:D] Running Loop=1
2018-11-27T04:53:03.525Z,1543294383.525 [Default:CheckIn:D] Stopped
2018-11-27T04:53:03.526Z,1543294383.526 [Default:CheckIn:E] Running Loop=1
2018-11-27T04:53:03.931Z,1543294383.931 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 168.733561 min 
2018-11-27T04:53:03.931Z,1543294383.931 [Default:CheckIn:E] Stopped
2018-11-27T04:53:03.931Z,1543294383.931 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T04:53:03.931Z,1543294383.931 [Default:CheckIn] Stopped
2018-11-27T04:53:03.931Z,1543294383.931 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T04:53:03.932Z,1543294383.932 [Default:CheckIn](INFO): Running loop #18
2018-11-27T04:53:03.932Z,1543294383.932 [Default:CheckIn] Running Loop=18
2018-11-27T04:53:03.932Z,1543294383.932 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T04:53:03.932Z,1543294383.932 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T04:53:07.128Z,1543294387.128 [NAL9602](INFO): Powering up
2018-11-27T04:53:18.295Z,1543294398.295 [NAL9602](INFO): NAL9602 initialized
2018-11-27T04:54:39.192Z,1543294479.192 [NAL9602](INFO): SBD MO Status=2, MOMSN=10769, MT Status=2, MTMSN=0
2018-11-27T04:54:39.192Z,1543294479.192 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:58:02.884Z,1543294682.884 [NAL9602](INFO): SBD MO Status=2, MOMSN=10769, MT Status=2, MTMSN=0
2018-11-27T04:58:02.884Z,1543294682.884 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T04:58:04.139Z,1543294684.139 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T04:53:03.9Z
2018-11-27T04:58:04.139Z,1543294684.139 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T04:58:04.139Z,1543294684.139 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T04:58:07.756Z,1543294687.756 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0055.lzma
2018-11-27T04:58:08.558Z,1543294688.558 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0055.lzma.bak
2018-11-27T04:58:08.558Z,1543294688.558 [DataOverHttps](INFO): SBD MOMSN=8924506
2018-11-27T04:58:17.543Z,1543294697.543 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181127T020041/Express0056.lzma
2018-11-27T04:58:18.344Z,1543294698.344 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0056.lzma.bak
2018-11-27T04:58:18.344Z,1543294698.344 [DataOverHttps](INFO): SBD MOMSN=8924508
2018-11-27T04:58:18.899Z,1543294698.899 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T04:58:18.899Z,1543294698.899 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T04:58:18.899Z,1543294698.899 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T04:58:22.368Z,1543294702.368 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T04:58:52.823Z,1543294732.823 [NAL9602](INFO): Powering down
2018-11-27T05:03:19.512Z,1543294999.512 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T05:03:19.513Z,1543294999.513 [Default:CheckIn:C.Wait] Stopped
2018-11-27T05:03:19.513Z,1543294999.513 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T05:03:19.513Z,1543294999.513 [Default:CheckIn:D] Running Loop=1
2018-11-27T05:03:19.920Z,1543294999.920 [Default:CheckIn:D] Stopped
2018-11-27T05:03:19.920Z,1543294999.920 [Default:CheckIn:E] Running Loop=1
2018-11-27T05:03:23.025Z,1543295003.025 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 179.006820 min 
2018-11-27T05:03:23.025Z,1543295003.025 [Default:CheckIn:E] Stopped
2018-11-27T05:03:23.025Z,1543295003.025 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T05:03:23.026Z,1543295003.026 [Default:CheckIn] Stopped
2018-11-27T05:03:23.026Z,1543295003.026 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T05:03:23.026Z,1543295003.026 [Default:CheckIn](INFO): Running loop #19
2018-11-27T05:03:23.026Z,1543295003.026 [Default:CheckIn] Running Loop=19
2018-11-27T05:03:23.026Z,1543295003.026 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T05:03:23.026Z,1543295003.026 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T05:03:23.451Z,1543295003.451 [NAL9602](INFO): Powering up
2018-11-27T05:03:34.651Z,1543295014.651 [NAL9602](INFO): NAL9602 initialized
2018-11-27T05:03:35.455Z,1543295015.455 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T05:03:35.455Z,1543295015.455 [NAL9602] Data Fault, FailCount= 1
2018-11-27T05:03:35.455Z,1543295015.455 [NAL9602](ERROR): Data Fault
2018-11-27T05:03:35.558Z,1543295015.558 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T05:03:35.851Z,1543295015.851 [NAL9602](INFO): Powering down
2018-11-27T05:03:36.704Z,1543295016.704 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T05:03:36.704Z,1543295016.704 [NAL9602] No Fault, FailCount= 1
2018-11-27T05:04:06.251Z,1543295046.251 [NAL9602](INFO): Powering up NAL9602
2018-11-27T05:04:17.455Z,1543295057.455 [NAL9602](INFO): NAL9602 initialized
2018-11-27T05:05:09.453Z,1543295109.453 [NAL9602](INFO): SBD MO Status=2, MOMSN=10769, MT Status=2, MTMSN=0
2018-11-27T05:05:09.453Z,1543295109.453 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-27T05:08:24.484Z,1543295304.484 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-27T05:03:23.0Z
2018-11-27T05:08:24.484Z,1543295304.484 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T05:08:24.484Z,1543295304.484 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-27T05:08:29.328Z,1543295309.328 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181127T020041/Courier0058.lzma
2018-11-27T05:08:30.130Z,1543295310.130 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Courier0058.lzma.bak
2018-11-27T05:08:30.130Z,1543295310.130 [DataOverHttps](INFO): SBD MOMSN=8924512
2018-11-27T05:08:41.555Z,1543295321.555 [DataOverHttps](INFO): Sending 217 bytes from file Logs/20181127T020041/Express0059.lzma
2018-11-27T05:08:42.356Z,1543295322.356 [DataOverHttps](INFO): Moved sent file to Logs/20181127T020041/Express0059.lzma.bak
2018-11-27T05:08:42.356Z,1543295322.356 [DataOverHttps](INFO): SBD MOMSN=8924514
2018-11-27T05:08:43.035Z,1543295323.035 [Default:CheckIn:Read_Iridium] Stopped
2018-11-27T05:08:43.035Z,1543295323.035 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-27T05:08:43.035Z,1543295323.035 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-27T05:09:23.467Z,1543295363.467 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-27T05:09:54.255Z,1543295394.255 [NAL9602](INFO): Powering down
2018-11-27T05:13:43.602Z,1543295623.602 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-27T05:13:43.603Z,1543295623.603 [Default:CheckIn:C.Wait] Stopped
2018-11-27T05:13:43.603Z,1543295623.603 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-27T05:13:43.603Z,1543295623.603 [Default:CheckIn:D] Running Loop=1
2018-11-27T05:13:44.003Z,1543295624.003 [Default:CheckIn:D] Stopped
2018-11-27T05:13:44.003Z,1543295624.003 [Default:CheckIn:E] Running Loop=1
2018-11-27T05:13:44.403Z,1543295624.403 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 189.408203 min 
2018-11-27T05:13:44.403Z,1543295624.403 [Default:CheckIn:E] Stopped
2018-11-27T05:13:44.403Z,1543295624.403 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-27T05:13:44.403Z,1543295624.403 [Default:CheckIn] Stopped
2018-11-27T05:13:44.403Z,1543295624.403 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T05:13:44.404Z,1543295624.404 [Default:CheckIn](INFO): Running loop #20
2018-11-27T05:13:44.404Z,1543295624.404 [Default:CheckIn] Running Loop=20
2018-11-27T05:13:44.404Z,1543295624.404 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-27T05:13:44.404Z,1543295624.404 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-27T05:13:47.847Z,1543295627.847 [NAL9602](INFO): Powering up
2018-11-27T05:13:59.019Z,1543295639.019 [NAL9602](INFO): NAL9602 initialized
2018-11-27T05:14:31.019Z,1543295671.019 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-27T05:14:31.101Z,1543295671.101 [NAL9602](FAULT): received: 
+CSQ:0

OK769, 2, 0, 0, 0

OK
2018-11-27T05:14:31.102Z,1543295671.102 [NAL9602] Data Fault, FailCount= 2
2018-11-27T05:14:31.102Z,1543295671.102 [NAL9602](ERROR): Data Fault
2018-11-27T05:14:31.184Z,1543295671.184 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T05:14:31.419Z,1543295671.419 [NAL9602](INFO): Powering down
2018-11-27T05:14:32.276Z,1543295672.276 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T05:14:32.276Z,1543295672.276 [NAL9602] No Fault, FailCount= 2
2018-11-27T05:15:01.787Z,1543295701.787 [NAL9602](INFO): Powering up NAL9602
2018-11-27T05:15:12.987Z,1543295712.987 [NAL9602](INFO): NAL9602 initialized
2018-11-27T05:15:13.790Z,1543295713.790 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-27T05:15:13.791Z,1543295713.791 [NAL9602] Data Fault, FailCount= 3
2018-11-27T05:15:13.791Z,1543295713.791 [NAL9602](ERROR): Data Fault
2018-11-27T05:15:13.847Z,1543295713.847 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-27T05:15:14.187Z,1543295714.187 [NAL9602](INFO): Powering down
2018-11-27T05:15:15.032Z,1543295715.032 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-27T05:15:15.032Z,1543295715.032 [NAL9602] No Fault, FailCount= 3
2018-11-27T05:15:44.587Z,1543295744.587 [NAL9602](INFO): Powering up NAL9602
2018-11-27T05:15:55.383Z,1543295755.383 [NAL9602](INFO): NAL9602 initialized
2018-11-27T05:18:30.599Z,1543295910.599 [CommandLine](IMPORTANT): got command restart application
2018-11-27T05:18:31.608Z,1543295911.608 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:31.608Z,1543295911.608 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:31.797Z,1543295911.797 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2018-11-27T05:18:31.798Z,1543295911.798 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:31.798Z,1543295911.798 [CommandLine](INFO): Join timeout helper Thread ID is 7000
2018-11-27T05:18:31.799Z,1543295911.799 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-11-27T05:18:31.799Z,1543295911.799 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:31.800Z,1543295911.800 [NavChartDb](INFO): Join timeout helper Thread ID is 7001
2018-11-27T05:18:31.910Z,1543295911.910 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:31.910Z,1543295911.910 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:31.918Z,1543295911.918 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-11-27T05:18:31.918Z,1543295911.918 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:31.918Z,1543295911.918 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 7002
2018-11-27T05:18:32.366Z,1543295912.366 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:32.366Z,1543295912.366 [WetLabsBB2FL](INFO): Powering down
2018-11-27T05:18:32.367Z,1543295912.367 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:32.378Z,1543295912.378 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-11-27T05:18:32.378Z,1543295912.378 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:32.378Z,1543295912.378 [CTD_Seabird](INFO): Join timeout helper Thread ID is 7003
2018-11-27T05:18:33.098Z,1543295913.098 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:33.098Z,1543295913.098 [CTD_Seabird](INFO): Powering down
2018-11-27T05:18:33.114Z,1543295913.114 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.134Z,1543295913.134 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-11-27T05:18:33.134Z,1543295913.134 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.134Z,1543295913.134 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 7004
2018-11-27T05:18:33.226Z,1543295913.226 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:33.226Z,1543295913.226 [CTD_NeilBrown](INFO): Powering down
2018-11-27T05:18:33.238Z,1543295913.238 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.246Z,1543295913.246 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-11-27T05:18:33.246Z,1543295913.246 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.247Z,1543295913.247 [Radio_Surface](INFO): Join timeout helper Thread ID is 7005
2018-11-27T05:18:33.314Z,1543295913.314 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:33.314Z,1543295913.314 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.326Z,1543295913.326 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-11-27T05:18:33.327Z,1543295913.327 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.327Z,1543295913.327 [logger](INFO): Join timeout helper Thread ID is 7006
2018-11-27T05:18:33.330Z,1543295913.330 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:33.330Z,1543295913.330 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.346Z,1543295913.346 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-11-27T05:18:33.346Z,1543295913.346 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.346Z,1543295913.346 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-11-27T05:18:33.347Z,1543295913.347 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.347Z,1543295913.347 [controlThread](INFO): Join timeout helper Thread ID is 7007
2018-11-27T05:18:33.506Z,1543295913.506 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-27T05:18:33.506Z,1543295913.506 [controlThread](DEBUG): Uninitializing ControlThread
2018-11-27T05:18:33.507Z,1543295913.507 [NAL9602](INFO): Powering down
2018-11-27T05:18:33.508Z,1543295913.508 [PNI_TCM](INFO): Powering down
2018-11-27T05:18:33.594Z,1543295913.594 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2018-11-27T05:18:33.595Z,1543295913.595 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-11-27T05:18:33.596Z,1543295913.596 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-11-27T05:18:33.596Z,1543295913.596 [MissionManager](INFO): Uninitializing Mission Default
2018-11-27T05:18:33.596Z,1543295913.596 [Default] Stopped
2018-11-27T05:18:33.596Z,1543295913.596 [Default](DEBUG): Aggregate::uninitialize Default
2018-11-27T05:18:33.596Z,1543295913.596 [Default:B.GoToSurface] Stopped
2018-11-27T05:18:33.596Z,1543295913.596 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-27T05:18:33.596Z,1543295913.596 [Default:CheckIn] Stopped
2018-11-27T05:18:33.597Z,1543295913.597 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-27T05:18:33.597Z,1543295913.597 [Default:CheckIn:Read_GPS] Stopped
2018-11-27T05:18:33.600Z,1543295913.600 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-11-27T05:18:33.600Z,1543295913.600 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-11-27T05:18:33.600Z,1543295913.600 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-11-27T05:18:33.600Z,1543295913.600 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-11-27T05:18:33.601Z,1543295913.601 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-11-27T05:18:33.601Z,1543295913.601 [BuoyancyServo](INFO): Powering down
2018-11-27T05:18:33.614Z,1543295913.614 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-11-27T05:18:33.614Z,1543295913.614 [ElevatorServo](INFO): Powering down
2018-11-27T05:18:33.614Z,1543295913.614 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-11-27T05:18:33.615Z,1543295913.615 [MassServo](INFO): Powering down
2018-11-27T05:18:33.615Z,1543295913.615 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-11-27T05:18:33.615Z,1543295913.615 [RudderServo](INFO): Powering down
2018-11-27T05:18:33.616Z,1543295913.616 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-11-27T05:18:33.616Z,1543295913.616 [ThrusterServo](INFO): Powering down
2018-11-27T05:18:33.617Z,1543295913.617 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-11-27T05:18:33.617Z,1543295913.617 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-11-27T05:18:33.618Z,1543295913.618 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-11-27T05:18:33.618Z,1543295913.618 [CBIT](DEBUG): Powering off loads.
2018-11-27T05:18:33.629Z,1543295913.629 [CBIT](DEBUG): Disabling WDT.
2018-11-27T05:18:33.641Z,1543295913.641 [CBIT](DEBUG): Opening all GF detection circuits.
2018-11-27T05:18:33.642Z,1543295913.642 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.690Z,1543295913.690 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.734Z,1543295913.734 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.737Z,1543295913.737 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.740Z,1543295913.740 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.772Z,1543295913.772 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-27T05:18:33.840Z,1543295913.840 [logger ThreadHandler](INFO): Thread cancelled.