2018-11-02T18:33:34.812Z,1541183614.812 [Supervisor](DEBUG): Initializing supervisor.
2018-11-02T18:33:34.814Z,1541183614.814 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-11-02T18:33:34.815Z,1541183614.815 [SyncHandler](INFO): Protected caller Thread ID is 797
2018-11-02T18:33:34.815Z,1541183614.815 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-11-02T18:33:34.816Z,1541183614.816 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-11-02T18:33:34.817Z,1541183614.817 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 798
2018-11-02T18:33:34.819Z,1541183614.819 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-11-02T18:33:34.831Z,1541183614.831 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-11-02T18:33:34.832Z,1541183614.832 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-11-02T18:33:34.833Z,1541183614.833 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 799
2018-11-02T18:33:34.834Z,1541183614.834 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-11-02T18:33:34.835Z,1541183614.835 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-11-02T18:33:34.835Z,1541183614.835 [logger ThreadHandler](INFO): Protected caller Thread ID is 800
2018-11-02T18:33:34.837Z,1541183614.837 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-11-02T18:33:34.837Z,1541183614.837 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-11-02T18:33:34.841Z,1541183614.841 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-11-02T18:33:35.195Z,1541183615.195 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-11-02T18:33:35.197Z,1541183615.197 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-11-02T18:33:35.414Z,1541183615.414 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-11-02T18:33:35.416Z,1541183615.416 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-11-02T18:33:35.735Z,1541183615.735 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-11-02T18:33:35.737Z,1541183615.737 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-11-02T18:33:35.890Z,1541183615.890 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-11-02T18:33:35.890Z,1541183615.890 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-11-02T18:33:35.992Z,1541183615.992 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-11-02T18:33:35.993Z,1541183615.993 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-11-02T18:33:36.480Z,1541183616.480 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-11-02T18:33:36.482Z,1541183616.482 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-11-02T18:33:36.976Z,1541183616.976 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-11-02T18:33:36.977Z,1541183616.977 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-11-02T18:33:37.472Z,1541183617.472 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-11-02T18:33:37.474Z,1541183617.474 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-11-02T18:33:37.581Z,1541183617.581 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-11-02T18:33:37.582Z,1541183617.582 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-11-02T18:33:37.682Z,1541183617.682 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-11-02T18:33:37.682Z,1541183617.682 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-11-02T18:33:37.913Z,1541183617.913 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-11-02T18:33:37.915Z,1541183617.915 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-11-02T18:33:38.131Z,1541183618.131 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-11-02T18:33:38.131Z,1541183618.131 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-11-02T18:33:38.506Z,1541183618.506 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-11-02T18:33:38.506Z,1541183618.506 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-11-02T18:33:39.367Z,1541183619.367 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-11-02T18:33:39.369Z,1541183619.369 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-11-02T18:33:39.453Z,1541183619.453 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-11-02T18:33:39.456Z,1541183619.456 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-11-02T18:33:39.564Z,1541183619.564 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-11-02T18:33:39.688Z,1541183619.688 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-11-02T18:33:39.787Z,1541183619.787 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-11-02T18:33:39.874Z,1541183619.874 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-11-02T18:33:40.050Z,1541183620.050 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-11-02T18:33:40.243Z,1541183620.243 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-11-02T18:33:40.320Z,1541183620.320 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-11-02T18:33:40.556Z,1541183620.556 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-11-02T18:33:40.557Z,1541183620.557 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-11-02T18:33:40.642Z,1541183620.642 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-11-02T18:33:40.737Z,1541183620.737 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-11-02T18:33:40.842Z,1541183620.842 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-11-02T18:33:40.975Z,1541183620.975 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-11-02T18:33:40.992Z,1541183620.992 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-11-02T18:33:41.278Z,1541183621.278 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-11-02T18:33:41.279Z,1541183621.279 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-11-02T18:33:41.335Z,1541183621.335 [DepthRateCalculator] Loaded
2018-11-02T18:33:41.336Z,1541183621.336 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-11-02T18:33:41.342Z,1541183621.342 [PitchRateCalculator] Loaded
2018-11-02T18:33:41.342Z,1541183621.342 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-11-02T18:33:41.359Z,1541183621.359 [SpeedCalculator] Loaded
2018-11-02T18:33:41.359Z,1541183621.359 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-11-02T18:33:41.380Z,1541183621.380 [TempGradientCalculator] Loaded
2018-11-02T18:33:41.381Z,1541183621.381 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-11-02T18:33:41.387Z,1541183621.387 [YawRateCalculator] Loaded
2018-11-02T18:33:41.387Z,1541183621.387 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-11-02T18:33:41.427Z,1541183621.427 [ElevatorOffsetCalculator] Loaded
2018-11-02T18:33:41.427Z,1541183621.427 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-11-02T18:33:41.427Z,1541183621.427 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-11-02T18:33:41.428Z,1541183621.428 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-11-02T18:33:41.531Z,1541183621.531 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-11-02T18:33:41.532Z,1541183621.532 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-11-02T18:33:41.666Z,1541183621.666 [BuoyancyServo] Loaded
2018-11-02T18:33:41.666Z,1541183621.666 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-11-02T18:33:41.681Z,1541183621.681 [ElevatorServo] Loaded
2018-11-02T18:33:41.682Z,1541183621.682 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-11-02T18:33:41.697Z,1541183621.697 [MassServo] Loaded
2018-11-02T18:33:41.697Z,1541183621.697 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-11-02T18:33:41.712Z,1541183621.712 [RudderServo] Loaded
2018-11-02T18:33:41.713Z,1541183621.713 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-11-02T18:33:41.727Z,1541183621.727 [ThrusterServo] Loaded
2018-11-02T18:33:41.727Z,1541183621.727 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-11-02T18:33:41.728Z,1541183621.728 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-11-02T18:33:41.728Z,1541183621.728 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-11-02T18:33:41.752Z,1541183621.752 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-11-02T18:33:41.753Z,1541183621.753 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-11-02T18:33:41.883Z,1541183621.883 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-11-02T18:33:41.883Z,1541183621.883 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-11-02T18:33:42.460Z,1541183622.460 [DataOverHttps] Loaded
2018-11-02T18:33:42.461Z,1541183622.461 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-11-02T18:33:42.474Z,1541183622.474 [Depth_Keller] Loaded
2018-11-02T18:33:42.475Z,1541183622.475 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-11-02T18:33:42.480Z,1541183622.480 [DropWeight] Loaded
2018-11-02T18:33:42.480Z,1541183622.480 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-11-02T18:33:42.578Z,1541183622.578 [NAL9602] Loaded
2018-11-02T18:33:42.578Z,1541183622.578 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-11-02T18:33:42.595Z,1541183622.595 [Onboard] Loaded
2018-11-02T18:33:42.595Z,1541183622.595 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-11-02T18:33:42.606Z,1541183622.606 [Radio_Surface] Loaded
2018-11-02T18:33:42.606Z,1541183622.606 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-11-02T18:33:42.607Z,1541183622.607 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4088F4E0
2018-11-02T18:33:42.607Z,1541183622.607 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 882
2018-11-02T18:33:42.760Z,1541183622.760 [PNI_TCM] Loaded
2018-11-02T18:33:42.760Z,1541183622.760 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-11-02T18:33:42.821Z,1541183622.821 [Rowe_600LCM] Loaded
2018-11-02T18:33:42.821Z,1541183622.821 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2018-11-02T18:33:42.822Z,1541183622.822 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 408BF4E0
2018-11-02T18:33:42.823Z,1541183622.823 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 883
2018-11-02T18:33:42.823Z,1541183622.823 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-11-02T18:33:42.824Z,1541183622.824 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-11-02T18:33:42.977Z,1541183622.977 [SBIT](DEBUG): Construct Startup Built In Test.
2018-11-02T18:33:42.000Z,1541183623.000 [SBIT] Loaded
2018-11-02T18:33:42.000Z,1541183623.000 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-11-02T18:33:43.001Z,1541183623.001 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-11-02T18:33:43.013Z,1541183623.013 [IBIT] Loaded
2018-11-02T18:33:43.014Z,1541183623.014 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-11-02T18:33:43.017Z,1541183623.017 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-11-02T18:33:43.167Z,1541183623.167 [CBIT] Loaded
2018-11-02T18:33:43.167Z,1541183623.167 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-11-02T18:33:43.168Z,1541183623.168 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-11-02T18:33:43.168Z,1541183623.168 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-11-02T18:33:43.377Z,1541183623.377 [Aanderaa_O2] Loaded
2018-11-02T18:33:43.377Z,1541183623.377 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2018-11-02T18:33:43.459Z,1541183623.459 [CTD_NeilBrown] Loaded
2018-11-02T18:33:43.459Z,1541183623.459 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-11-02T18:33:43.461Z,1541183623.461 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4098A4E0
2018-11-02T18:33:43.461Z,1541183623.461 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 884
2018-11-02T18:33:43.517Z,1541183623.517 [CTD_Seabird] Loaded
2018-11-02T18:33:43.517Z,1541183623.517 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-11-02T18:33:43.518Z,1541183623.518 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409BA4E0
2018-11-02T18:33:43.518Z,1541183623.518 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 885
2018-11-02T18:33:43.533Z,1541183623.533 [PAR_Licor] Loaded
2018-11-02T18:33:43.533Z,1541183623.533 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-11-02T18:33:43.582Z,1541183623.582 [WetLabsBB2FL] Loaded
2018-11-02T18:33:43.582Z,1541183623.582 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-11-02T18:33:43.583Z,1541183623.583 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409EA4E0
2018-11-02T18:33:43.584Z,1541183623.584 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 886
2018-11-02T18:33:43.585Z,1541183623.585 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-11-02T18:33:43.587Z,1541183623.587 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-11-02T18:33:44.191Z,1541183624.191 [VerticalControl](DEBUG): Construct VerticalControl.
2018-11-02T18:33:44.337Z,1541183624.337 [VerticalControl] Loaded
2018-11-02T18:33:44.338Z,1541183624.338 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-11-02T18:33:44.338Z,1541183624.338 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-11-02T18:33:44.396Z,1541183624.396 [HorizontalControl] Loaded
2018-11-02T18:33:44.396Z,1541183624.396 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-11-02T18:33:44.397Z,1541183624.397 [SpeedControl](DEBUG): Construct SpeedControl.
2018-11-02T18:33:44.398Z,1541183624.398 [SpeedControl] Loaded
2018-11-02T18:33:44.399Z,1541183624.399 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-11-02T18:33:44.399Z,1541183624.399 [LoopControl](DEBUG): Construct LoopControl.
2018-11-02T18:33:44.400Z,1541183624.400 [LoopControl] Loaded
2018-11-02T18:33:44.400Z,1541183624.400 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-11-02T18:33:44.401Z,1541183624.401 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-11-02T18:33:44.402Z,1541183624.402 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-11-02T18:33:44.440Z,1541183624.440 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-11-02T18:33:44.441Z,1541183624.441 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-11-02T18:33:44.548Z,1541183624.548 [DeadReckonUsingSpeedCalculator] Loaded
2018-11-02T18:33:44.548Z,1541183624.548 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-11-02T18:33:44.564Z,1541183624.564 [NavChart] Loaded
2018-11-02T18:33:44.564Z,1541183624.564 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-11-02T18:33:44.568Z,1541183624.568 [UniversalFixResidualReporter] Loaded
2018-11-02T18:33:44.569Z,1541183624.569 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-11-02T18:33:44.569Z,1541183624.569 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-11-02T18:33:44.573Z,1541183624.573 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-11-02T18:33:44.574Z,1541183624.574 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-11-02T18:33:44.580Z,1541183624.580 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-11-02T18:33:44.581Z,1541183624.581 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A764E0
2018-11-02T18:33:44.582Z,1541183624.582 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 887
2018-11-02T18:33:44.586Z,1541183624.586 [Supervisor](INFO): Main Thread ID is 796
2018-11-02T18:33:44.587Z,1541183624.587 [Supervisor](DEBUG): Running supervisor.
2018-11-02T18:33:44.587Z,1541183624.587 [CommandLine ThreadHandler](INFO): Handler Thread ID is 888
2018-11-02T18:33:44.590Z,1541183624.590 [controlThread ThreadHandler](INFO): Handler Thread ID is 889
2018-11-02T18:33:44.590Z,1541183624.590 [controlThread](DEBUG): Initializing ControlThread
2018-11-02T18:33:44.591Z,1541183624.591 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-11-02T18:33:44.591Z,1541183624.591 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-11-02T18:33:44.591Z,1541183624.591 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-11-02T18:33:44.592Z,1541183624.592 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-11-02T18:33:44.592Z,1541183624.592 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-11-02T18:33:44.593Z,1541183624.593 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-11-02T18:33:44.599Z,1541183624.599 [SBIT](INFO): Initialize SBIT Component.
2018-11-02T18:33:44.599Z,1541183624.599 [SBIT](IMPORTANT): git: 2018-11-02
2018-11-02T18:33:44.599Z,1541183624.599 [SBIT](INFO): git hash: 766718804c5d96cf896f07eddb44b232c8585615
2018-11-02T18:33:44.600Z,1541183624.600 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-11-02T18:33:44.600Z,1541183624.600 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-11-02T18:33:44.601Z,1541183624.601 [SBIT](INFO): Beginning SBIT in 36.000000 seconds.
2018-11-02T18:33:44.602Z,1541183624.602 [IBIT](INFO): Initialize IBIT Component.
2018-11-02T18:33:44.603Z,1541183624.603 [CBIT](DEBUG): Initialize CBIT Component.
2018-11-02T18:33:44.603Z,1541183624.603 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-11-02T18:33:44.604Z,1541183624.604 [logger ThreadHandler](INFO): Handler Thread ID is 890
2018-11-02T18:33:44.621Z,1541183624.621 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 891
2018-11-02T18:33:44.627Z,1541183624.627 [Radio_Surface](INFO): Powering up
2018-11-02T18:33:44.633Z,1541183624.633 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 892
2018-11-02T18:33:44.634Z,1541183624.634 [Rowe_600LCM](INFO): Initializing
2018-11-02T18:33:44.634Z,1541183624.634 [Rowe_600LCM](INFO): Checking LCM
2018-11-02T18:33:44.747Z,1541183624.747 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 893
2018-11-02T18:33:44.748Z,1541183624.748 [CTD_NeilBrown](INFO): Powering down
2018-11-02T18:33:44.773Z,1541183624.773 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-11-02T18:33:44.775Z,1541183624.775 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-11-02T18:33:44.776Z,1541183624.776 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-11-02T18:33:44.776Z,1541183624.776 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-11-02T18:33:44.777Z,1541183624.777 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-02T18:33:44.777Z,1541183624.777 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T18:33:44.778Z,1541183624.778 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T18:33:44.778Z,1541183624.778 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-11-02T18:33:44.779Z,1541183624.779 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-11-02T18:33:44.780Z,1541183624.780 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-11-02T18:33:44.876Z,1541183624.876 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 894
2018-11-02T18:33:44.877Z,1541183624.877 [CTD_Seabird](INFO): Initializing
2018-11-02T18:33:44.877Z,1541183624.877 [CTD_Seabird](INFO): Checking LCM
2018-11-02T18:33:44.879Z,1541183624.879 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 895
2018-11-02T18:33:44.880Z,1541183624.880 [WetLabsBB2FL](INFO): Powering down
2018-11-02T18:33:44.985Z,1541183624.985 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-02T18:33:44.989Z,1541183624.989 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 896
2018-11-02T18:33:45.030Z,1541183625.030 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-11-02T18:33:45.030Z,1541183625.030 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-11-02T18:33:45.030Z,1541183625.030 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-11-02T18:33:45.030Z,1541183625.030 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-11-02T18:33:45.031Z,1541183625.031 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-11-02T18:33:45.031Z,1541183625.031 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-11-02T18:33:45.031Z,1541183625.031 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-11-02T18:33:45.031Z,1541183625.031 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-11-02T18:33:45.031Z,1541183625.031 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-11-02T18:33:45.032Z,1541183625.032 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-11-02T18:33:45.032Z,1541183625.032 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-11-02T18:33:45.032Z,1541183625.032 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-11-02T18:33:45.032Z,1541183625.032 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-11-02T18:33:45.032Z,1541183625.032 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-11-02T18:33:45.037Z,1541183625.037 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-11-02T18:33:45.038Z,1541183625.038 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-11-02T18:33:45.045Z,1541183625.045 [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-02T18:33:45.046Z,1541183625.046 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-11-02T18:33:45.061Z,1541183625.061 [CTD_Seabird](INFO): LCM OK
2018-11-02T18:33:45.061Z,1541183625.061 [CTD_Seabird](INFO): Powering up
2018-11-02T18:33:45.065Z,1541183625.065 [Rowe_600LCM](INFO): LCM OK
2018-11-02T18:33:45.065Z,1541183625.065 [Rowe_600LCM](INFO): Powering up
2018-11-02T18:33:45.129Z,1541183625.129 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-11-02T18:33:45.130Z,1541183625.130 [Default:A.Wait](DEBUG): Construct Wait.
2018-11-02T18:33:45.132Z,1541183625.132 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-02T18:33:45.178Z,1541183625.178 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-11-02T18:33:45.193Z,1541183625.193 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-11-02T18:33:45.199Z,1541183625.199 [Default:E.Execute](DEBUG): Construct Execute.
2018-11-02T18:33:45.219Z,1541183625.219 [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-02T18:33:45.224Z,1541183625.224 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,Aanderaa_O2,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-02T18:33:45.248Z,1541183625.248 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-11-02T18:33:45.280Z,1541183625.280 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2018-11-02T18:33:45.432Z,1541183625.432 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-11-02T18:33:45.738Z,1541183625.738 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-02T18:33:45.745Z,1541183625.745 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-02T18:33:45.773Z,1541183625.773 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-11-02T18:33:45.781Z,1541183625.781 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-11-02T18:33:45.787Z,1541183625.787 [MassServo](DEBUG): Initializing EZServoServo.
2018-11-02T18:33:45.793Z,1541183625.793 [MassServo](DEBUG): Initializing MassServo.
2018-11-02T18:33:45.815Z,1541183625.815 [RudderServo](DEBUG): Initializing EZServoServo.
2018-11-02T18:33:45.821Z,1541183625.821 [RudderServo](DEBUG): Initializing RudderServo.
2018-11-02T18:33:45.839Z,1541183625.839 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-11-02T18:33:45.845Z,1541183625.845 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-11-02T18:33:46.693Z,1541183626.693 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-11-02T18:33:46.693Z,1541183626.693 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-11-02T18:33:46.693Z,1541183626.693 [BuoyancyServo] Communications Fault, FailCount= 1
2018-11-02T18:33:46.693Z,1541183626.693 [BuoyancyServo](ERROR): Communications Fault
2018-11-02T18:33:46.908Z,1541183626.908 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-11-02T18:33:46.966Z,1541183626.966 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-11-02T18:33:46.967Z,1541183626.967 [BuoyancyServo](INFO): Powering down
2018-11-02T18:33:48.669Z,1541183628.669 [Aanderaa_O2](INFO): Powering down
2018-11-02T18:33:48.842Z,1541183628.842 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-11-02T18:33:48.965Z,1541183628.965 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-11-02T18:33:49.155Z,1541183629.155 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-11-02T18:33:49.156Z,1541183629.156 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-11-02T18:33:49.157Z,1541183629.157 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-11-02T18:33:49.241Z,1541183629.241 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-11-02T18:33:49.241Z,1541183629.241 [BuoyancyServo] No Fault, FailCount= 1
2018-11-02T18:33:49.405Z,1541183629.405 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-02T18:33:49.405Z,1541183629.405 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-02T18:33:50.413Z,1541183630.413 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-11-02T18:33:50.547Z,1541183630.547 [CTD_Seabird](INFO): Started Seabird LCM interface with command:nohup ./lrauv-framework/onboard/bin/gpctd -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyC6 -b 9600 >& /dev/null &
2018-11-02T18:33:50.549Z,1541183630.549 [CTD_Seabird](INFO): LCM subscribed to channel:seabird_gpctd_t.seabird-gpctd
2018-11-02T18:33:51.308Z,1541183631.308 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-11-02T18:33:51.309Z,1541183631.309 [CTD_Seabird](INFO): Powering down
2018-11-02T18:34:12.605Z,1541183652.605 [NAL9602](INFO): Powering up NAL9602
2018-11-02T18:34:21.162Z,1541183661.162 [SBIT](IMPORTANT): Beginning Startup BIT
2018-11-02T18:34:21.167Z,1541183661.167 [CBIT](IMPORTANT): Beginning ground fault scan
2018-11-02T18:34:23.966Z,1541183663.966 [NAL9602](INFO): NAL9602 initialized
2018-11-02T18:34:30.706Z,1541183670.706 [CommandLine](IMPORTANT): got command failComponent
2018-11-02T18:34:30.706Z,1541183670.706 [CommandLine](IMPORTANT): Failed components:
2018-11-02T18:34:30.706Z,1541183670.706 [CommandLine](IMPORTANT): No failed Components.
2018-11-02T18:34:32.114Z,1541183672.114 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.003979
CHAN A1 (24V): -0.010498
CHAN A2 (12V): -0.002001
CHAN A3 (5V): -0.001050
CHAN B0 (3.3V): -0.000251
CHAN B1 (3.15aV): -0.000049
CHAN B2 (3.15bV): -0.000393
CHAN B3 (GND): -0.000369
OPEN: -0.000376
Full Scale Calc: 4.765 mA, -1.589 mA
2018-11-02T18:34:56.948Z,1541183696.948 [NAL9602](INFO): SBD MO Status=2, MOMSN=10406, MT Status=2, MTMSN=0
2018-11-02T18:34:56.948Z,1541183696.948 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T18:35:15.147Z,1541183715.147 [SBIT](IMPORTANT): SBIT PASSED
2018-11-02T18:35:15.218Z,1541183715.218 [CommandLine](IMPORTANT): got command configSet list
2018-11-02T18:35:15.218Z,1541183715.218 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=28 count;

2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): BPC1.batteryMuxCycleTime=10 minute;

2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=1 minute;

2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool;

2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=1 bool;

2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool;

2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index;

2018-11-02T18:35:15.219Z,1541183715.219 [CommandLine](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;

2018-11-02T18:35:15.220Z,1541183715.220 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=1 bool;

2018-11-02T18:35:15.220Z,1541183715.220 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup=0 bool;

2018-11-02T18:35:15.220Z,1541183715.220 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=213 cubic_centimeter;

2018-11-02T18:35:15.220Z,1541183715.220 [CommandLine](IMPORTANT): VerticalControl.massDefault=4 millimeter;

2018-11-02T18:35:15.530Z,1541183715.530 [MissionManager](IMPORTANT): Started mission Startup
2018-11-02T18:35:15.530Z,1541183715.530 [Startup] Running Loop=1
2018-11-02T18:35:15.531Z,1541183715.531 [Startup](DEBUG): Aggregate::initialize Startup
2018-11-02T18:35:15.531Z,1541183715.531 [Startup:A.GoToSurface] Running Loop=1
2018-11-02T18:35:15.531Z,1541183715.531 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-02T18:35:15.531Z,1541183715.531 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-02T18:35:15.532Z,1541183715.532 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-02T18:35:15.532Z,1541183715.532 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-02T18:35:15.541Z,1541183715.541 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-02T18:35:15.541Z,1541183715.541 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-02T18:35:15.556Z,1541183715.556 [Startup:StartupSatComms] Running Loop=1
2018-11-02T18:35:15.556Z,1541183715.556 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-11-02T18:35:15.556Z,1541183715.556 [Startup:StartupSatComms:A] Running Loop=1
2018-11-02T18:35:15.918Z,1541183715.918 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-11-02T18:36:00.607Z,1541183760.607 [CommandLine](IMPORTANT): got command configSet Rowe_600LCM.loadAtStartup 0.000000 bool
2018-11-02T18:36:00.607Z,1541183760.607 [CommandLine](FAULT): configSet Rowe_600LCM.loadAtStartup without persist will have no effect.
2018-11-02T18:36:01.073Z,1541183761.073 [Rowe_600LCM](IMPORTANT): Stopping now due to load at startup. No immediate restart required.
2018-11-02T18:36:01.074Z,1541183761.074 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-11-02T18:36:01.335Z,1541183761.335 [Rowe_600LCM](INFO): Powering down
2018-11-02T18:36:01.737Z,1541183761.737 [Rowe_600LCM](FAULT): LCB fault:  Software Overcurrent.
2018-11-02T18:36:01.738Z,1541183761.738 [Rowe_600LCM] Hardware Fault, FailCount= 1
2018-11-02T18:36:01.738Z,1541183761.738 [Rowe_600LCM](ERROR): Hardware Fault
2018-11-02T18:36:01.947Z,1541183761.947 [CBIT](ERROR): Hardware Fault in component: Rowe_600LCM
2018-11-02T18:36:02.338Z,1541183762.338 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-11-02T18:36:02.338Z,1541183762.338 [Rowe_600LCM] No Fault, FailCount= 1
2018-11-02T18:36:02.545Z,1541183762.545 [Rowe_600LCM](INFO): Initializing
2018-11-02T18:36:02.545Z,1541183762.545 [Rowe_600LCM](INFO): Checking LCM
2018-11-02T18:36:02.546Z,1541183762.546 [Rowe_600LCM](INFO): LCM OK
2018-11-02T18:36:02.546Z,1541183762.546 [Rowe_600LCM](INFO): Powering up
2018-11-02T18:36:06.719Z,1541183766.719 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-11-02T18:36:06.852Z,1541183766.852 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-11-02T18:36:06.854Z,1541183766.854 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-11-02T18:36:06.854Z,1541183766.854 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-11-02T18:36:06.855Z,1541183766.855 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-11-02T18:36:07.264Z,1541183767.264 [Rowe_600LCM](IMPORTANT): Stopping now due to load at startup. No immediate restart required.
2018-11-02T18:36:07.265Z,1541183767.265 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-11-02T18:36:07.367Z,1541183767.367 [Rowe_600LCM](INFO): Powering down
2018-11-02T18:36:17.039Z,1541183777.039 [Startup:StartupSatComms:A](INFO): Timed out from 2018-11-02T18:35:15.6Z
2018-11-02T18:36:17.039Z,1541183777.039 [Startup:StartupSatComms:A] Stopped
2018-11-02T18:36:17.039Z,1541183777.039 [Startup:StartupSatComms:B] Running Loop=1
2018-11-02T18:36:17.197Z,1541183777.197 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-11-02T18:36:17.911Z,1541183777.911 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004437
2018-11-02T18:36:22.323Z,1541183782.323 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T182603/Courier0004.lzma
2018-11-02T18:36:23.119Z,1541183783.119 [DataOverHttps](INFO): Moved sent file to Logs/20181102T182603/Courier0004.lzma.bak
2018-11-02T18:36:23.119Z,1541183783.119 [DataOverHttps](INFO): SBD MOMSN=8782574
2018-11-02T18:36:31.925Z,1541183791.925 [DataOverHttps](INFO): Sending 745 bytes from file Logs/20181102T182049/Express0001.lzma
2018-11-02T18:36:32.711Z,1541183792.711 [DataOverHttps](INFO): Moved sent file to Logs/20181102T182049/Express0001.lzma.bak
2018-11-02T18:36:32.711Z,1541183792.711 [DataOverHttps](INFO): SBD MOMSN=8782577
2018-11-02T18:36:41.547Z,1541183801.547 [DataOverHttps](INFO): Sending 740 bytes from file Logs/20181102T182238/Express0001.lzma
2018-11-02T18:36:42.331Z,1541183802.331 [DataOverHttps](INFO): Moved sent file to Logs/20181102T182238/Express0001.lzma.bak
2018-11-02T18:36:42.331Z,1541183802.331 [DataOverHttps](INFO): SBD MOMSN=8782607
2018-11-02T18:36:46.279Z,1541183806.279 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-11-02T18:36:46.279Z,1541183806.279 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2018-11-02T18:36:46.279Z,1541183806.279 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-02T18:36:46.332Z,1541183806.332 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-02T18:36:46.431Z,1541183806.431 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-02T18:36:46.431Z,1541183806.431 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2018-11-02T18:36:46.783Z,1541183806.783 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-02T18:36:46.784Z,1541183806.784 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-02T18:36:46.784Z,1541183806.784 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-02T18:36:51.158Z,1541183811.158 [DataOverHttps](INFO): Sending 1050 bytes from file Logs/20181102T182603/Express0001.lzma
2018-11-02T18:36:51.911Z,1541183811.911 [DataOverHttps](INFO): Moved sent file to Logs/20181102T182603/Express0001.lzma.bak
2018-11-02T18:36:51.911Z,1541183811.911 [DataOverHttps](INFO): SBD MOMSN=8782637
2018-11-02T18:36:55.838Z,1541183815.838 [NAL9602](INFO): SBD MO Status=2, MOMSN=10406, MT Status=2, MTMSN=0
2018-11-02T18:36:55.838Z,1541183815.838 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T18:37:00.757Z,1541183820.757 [DataOverHttps](INFO): Sending 730 bytes from file Logs/20181102T182603/Express0005.lzma
2018-11-02T18:37:01.531Z,1541183821.531 [DataOverHttps](INFO): Moved sent file to Logs/20181102T182603/Express0005.lzma.bak
2018-11-02T18:37:01.531Z,1541183821.531 [DataOverHttps](INFO): SBD MOMSN=8782675
2018-11-02T18:37:10.392Z,1541183830.392 [DataOverHttps](INFO): Sending 1136 bytes from file Logs/20181102T183334/Express0001.lzma
2018-11-02T18:37:11.187Z,1541183831.187 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0001.lzma.bak
2018-11-02T18:37:11.187Z,1541183831.187 [DataOverHttps](INFO): SBD MOMSN=8782697
2018-11-02T18:37:11.656Z,1541183831.656 [Startup:StartupSatComms:B] Stopped
2018-11-02T18:37:11.656Z,1541183831.656 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-11-02T18:37:11.656Z,1541183831.656 [Startup:StartupSatComms] Stopped
2018-11-02T18:37:11.657Z,1541183831.657 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-11-02T18:37:11.658Z,1541183831.658 [Startup](INFO): Completed Startup
2018-11-02T18:37:11.658Z,1541183831.658 [MissionManager](INFO): Startup is completed.
2018-11-02T18:37:11.658Z,1541183831.658 [MissionManager](INFO): Uninitializing Mission Startup
2018-11-02T18:37:11.658Z,1541183831.658 [Startup] Stopped
2018-11-02T18:37:11.658Z,1541183831.658 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-11-02T18:37:11.658Z,1541183831.658 [Startup:A.GoToSurface] Stopped
2018-11-02T18:37:11.659Z,1541183831.659 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-02T18:37:12.051Z,1541183832.051 [MissionManager](IMPORTANT): Started mission Default
2018-11-02T18:37:12.051Z,1541183832.051 [Default] Running Loop=1
2018-11-02T18:37:12.051Z,1541183832.051 [Default](DEBUG): Aggregate::initialize Default
2018-11-02T18:37:12.051Z,1541183832.051 [Default:B.GoToSurface] Running Loop=1
2018-11-02T18:37:12.051Z,1541183832.051 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-02T18:37:12.052Z,1541183832.052 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-02T18:37:12.052Z,1541183832.052 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-02T18:37:12.052Z,1541183832.052 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-02T18:37:12.057Z,1541183832.057 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-02T18:37:12.057Z,1541183832.057 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-02T18:37:12.058Z,1541183832.058 [Default:A.Wait] Running Loop=1
2018-11-02T18:37:12.058Z,1541183832.058 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-11-02T18:37:21.600Z,1541183841.600 [NAL9602](INFO): SBD MO Status=0, MOMSN=10406, MT Status=0, MTMSN=0
2018-11-02T18:37:21.600Z,1541183841.600 [NAL9602](INFO): No messages in MT queue
2018-11-02T18:37:25.239Z,1541183845.239 [Default:A.Wait](INFO): Done Waiting.
2018-11-02T18:37:25.239Z,1541183845.239 [Default:A.Wait] Stopped
2018-11-02T18:37:25.239Z,1541183845.239 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T18:37:25.653Z,1541183845.653 [Default:CheckIn] Running Loop=1
2018-11-02T18:37:25.653Z,1541183845.653 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T18:37:25.653Z,1541183845.653 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T18:37:26.057Z,1541183846.057 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-11-02T18:39:44.787Z,1541183984.787 [NAL9602](INFO): GPS fix at 20181102T183942: (36.802655, -121.788297)
2018-11-02T18:39:44.821Z,1541183984.821 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T18:39:44.821Z,1541183984.821 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T18:39:45.252Z,1541183985.252 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-11-02T18:39:51.486Z,1541183991.486 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20181102T183334/Courier0004.lzma
2018-11-02T18:39:52.267Z,1541183992.267 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0004.lzma.bak
2018-11-02T18:39:52.267Z,1541183992.267 [DataOverHttps](INFO): SBD MOMSN=8782733
2018-11-02T18:40:02.062Z,1541184002.062 [DataOverHttps](INFO): Sending 210 bytes from file Logs/20181102T183334/Express0005.lzma
2018-11-02T18:40:02.863Z,1541184002.863 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0005.lzma.bak
2018-11-02T18:40:02.863Z,1541184002.863 [DataOverHttps](INFO): SBD MOMSN=8782736
2018-11-02T18:40:03.362Z,1541184003.362 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T18:40:03.363Z,1541184003.363 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T18:40:03.363Z,1541184003.363 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T18:40:21.806Z,1541184021.806 [NAL9602](INFO): Powering down
2018-11-02T18:45:03.781Z,1541184303.781 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T18:45:03.782Z,1541184303.782 [Default:CheckIn:C.Wait] Stopped
2018-11-02T18:45:03.782Z,1541184303.782 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T18:45:03.782Z,1541184303.782 [Default:CheckIn:D] Running Loop=1
2018-11-02T18:45:04.194Z,1541184304.194 [Default:CheckIn:D] Stopped
2018-11-02T18:45:04.194Z,1541184304.194 [Default:CheckIn:E] Running Loop=1
2018-11-02T18:45:07.495Z,1541184307.495 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.869022 min 
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn:E] Stopped
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn] Stopped
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn](INFO): Running loop #2
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn] Running Loop=2
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T18:45:07.497Z,1541184307.497 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T18:45:07.962Z,1541184307.962 [NAL9602](INFO): Powering up
2018-11-02T18:45:19.162Z,1541184319.162 [NAL9602](INFO): NAL9602 initialized
2018-11-02T18:46:18.371Z,1541184378.371 [NAL9602](INFO): SBD MO Status=2, MOMSN=10407, MT Status=2, MTMSN=0
2018-11-02T18:46:18.372Z,1541184378.372 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T18:50:07.794Z,1541184607.794 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T18:45:07.5Z
2018-11-02T18:50:07.794Z,1541184607.794 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T18:50:07.794Z,1541184607.794 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T18:50:12.675Z,1541184612.675 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0007.lzma
2018-11-02T18:50:13.467Z,1541184613.467 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0007.lzma.bak
2018-11-02T18:50:13.467Z,1541184613.467 [DataOverHttps](INFO): SBD MOMSN=8782795
2018-11-02T18:50:17.455Z,1541184617.455 [NAL9602](INFO): SBD MO Status=2, MOMSN=10407, MT Status=2, MTMSN=0
2018-11-02T18:50:17.455Z,1541184617.455 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T18:50:22.278Z,1541184622.278 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T18:50:22.379Z,1541184622.379 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20181102T183334/Express0008.lzma
2018-11-02T18:50:23.179Z,1541184623.179 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0008.lzma.bak
2018-11-02T18:50:23.179Z,1541184623.179 [DataOverHttps](INFO): SBD MOMSN=8782797
2018-11-02T18:50:23.639Z,1541184623.639 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T18:50:23.639Z,1541184623.639 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T18:50:23.639Z,1541184623.639 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T18:50:52.802Z,1541184652.802 [NAL9602](INFO): Powering down
2018-11-02T18:55:24.327Z,1541184924.327 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T18:55:24.327Z,1541184924.327 [Default:CheckIn:C.Wait] Stopped
2018-11-02T18:55:24.327Z,1541184924.327 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T18:55:24.327Z,1541184924.327 [Default:CheckIn:D] Running Loop=1
2018-11-02T18:55:24.752Z,1541184924.752 [Default:CheckIn:D] Stopped
2018-11-02T18:55:24.752Z,1541184924.752 [Default:CheckIn:E] Running Loop=1
2018-11-02T18:55:25.161Z,1541184925.161 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.211684 min 
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn:E] Stopped
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn] Stopped
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn](INFO): Running loop #3
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn] Running Loop=3
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T18:55:25.162Z,1541184925.162 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T18:55:28.406Z,1541184928.406 [NAL9602](INFO): Powering up
2018-11-02T18:55:39.546Z,1541184939.546 [NAL9602](INFO): NAL9602 initialized
2018-11-02T18:55:40.346Z,1541184940.346 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T18:55:40.346Z,1541184940.346 [NAL9602] Data Fault, FailCount= 1
2018-11-02T18:55:40.346Z,1541184940.346 [NAL9602](ERROR): Data Fault
2018-11-02T18:55:40.420Z,1541184940.420 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T18:55:40.746Z,1541184940.746 [NAL9602](INFO): Powering down
2018-11-02T18:55:41.599Z,1541184941.599 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T18:55:41.599Z,1541184941.599 [NAL9602] No Fault, FailCount= 1
2018-11-02T18:56:11.146Z,1541184971.146 [NAL9602](INFO): Powering up NAL9602
2018-11-02T18:56:22.346Z,1541184982.346 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:00:24.680Z,1541185224.680 [NAL9602](INFO): SBD MO Status=0, MOMSN=10407, MT Status=0, MTMSN=0
2018-11-02T19:00:24.680Z,1541185224.680 [NAL9602](INFO): No messages in MT queue
2018-11-02T19:00:25.551Z,1541185225.551 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T18:55:25.2Z
2018-11-02T19:00:25.551Z,1541185225.551 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T19:00:25.551Z,1541185225.551 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T19:00:29.114Z,1541185229.114 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0010.lzma
2018-11-02T19:00:29.903Z,1541185229.903 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0010.lzma.bak
2018-11-02T19:00:29.903Z,1541185229.903 [DataOverHttps](INFO): SBD MOMSN=8782865
2018-11-02T19:00:38.782Z,1541185238.782 [DataOverHttps](INFO): Sending 239 bytes from file Logs/20181102T183334/Express0011.lzma
2018-11-02T19:00:39.583Z,1541185239.583 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0011.lzma.bak
2018-11-02T19:00:39.583Z,1541185239.583 [DataOverHttps](INFO): SBD MOMSN=8782867
2018-11-02T19:00:40.052Z,1541185240.052 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T19:00:40.052Z,1541185240.052 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T19:00:40.069Z,1541185240.069 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T19:01:04.106Z,1541185264.106 [NAL9602](INFO): Powering down
2018-11-02T19:05:40.679Z,1541185540.679 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T19:05:40.679Z,1541185540.679 [Default:CheckIn:C.Wait] Stopped
2018-11-02T19:05:40.679Z,1541185540.679 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T19:05:40.679Z,1541185540.679 [Default:CheckIn:D] Running Loop=1
2018-11-02T19:05:41.079Z,1541185541.079 [Default:CheckIn:D] Stopped
2018-11-02T19:05:41.080Z,1541185541.080 [Default:CheckIn:E] Running Loop=1
2018-11-02T19:05:44.196Z,1541185544.196 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.483805 min 
2018-11-02T19:05:44.197Z,1541185544.197 [Default:CheckIn:E] Stopped
2018-11-02T19:05:44.197Z,1541185544.197 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T19:05:44.197Z,1541185544.197 [Default:CheckIn] Stopped
2018-11-02T19:05:44.197Z,1541185544.197 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T19:05:44.197Z,1541185544.197 [Default:CheckIn](INFO): Running loop #4
2018-11-02T19:05:44.197Z,1541185544.197 [Default:CheckIn] Running Loop=4
2018-11-02T19:05:44.197Z,1541185544.197 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T19:05:44.198Z,1541185544.198 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T19:05:44.646Z,1541185544.646 [NAL9602](INFO): Powering up
2018-11-02T19:05:55.846Z,1541185555.846 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:10:44.859Z,1541185844.859 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T19:05:44.2Z
2018-11-02T19:10:44.859Z,1541185844.859 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T19:10:44.859Z,1541185844.859 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T19:10:49.726Z,1541185849.726 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0013.lzma
2018-11-02T19:10:50.527Z,1541185850.527 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0013.lzma.bak
2018-11-02T19:10:50.527Z,1541185850.527 [DataOverHttps](INFO): SBD MOMSN=8782932
2018-11-02T19:10:59.543Z,1541185859.543 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20181102T183334/Express0014.lzma
2018-11-02T19:11:00.307Z,1541185860.307 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0014.lzma.bak
2018-11-02T19:11:00.307Z,1541185860.307 [DataOverHttps](INFO): SBD MOMSN=8782934
2018-11-02T19:11:00.796Z,1541185860.796 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T19:11:00.796Z,1541185860.796 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T19:11:00.796Z,1541185860.796 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T19:11:04.352Z,1541185864.352 [NAL9602](INFO): SBD MO Status=2, MOMSN=10408, MT Status=2, MTMSN=0
2018-11-02T19:11:04.352Z,1541185864.352 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T19:11:04.494Z,1541185864.494 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T19:11:35.250Z,1541185895.250 [NAL9602](INFO): Powering down
2018-11-02T19:16:01.293Z,1541186161.293 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T19:16:01.294Z,1541186161.294 [Default:CheckIn:C.Wait] Stopped
2018-11-02T19:16:01.294Z,1541186161.294 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T19:16:01.294Z,1541186161.294 [Default:CheckIn:D] Running Loop=1
2018-11-02T19:16:01.689Z,1541186161.689 [Default:CheckIn:D] Stopped
2018-11-02T19:16:01.689Z,1541186161.689 [Default:CheckIn:E] Running Loop=1
2018-11-02T19:16:02.098Z,1541186162.098 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.827299 min 
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn:E] Stopped
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn] Stopped
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn](INFO): Running loop #5
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn] Running Loop=5
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T19:16:02.099Z,1541186162.099 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T19:16:05.293Z,1541186165.293 [NAL9602](INFO): Powering up
2018-11-02T19:16:16.478Z,1541186176.478 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:16:17.278Z,1541186177.278 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T19:16:17.278Z,1541186177.278 [NAL9602] Data Fault, FailCount= 1
2018-11-02T19:16:17.278Z,1541186177.278 [NAL9602](ERROR): Data Fault
2018-11-02T19:16:17.388Z,1541186177.388 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T19:16:17.678Z,1541186177.678 [NAL9602](INFO): Powering down
2018-11-02T19:16:18.560Z,1541186178.560 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T19:16:18.560Z,1541186178.560 [NAL9602] No Fault, FailCount= 1
2018-11-02T19:16:48.078Z,1541186208.078 [NAL9602](INFO): Powering up NAL9602
2018-11-02T19:16:59.278Z,1541186219.278 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:21:02.431Z,1541186462.431 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T19:16:02.1Z
2018-11-02T19:21:02.431Z,1541186462.431 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T19:21:02.432Z,1541186462.432 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T19:21:05.836Z,1541186465.836 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0016.lzma
2018-11-02T19:21:06.619Z,1541186466.619 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0016.lzma.bak
2018-11-02T19:21:06.619Z,1541186466.619 [DataOverHttps](INFO): SBD MOMSN=8782994
2018-11-02T19:21:15.577Z,1541186475.577 [DataOverHttps](INFO): Sending 218 bytes from file Logs/20181102T183334/Express0017.lzma
2018-11-02T19:21:16.363Z,1541186476.363 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0017.lzma.bak
2018-11-02T19:21:16.363Z,1541186476.363 [DataOverHttps](INFO): SBD MOMSN=8782996
2018-11-02T19:21:16.833Z,1541186476.833 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T19:21:16.833Z,1541186476.833 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T19:21:16.833Z,1541186476.833 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T19:22:02.350Z,1541186522.350 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T19:22:32.890Z,1541186552.890 [NAL9602](INFO): Powering down
2018-11-02T19:26:17.619Z,1541186777.619 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T19:26:17.619Z,1541186777.619 [Default:CheckIn:C.Wait] Stopped
2018-11-02T19:26:17.619Z,1541186777.619 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T19:26:17.619Z,1541186777.619 [Default:CheckIn:D] Running Loop=1
2018-11-02T19:26:18.016Z,1541186778.016 [Default:CheckIn:D] Stopped
2018-11-02T19:26:18.016Z,1541186778.016 [Default:CheckIn:E] Running Loop=1
2018-11-02T19:26:21.394Z,1541186781.394 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.099414 min 
2018-11-02T19:26:21.394Z,1541186781.394 [Default:CheckIn:E] Stopped
2018-11-02T19:26:21.394Z,1541186781.394 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T19:26:21.394Z,1541186781.394 [Default:CheckIn] Stopped
2018-11-02T19:26:21.394Z,1541186781.394 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T19:26:21.394Z,1541186781.394 [Default:CheckIn](INFO): Running loop #6
2018-11-02T19:26:21.395Z,1541186781.395 [Default:CheckIn] Running Loop=6
2018-11-02T19:26:21.395Z,1541186781.395 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T19:26:21.395Z,1541186781.395 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T19:26:21.818Z,1541186781.818 [NAL9602](INFO): Powering up
2018-11-02T19:26:32.618Z,1541186792.618 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:27:04.622Z,1541186824.622 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T19:27:04.697Z,1541186824.697 [NAL9602](FAULT): received: 
+CSQ:0

OK408, 2, 0, 0, 0

OK
2018-11-02T19:27:04.697Z,1541186824.697 [NAL9602] Data Fault, FailCount= 2
2018-11-02T19:27:04.697Z,1541186824.697 [NAL9602](ERROR): Data Fault
2018-11-02T19:27:04.812Z,1541186824.812 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T19:27:05.022Z,1541186825.022 [NAL9602](INFO): Powering down
2018-11-02T19:27:05.877Z,1541186825.877 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T19:27:05.877Z,1541186825.877 [NAL9602] No Fault, FailCount= 2
2018-11-02T19:27:35.034Z,1541186855.034 [NAL9602](INFO): Powering up NAL9602
2018-11-02T19:27:46.234Z,1541186866.234 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:27:47.042Z,1541186867.042 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T19:27:47.042Z,1541186867.042 [NAL9602] Data Fault, FailCount= 3
2018-11-02T19:27:47.043Z,1541186867.043 [NAL9602](ERROR): Data Fault
2018-11-02T19:27:47.118Z,1541186867.118 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T19:27:47.438Z,1541186867.438 [NAL9602](INFO): Powering down
2018-11-02T19:27:48.301Z,1541186868.301 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T19:27:48.301Z,1541186868.301 [NAL9602] No Fault, FailCount= 3
2018-11-02T19:28:17.834Z,1541186897.834 [NAL9602](INFO): Powering up NAL9602
2018-11-02T19:28:28.658Z,1541186908.658 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:31:21.619Z,1541187081.619 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T19:26:21.4Z
2018-11-02T19:31:21.619Z,1541187081.619 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T19:31:21.619Z,1541187081.619 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T19:31:26.485Z,1541187086.485 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0019.lzma
2018-11-02T19:31:27.283Z,1541187087.283 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0019.lzma.bak
2018-11-02T19:31:27.283Z,1541187087.283 [DataOverHttps](INFO): SBD MOMSN=8783061
2018-11-02T19:31:36.196Z,1541187096.196 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T19:31:36.299Z,1541187096.299 [DataOverHttps](INFO): Sending 253 bytes from file Logs/20181102T183334/Express0020.lzma
2018-11-02T19:31:37.099Z,1541187097.099 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0020.lzma.bak
2018-11-02T19:31:37.099Z,1541187097.099 [DataOverHttps](INFO): SBD MOMSN=8783063
2018-11-02T19:31:37.574Z,1541187097.574 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T19:31:37.574Z,1541187097.574 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T19:31:37.575Z,1541187097.575 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T19:32:06.702Z,1541187126.702 [NAL9602](INFO): Powering down
2018-11-02T19:36:38.160Z,1541187398.160 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T19:36:38.165Z,1541187398.165 [Default:CheckIn:C.Wait] Stopped
2018-11-02T19:36:38.165Z,1541187398.165 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T19:36:38.165Z,1541187398.165 [Default:CheckIn:D] Running Loop=1
2018-11-02T19:36:38.581Z,1541187398.581 [Default:CheckIn:D] Stopped
2018-11-02T19:36:38.581Z,1541187398.581 [Default:CheckIn:E] Running Loop=1
2018-11-02T19:36:41.687Z,1541187401.687 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.442159 min 
2018-11-02T19:36:41.688Z,1541187401.688 [Default:CheckIn:E] Stopped
2018-11-02T19:36:41.688Z,1541187401.688 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T19:36:41.688Z,1541187401.688 [Default:CheckIn] Stopped
2018-11-02T19:36:41.688Z,1541187401.688 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T19:36:41.688Z,1541187401.688 [Default:CheckIn](INFO): Running loop #7
2018-11-02T19:36:41.688Z,1541187401.688 [Default:CheckIn] Running Loop=7
2018-11-02T19:36:41.704Z,1541187401.704 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T19:36:41.705Z,1541187401.705 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T19:36:42.142Z,1541187402.142 [NAL9602](INFO): Powering up
2018-11-02T19:36:53.343Z,1541187413.343 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:37:25.347Z,1541187445.347 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T19:37:25.421Z,1541187445.421 [NAL9602](FAULT): received: 
+CSQ:0

OK408, 2, 0, 0, 0

OK
2018-11-02T19:37:25.421Z,1541187445.421 [NAL9602] Data Fault, FailCount= 4
2018-11-02T19:37:25.421Z,1541187445.421 [NAL9602](ERROR): Data Fault
2018-11-02T19:37:25.522Z,1541187445.522 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T19:37:25.742Z,1541187445.742 [NAL9602](INFO): Powering down
2018-11-02T19:37:26.640Z,1541187446.640 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T19:37:26.640Z,1541187446.640 [NAL9602] No Fault, FailCount= 4
2018-11-02T19:37:55.862Z,1541187475.862 [NAL9602](INFO): Powering up NAL9602
2018-11-02T19:38:07.062Z,1541187487.062 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:41:42.025Z,1541187702.025 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T19:36:41.7Z
2018-11-02T19:41:42.025Z,1541187702.025 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T19:41:42.025Z,1541187702.025 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T19:41:47.046Z,1541187707.046 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0022.lzma
2018-11-02T19:41:47.843Z,1541187707.843 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0022.lzma.bak
2018-11-02T19:41:47.843Z,1541187707.843 [DataOverHttps](INFO): SBD MOMSN=8783133
2018-11-02T19:41:56.581Z,1541187716.581 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T19:41:56.675Z,1541187716.675 [DataOverHttps](INFO): Sending 237 bytes from file Logs/20181102T183334/Express0023.lzma
2018-11-02T19:41:57.475Z,1541187717.475 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0023.lzma.bak
2018-11-02T19:41:57.475Z,1541187717.475 [DataOverHttps](INFO): SBD MOMSN=8783135
2018-11-02T19:41:57.937Z,1541187717.937 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T19:41:57.937Z,1541187717.937 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T19:41:57.937Z,1541187717.937 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T19:42:26.858Z,1541187746.858 [NAL9602](INFO): Powering down
2018-11-02T19:46:58.418Z,1541188018.418 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T19:46:58.418Z,1541188018.418 [Default:CheckIn:C.Wait] Stopped
2018-11-02T19:46:58.418Z,1541188018.418 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T19:46:58.418Z,1541188018.418 [Default:CheckIn:D] Running Loop=1
2018-11-02T19:46:58.820Z,1541188018.820 [Default:CheckIn:D] Stopped
2018-11-02T19:46:58.820Z,1541188018.820 [Default:CheckIn:E] Running Loop=1
2018-11-02T19:46:59.224Z,1541188019.224 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.779476 min 
2018-11-02T19:46:59.224Z,1541188019.224 [Default:CheckIn:E] Stopped
2018-11-02T19:46:59.224Z,1541188019.224 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T19:46:59.224Z,1541188019.224 [Default:CheckIn] Stopped
2018-11-02T19:46:59.225Z,1541188019.225 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T19:46:59.225Z,1541188019.225 [Default:CheckIn](INFO): Running loop #8
2018-11-02T19:46:59.225Z,1541188019.225 [Default:CheckIn] Running Loop=8
2018-11-02T19:46:59.225Z,1541188019.225 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T19:46:59.225Z,1541188019.225 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T19:47:02.423Z,1541188022.423 [NAL9602](INFO): Powering up
2018-11-02T19:47:13.567Z,1541188033.567 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:47:14.358Z,1541188034.358 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T19:47:14.358Z,1541188034.358 [NAL9602] Data Fault, FailCount= 5
2018-11-02T19:47:14.358Z,1541188034.358 [NAL9602](ERROR): Data Fault
2018-11-02T19:47:14.435Z,1541188034.435 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T19:47:14.436Z,1541188034.436 [CBIT](CRITICAL): Data Fault in component: NAL9602
2018-11-02T19:47:14.758Z,1541188034.758 [NAL9602](INFO): Powering down
2018-11-02T19:47:14.834Z,1541188034.834 [CommandLine](FAULT): Scheduling is paused
2018-11-02T19:47:14.834Z,1541188034.834 [CBIT](INFO): Critical error at 20181102T194714
2018-11-02T19:47:14.835Z,1541188034.835 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-11-02T19:49:14.730Z,1541188154.730 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T19:49:14.730Z,1541188154.730 [NAL9602] No Fault, FailCount= 5
2018-11-02T19:49:15.078Z,1541188155.078 [NAL9602](INFO): Powering up NAL9602
2018-11-02T19:49:26.278Z,1541188166.278 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:51:22.162Z,1541188282.162 [CommandLine](IMPORTANT): got command failComponent
2018-11-02T19:51:22.162Z,1541188282.162 [CommandLine](IMPORTANT): Failed components:
2018-11-02T19:51:22.163Z,1541188282.163 [CommandLine](IMPORTANT): No failed Components.
2018-11-02T19:51:59.555Z,1541188319.555 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T19:46:59.2Z
2018-11-02T19:51:59.555Z,1541188319.555 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T19:51:59.555Z,1541188319.555 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T19:52:03.278Z,1541188323.278 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20181102T183334/Courier0025.lzma
2018-11-02T19:52:04.055Z,1541188324.055 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0025.lzma.bak
2018-11-02T19:52:04.055Z,1541188324.055 [DataOverHttps](INFO): SBD MOMSN=8783205
2018-11-02T19:52:12.872Z,1541188332.872 [DataOverHttps](INFO): Sending 294 bytes from file Logs/20181102T183334/Express0026.lzma
2018-11-02T19:52:13.671Z,1541188333.671 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0026.lzma.bak
2018-11-02T19:52:13.671Z,1541188333.671 [DataOverHttps](INFO): SBD MOMSN=8783208
2018-11-02T19:52:14.142Z,1541188334.142 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T19:52:14.142Z,1541188334.142 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T19:52:14.142Z,1541188334.142 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T19:54:29.374Z,1541188469.374 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T19:55:00.170Z,1541188500.170 [NAL9602](INFO): Powering down
2018-11-02T19:57:14.694Z,1541188634.694 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T19:57:14.695Z,1541188634.695 [Default:CheckIn:C.Wait] Stopped
2018-11-02T19:57:14.695Z,1541188634.695 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T19:57:14.695Z,1541188634.695 [Default:CheckIn:D] Running Loop=1
2018-11-02T19:57:15.094Z,1541188635.094 [Default:CheckIn:D] Stopped
2018-11-02T19:57:15.094Z,1541188635.094 [Default:CheckIn:E] Running Loop=1
2018-11-02T19:57:18.201Z,1541188638.201 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.050716 min 
2018-11-02T19:57:18.201Z,1541188638.201 [Default:CheckIn:E] Stopped
2018-11-02T19:57:18.201Z,1541188638.201 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T19:57:18.202Z,1541188638.202 [Default:CheckIn] Stopped
2018-11-02T19:57:18.202Z,1541188638.202 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T19:57:18.202Z,1541188638.202 [Default:CheckIn](INFO): Running loop #9
2018-11-02T19:57:18.202Z,1541188638.202 [Default:CheckIn] Running Loop=9
2018-11-02T19:57:18.202Z,1541188638.202 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T19:57:18.202Z,1541188638.202 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T19:57:18.626Z,1541188638.626 [NAL9602](INFO): Powering up
2018-11-02T19:57:29.826Z,1541188649.826 [NAL9602](INFO): NAL9602 initialized
2018-11-02T19:58:01.826Z,1541188681.826 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T19:58:01.910Z,1541188681.910 [NAL9602](FAULT): received: 
+CSQ:0

OK408, 2, 0, 0, 0

OK
2018-11-02T19:58:01.910Z,1541188681.910 [NAL9602] Data Fault, FailCount= 1
2018-11-02T19:58:01.911Z,1541188681.911 [NAL9602](ERROR): Data Fault
2018-11-02T19:58:01.999Z,1541188681.999 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T19:58:02.230Z,1541188682.230 [NAL9602](INFO): Powering down
2018-11-02T19:58:03.096Z,1541188683.096 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T19:58:03.097Z,1541188683.097 [NAL9602] No Fault, FailCount= 1
2018-11-02T19:58:32.295Z,1541188712.295 [NAL9602](INFO): Powering up NAL9602
2018-11-02T19:58:43.489Z,1541188723.489 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:02:18.926Z,1541188938.926 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T19:57:18.2Z
2018-11-02T20:02:18.927Z,1541188938.927 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T20:02:18.927Z,1541188938.927 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T20:02:23.763Z,1541188943.763 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0028.lzma
2018-11-02T20:02:24.563Z,1541188944.563 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0028.lzma.bak
2018-11-02T20:02:24.563Z,1541188944.563 [DataOverHttps](INFO): SBD MOMSN=8783337
2018-11-02T20:02:33.315Z,1541188953.315 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T20:02:33.419Z,1541188953.419 [DataOverHttps](INFO): Sending 237 bytes from file Logs/20181102T183334/Express0029.lzma
2018-11-02T20:02:34.219Z,1541188954.219 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0029.lzma.bak
2018-11-02T20:02:34.219Z,1541188954.219 [DataOverHttps](INFO): SBD MOMSN=8783339
2018-11-02T20:02:34.687Z,1541188954.687 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T20:02:34.687Z,1541188954.687 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T20:02:34.687Z,1541188954.687 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T20:03:03.698Z,1541188983.698 [NAL9602](INFO): Powering down
2018-11-02T20:07:35.310Z,1541189255.310 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T20:07:35.311Z,1541189255.311 [Default:CheckIn:C.Wait] Stopped
2018-11-02T20:07:35.311Z,1541189255.311 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T20:07:35.311Z,1541189255.311 [Default:CheckIn:D] Running Loop=1
2018-11-02T20:07:35.712Z,1541189255.712 [Default:CheckIn:D] Stopped
2018-11-02T20:07:35.712Z,1541189255.712 [Default:CheckIn:E] Running Loop=1
2018-11-02T20:07:38.822Z,1541189258.822 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 90.394344 min 
2018-11-02T20:07:38.822Z,1541189258.822 [Default:CheckIn:E] Stopped
2018-11-02T20:07:38.822Z,1541189258.822 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T20:07:38.822Z,1541189258.822 [Default:CheckIn] Stopped
2018-11-02T20:07:38.822Z,1541189258.822 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T20:07:38.823Z,1541189258.823 [Default:CheckIn](INFO): Running loop #10
2018-11-02T20:07:38.823Z,1541189258.823 [Default:CheckIn] Running Loop=10
2018-11-02T20:07:38.823Z,1541189258.823 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T20:07:38.823Z,1541189258.823 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T20:07:39.283Z,1541189259.283 [NAL9602](INFO): Powering up
2018-11-02T20:07:50.478Z,1541189270.478 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:07:51.278Z,1541189271.278 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T20:07:51.278Z,1541189271.278 [NAL9602] Data Fault, FailCount= 2
2018-11-02T20:07:51.278Z,1541189271.278 [NAL9602](ERROR): Data Fault
2018-11-02T20:07:51.377Z,1541189271.377 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T20:07:51.678Z,1541189271.678 [NAL9602](INFO): Powering down
2018-11-02T20:07:52.536Z,1541189272.536 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:07:52.536Z,1541189272.536 [NAL9602] No Fault, FailCount= 2
2018-11-02T20:08:22.078Z,1541189302.078 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:08:33.282Z,1541189313.282 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:08:51.704Z,1541189331.704 [NAL9602](INFO): SBD MO Status=0, MOMSN=10408, MT Status=0, MTMSN=0
2018-11-02T20:08:51.704Z,1541189331.704 [NAL9602](INFO): No messages in MT queue
2018-11-02T20:12:39.172Z,1541189559.172 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T20:07:38.8Z
2018-11-02T20:12:39.173Z,1541189559.173 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T20:12:39.173Z,1541189559.173 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T20:12:44.055Z,1541189564.055 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0031.lzma
2018-11-02T20:12:44.855Z,1541189564.855 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0031.lzma.bak
2018-11-02T20:12:44.855Z,1541189564.855 [DataOverHttps](INFO): SBD MOMSN=8783395
2018-11-02T20:12:53.854Z,1541189573.854 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20181102T183334/Express0032.lzma
2018-11-02T20:12:54.655Z,1541189574.655 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0032.lzma.bak
2018-11-02T20:12:54.655Z,1541189574.655 [DataOverHttps](INFO): SBD MOMSN=8783397
2018-11-02T20:12:55.124Z,1541189575.124 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T20:12:55.124Z,1541189575.124 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T20:12:55.124Z,1541189575.124 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T20:13:14.354Z,1541189594.354 [NAL9602](INFO): Powering down
2018-11-02T20:17:55.917Z,1541189875.917 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T20:17:55.918Z,1541189875.918 [Default:CheckIn:C.Wait] Stopped
2018-11-02T20:17:55.918Z,1541189875.918 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T20:17:55.918Z,1541189875.918 [Default:CheckIn:D] Running Loop=1
2018-11-02T20:17:59.228Z,1541189879.228 [Default:CheckIn:D] Stopped
2018-11-02T20:17:59.228Z,1541189879.228 [Default:CheckIn:E] Running Loop=1
2018-11-02T20:17:59.370Z,1541189879.370 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 100.786279 min 
2018-11-02T20:17:59.370Z,1541189879.370 [Default:CheckIn:E] Stopped
2018-11-02T20:17:59.370Z,1541189879.370 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T20:17:59.370Z,1541189879.370 [Default:CheckIn] Stopped
2018-11-02T20:17:59.370Z,1541189879.370 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T20:17:59.371Z,1541189879.371 [Default:CheckIn](INFO): Running loop #11
2018-11-02T20:17:59.371Z,1541189879.371 [Default:CheckIn] Running Loop=11
2018-11-02T20:17:59.371Z,1541189879.371 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T20:17:59.371Z,1541189879.371 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T20:18:00.082Z,1541189880.082 [NAL9602](INFO): Powering up
2018-11-02T20:18:11.278Z,1541189891.278 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:18:32.879Z,1541189912.879 [NAL9602](INFO): SBD MO Status=2, MOMSN=10409, MT Status=2, MTMSN=0
2018-11-02T20:18:32.880Z,1541189912.880 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T20:19:22.479Z,1541189962.479 [NAL9602](INFO): SBD MO Status=2, MOMSN=10409, MT Status=2, MTMSN=0
2018-11-02T20:19:22.480Z,1541189962.480 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T20:20:05.659Z,1541190005.659 [NAL9602](INFO): SBD MO Status=0, MOMSN=10409, MT Status=0, MTMSN=0
2018-11-02T20:20:05.659Z,1541190005.659 [NAL9602](INFO): No messages in MT queue
2018-11-02T20:20:05.660Z,1541190005.660 [NAL9602](INFO): Failure count cleared after critical for NAL9602
2018-11-02T20:20:06.458Z,1541190006.458 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T20:20:06.458Z,1541190006.458 [NAL9602] Data Fault, FailCount= 1
2018-11-02T20:20:06.458Z,1541190006.458 [NAL9602](ERROR): Data Fault
2018-11-02T20:20:06.568Z,1541190006.568 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T20:20:06.858Z,1541190006.858 [NAL9602](INFO): Powering down
2018-11-02T20:20:07.709Z,1541190007.709 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:20:07.709Z,1541190007.709 [NAL9602] No Fault, FailCount= 1
2018-11-02T20:20:37.258Z,1541190037.258 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:20:48.458Z,1541190048.458 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:23:00.371Z,1541190180.371 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T20:17:59.4Z
2018-11-02T20:23:00.371Z,1541190180.371 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T20:23:00.371Z,1541190180.371 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T20:23:05.270Z,1541190185.270 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0034.lzma
2018-11-02T20:23:06.055Z,1541190186.055 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0034.lzma.bak
2018-11-02T20:23:06.055Z,1541190186.055 [DataOverHttps](INFO): SBD MOMSN=8783470
2018-11-02T20:23:15.005Z,1541190195.005 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20181102T183334/Express0035.lzma
2018-11-02T20:23:15.783Z,1541190195.783 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0035.lzma.bak
2018-11-02T20:23:15.783Z,1541190195.783 [DataOverHttps](INFO): SBD MOMSN=8783472
2018-11-02T20:23:16.254Z,1541190196.254 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T20:23:16.254Z,1541190196.254 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T20:23:16.254Z,1541190196.254 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T20:23:30.586Z,1541190210.586 [NAL9602](INFO): Powering down
2018-11-02T20:28:16.736Z,1541190496.736 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T20:28:16.736Z,1541190496.736 [Default:CheckIn:C.Wait] Stopped
2018-11-02T20:28:16.736Z,1541190496.736 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T20:28:16.737Z,1541190496.737 [Default:CheckIn:D] Running Loop=1
2018-11-02T20:28:17.139Z,1541190497.139 [Default:CheckIn:D] Stopped
2018-11-02T20:28:17.139Z,1541190497.139 [Default:CheckIn:E] Running Loop=1
2018-11-02T20:28:20.253Z,1541190500.253 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 111.084798 min 
2018-11-02T20:28:20.253Z,1541190500.253 [Default:CheckIn:E] Stopped
2018-11-02T20:28:20.253Z,1541190500.253 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T20:28:20.253Z,1541190500.253 [Default:CheckIn] Stopped
2018-11-02T20:28:20.253Z,1541190500.253 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T20:28:20.254Z,1541190500.254 [Default:CheckIn](INFO): Running loop #12
2018-11-02T20:28:20.254Z,1541190500.254 [Default:CheckIn] Running Loop=12
2018-11-02T20:28:20.254Z,1541190500.254 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T20:28:20.254Z,1541190500.254 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T20:28:20.698Z,1541190500.698 [NAL9602](INFO): Powering up
2018-11-02T20:28:31.898Z,1541190511.898 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:28:44.299Z,1541190524.299 [NAL9602](INFO): SBD MO Status=0, MOMSN=10410, MT Status=0, MTMSN=0
2018-11-02T20:28:44.299Z,1541190524.299 [NAL9602](INFO): No messages in MT queue
2018-11-02T20:30:50.582Z,1541190650.582 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T20:30:50.582Z,1541190650.582 [NAL9602] Data Fault, FailCount= 1
2018-11-02T20:30:50.582Z,1541190650.582 [NAL9602](ERROR): Data Fault
2018-11-02T20:30:50.677Z,1541190650.677 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T20:30:50.982Z,1541190650.982 [NAL9602](INFO): Powering down
2018-11-02T20:30:51.841Z,1541190651.841 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:30:51.841Z,1541190651.841 [NAL9602] No Fault, FailCount= 1
2018-11-02T20:31:21.386Z,1541190681.386 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:31:32.582Z,1541190692.582 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:33:21.044Z,1541190801.044 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T20:28:20.3Z
2018-11-02T20:33:21.044Z,1541190801.044 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T20:33:21.044Z,1541190801.044 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T20:33:25.900Z,1541190805.900 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0037.lzma
2018-11-02T20:33:26.691Z,1541190806.691 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0037.lzma.bak
2018-11-02T20:33:26.691Z,1541190806.691 [DataOverHttps](INFO): SBD MOMSN=8783537
2018-11-02T20:33:35.805Z,1541190815.805 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20181102T183334/Express0038.lzma
2018-11-02T20:33:36.568Z,1541190816.568 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0038.lzma.bak
2018-11-02T20:33:36.568Z,1541190816.568 [DataOverHttps](INFO): SBD MOMSN=8783539
2018-11-02T20:33:37.032Z,1541190817.032 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T20:33:37.033Z,1541190817.033 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T20:33:37.033Z,1541190817.033 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T20:33:51.354Z,1541190831.354 [NAL9602](INFO): Powering down
2018-11-02T20:38:37.620Z,1541191117.620 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T20:38:37.620Z,1541191117.620 [Default:CheckIn:C.Wait] Stopped
2018-11-02T20:38:37.621Z,1541191117.621 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T20:38:37.621Z,1541191117.621 [Default:CheckIn:D] Running Loop=1
2018-11-02T20:38:38.019Z,1541191118.019 [Default:CheckIn:D] Stopped
2018-11-02T20:38:38.019Z,1541191118.019 [Default:CheckIn:E] Running Loop=1
2018-11-02T20:38:38.415Z,1541191118.415 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 121.432796 min 
2018-11-02T20:38:38.415Z,1541191118.415 [Default:CheckIn:E] Stopped
2018-11-02T20:38:38.416Z,1541191118.416 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T20:38:38.416Z,1541191118.416 [Default:CheckIn] Stopped
2018-11-02T20:38:38.416Z,1541191118.416 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T20:38:38.416Z,1541191118.416 [Default:CheckIn](INFO): Running loop #13
2018-11-02T20:38:38.416Z,1541191118.416 [Default:CheckIn] Running Loop=13
2018-11-02T20:38:38.416Z,1541191118.416 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T20:38:38.416Z,1541191118.416 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T20:38:42.014Z,1541191122.014 [NAL9602](INFO): Powering up
2018-11-02T20:38:52.915Z,1541191132.915 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:39:37.721Z,1541191177.721 [NAL9602](INFO): SBD MO Status=2, MOMSN=10411, MT Status=2, MTMSN=0
2018-11-02T20:39:37.721Z,1541191177.721 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T20:39:51.103Z,1541191191.103 [NAL9602](INFO): SBD MO Status=2, MOMSN=10411, MT Status=2, MTMSN=0
2018-11-02T20:39:51.104Z,1541191191.104 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T20:40:19.495Z,1541191219.495 [NAL9602](INFO): SBD MO Status=2, MOMSN=10411, MT Status=2, MTMSN=0
2018-11-02T20:40:19.496Z,1541191219.496 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T20:41:07.499Z,1541191267.499 [NAL9602](INFO): SBD MO Status=0, MOMSN=10411, MT Status=0, MTMSN=0
2018-11-02T20:41:07.500Z,1541191267.500 [NAL9602](INFO): No messages in MT queue
2018-11-02T20:41:26.701Z,1541191286.701 [NAL9602](INFO): GPS fix at 20181102T204124: (36.802637, -121.787880)
2018-11-02T20:41:26.735Z,1541191286.735 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T20:41:26.735Z,1541191286.735 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T20:41:31.140Z,1541191291.140 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181102T183334/Courier0040.lzma
2018-11-02T20:41:31.907Z,1541191291.907 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0040.lzma.bak
2018-11-02T20:41:31.907Z,1541191291.907 [DataOverHttps](INFO): SBD MOMSN=8783644
2018-11-02T20:41:40.735Z,1541191300.735 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20181102T183334/Express0041.lzma
2018-11-02T20:41:41.535Z,1541191301.535 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0041.lzma.bak
2018-11-02T20:41:41.535Z,1541191301.535 [DataOverHttps](INFO): SBD MOMSN=8783647
2018-11-02T20:41:42.020Z,1541191302.020 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T20:41:42.020Z,1541191302.020 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T20:41:42.020Z,1541191302.020 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T20:42:01.306Z,1541191321.306 [NAL9602](INFO): Powering down
2018-11-02T20:46:42.758Z,1541191602.758 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T20:46:42.758Z,1541191602.758 [Default:CheckIn:C.Wait] Stopped
2018-11-02T20:46:42.758Z,1541191602.758 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T20:46:42.758Z,1541191602.758 [Default:CheckIn:D] Running Loop=1
2018-11-02T20:46:45.861Z,1541191605.861 [Default:CheckIn:D] Stopped
2018-11-02T20:46:45.861Z,1541191605.861 [Default:CheckIn:E] Running Loop=1
2018-11-02T20:46:45.994Z,1541191605.994 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 129.563501 min 
2018-11-02T20:46:45.994Z,1541191605.994 [Default:CheckIn:E] Stopped
2018-11-02T20:46:45.995Z,1541191605.995 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T20:46:45.995Z,1541191605.995 [Default:CheckIn] Stopped
2018-11-02T20:46:45.995Z,1541191605.995 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T20:46:45.995Z,1541191605.995 [Default:CheckIn](INFO): Running loop #14
2018-11-02T20:46:45.995Z,1541191605.995 [Default:CheckIn] Running Loop=14
2018-11-02T20:46:45.995Z,1541191605.995 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T20:46:45.995Z,1541191605.995 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T20:46:46.693Z,1541191606.693 [NAL9602](INFO): Powering up
2018-11-02T20:46:57.886Z,1541191617.886 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:47:08.687Z,1541191628.687 [NAL9602](INFO): SBD MO Status=0, MOMSN=10412, MT Status=0, MTMSN=0
2018-11-02T20:47:08.688Z,1541191628.688 [NAL9602](INFO): No messages in MT queue
2018-11-02T20:51:47.144Z,1541191907.144 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T20:46:45.0Z
2018-11-02T20:51:47.144Z,1541191907.144 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T20:51:47.144Z,1541191907.144 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T20:51:52.093Z,1541191912.093 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0043.lzma
2018-11-02T20:51:52.871Z,1541191912.871 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0043.lzma.bak
2018-11-02T20:51:52.871Z,1541191912.871 [DataOverHttps](INFO): SBD MOMSN=8783761
2018-11-02T20:52:01.904Z,1541191921.904 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20181102T183334/Express0044.lzma
2018-11-02T20:52:02.703Z,1541191922.703 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0044.lzma.bak
2018-11-02T20:52:02.703Z,1541191922.703 [DataOverHttps](INFO): SBD MOMSN=8783763
2018-11-02T20:52:03.187Z,1541191923.187 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T20:52:03.187Z,1541191923.187 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T20:52:03.187Z,1541191923.187 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T20:52:17.530Z,1541191937.530 [NAL9602](INFO): Powering down
2018-11-02T20:57:03.593Z,1541192223.593 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T20:57:03.593Z,1541192223.593 [Default:CheckIn:C.Wait] Stopped
2018-11-02T20:57:03.593Z,1541192223.593 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T20:57:03.593Z,1541192223.593 [Default:CheckIn:D] Running Loop=1
2018-11-02T20:57:03.996Z,1541192223.996 [Default:CheckIn:D] Stopped
2018-11-02T20:57:03.996Z,1541192223.996 [Default:CheckIn:E] Running Loop=1
2018-11-02T20:57:04.399Z,1541192224.399 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 139.865755 min 
2018-11-02T20:57:04.399Z,1541192224.399 [Default:CheckIn:E] Stopped
2018-11-02T20:57:04.399Z,1541192224.399 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T20:57:04.399Z,1541192224.399 [Default:CheckIn] Stopped
2018-11-02T20:57:04.399Z,1541192224.399 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T20:57:04.400Z,1541192224.400 [Default:CheckIn](INFO): Running loop #15
2018-11-02T20:57:04.400Z,1541192224.400 [Default:CheckIn] Running Loop=15
2018-11-02T20:57:04.400Z,1541192224.400 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T20:57:04.400Z,1541192224.400 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T20:57:07.888Z,1541192227.888 [NAL9602](INFO): Powering up
2018-11-02T20:57:18.774Z,1541192238.774 [NAL9602](INFO): NAL9602 initialized
2018-11-02T20:57:19.570Z,1541192239.570 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T20:57:19.570Z,1541192239.570 [NAL9602] Data Fault, FailCount= 1
2018-11-02T20:57:19.570Z,1541192239.570 [NAL9602](ERROR): Data Fault
2018-11-02T20:57:19.672Z,1541192239.672 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T20:57:19.978Z,1541192239.978 [NAL9602](INFO): Powering down
2018-11-02T20:57:20.861Z,1541192240.861 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T20:57:20.861Z,1541192240.861 [NAL9602] No Fault, FailCount= 1
2018-11-02T20:57:50.374Z,1541192270.374 [NAL9602](INFO): Powering up NAL9602
2018-11-02T20:58:01.570Z,1541192281.570 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:02:04.517Z,1541192524.517 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T20:57:04.4Z
2018-11-02T21:02:04.518Z,1541192524.518 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T21:02:04.518Z,1541192524.518 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T21:02:08.663Z,1541192528.663 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0046.lzma
2018-11-02T21:02:09.463Z,1541192529.463 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0046.lzma.bak
2018-11-02T21:02:09.463Z,1541192529.463 [DataOverHttps](INFO): SBD MOMSN=8783824
2018-11-02T21:02:18.279Z,1541192538.279 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20181102T183334/Express0047.lzma
2018-11-02T21:02:19.075Z,1541192539.075 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0047.lzma.bak
2018-11-02T21:02:19.075Z,1541192539.075 [DataOverHttps](INFO): SBD MOMSN=8783826
2018-11-02T21:02:19.546Z,1541192539.546 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T21:02:19.547Z,1541192539.547 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T21:02:19.547Z,1541192539.547 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T21:03:04.502Z,1541192584.502 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T21:03:35.294Z,1541192615.294 [NAL9602](INFO): Powering down
2018-11-02T21:07:20.054Z,1541192840.054 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T21:07:20.054Z,1541192840.054 [Default:CheckIn:C.Wait] Stopped
2018-11-02T21:07:20.054Z,1541192840.054 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T21:07:20.054Z,1541192840.054 [Default:CheckIn:D] Running Loop=1
2018-11-02T21:07:20.419Z,1541192840.419 [Default:CheckIn:D] Stopped
2018-11-02T21:07:20.419Z,1541192840.419 [Default:CheckIn:E] Running Loop=1
2018-11-02T21:07:20.819Z,1541192840.819 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 150.139469 min 
2018-11-02T21:07:20.819Z,1541192840.819 [Default:CheckIn:E] Stopped
2018-11-02T21:07:20.819Z,1541192840.819 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T21:07:20.819Z,1541192840.819 [Default:CheckIn] Stopped
2018-11-02T21:07:20.820Z,1541192840.820 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T21:07:20.820Z,1541192840.820 [Default:CheckIn](INFO): Running loop #16
2018-11-02T21:07:20.820Z,1541192840.820 [Default:CheckIn] Running Loop=16
2018-11-02T21:07:20.820Z,1541192840.820 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T21:07:20.820Z,1541192840.820 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T21:07:24.310Z,1541192844.310 [NAL9602](INFO): Powering up
2018-11-02T21:07:35.182Z,1541192855.182 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:08:07.182Z,1541192887.182 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T21:08:07.261Z,1541192887.261 [NAL9602](FAULT): received: 
+CSQ:0

OK412, 0, 0, 0, 0

OK
2018-11-02T21:08:07.261Z,1541192887.261 [NAL9602] Data Fault, FailCount= 2
2018-11-02T21:08:07.261Z,1541192887.261 [NAL9602](ERROR): Data Fault
2018-11-02T21:08:07.304Z,1541192887.304 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T21:08:07.582Z,1541192887.582 [NAL9602](INFO): Powering down
2018-11-02T21:08:08.448Z,1541192888.448 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T21:08:08.448Z,1541192888.448 [NAL9602] No Fault, FailCount= 2
2018-11-02T21:08:37.598Z,1541192917.598 [NAL9602](INFO): Powering up NAL9602
2018-11-02T21:08:48.398Z,1541192928.398 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:08:49.198Z,1541192929.198 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T21:08:49.198Z,1541192929.198 [NAL9602] Data Fault, FailCount= 3
2018-11-02T21:08:49.198Z,1541192929.198 [NAL9602](ERROR): Data Fault
2018-11-02T21:08:49.282Z,1541192929.282 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T21:08:49.598Z,1541192929.598 [NAL9602](INFO): Powering down
2018-11-02T21:08:50.460Z,1541192930.460 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T21:08:50.460Z,1541192930.460 [NAL9602] No Fault, FailCount= 3
2018-11-02T21:09:19.602Z,1541192959.602 [NAL9602](INFO): Powering up NAL9602
2018-11-02T21:09:30.510Z,1541192970.510 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:12:21.224Z,1541193141.224 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T21:07:20.8Z
2018-11-02T21:12:21.224Z,1541193141.224 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T21:12:21.224Z,1541193141.224 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T21:12:25.219Z,1541193145.219 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0049.lzma
2018-11-02T21:12:25.991Z,1541193145.991 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0049.lzma.bak
2018-11-02T21:12:25.991Z,1541193145.991 [DataOverHttps](INFO): SBD MOMSN=8783893
2018-11-02T21:12:34.854Z,1541193154.854 [DataOverHttps](INFO): Sending 253 bytes from file Logs/20181102T183334/Express0050.lzma
2018-11-02T21:12:35.655Z,1541193155.655 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0050.lzma.bak
2018-11-02T21:12:35.655Z,1541193155.655 [DataOverHttps](INFO): SBD MOMSN=8783895
2018-11-02T21:12:36.139Z,1541193156.139 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T21:12:36.140Z,1541193156.140 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T21:12:36.140Z,1541193156.140 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T21:12:39.586Z,1541193159.586 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T21:13:10.082Z,1541193190.082 [NAL9602](INFO): Powering down
2018-11-02T21:17:36.755Z,1541193456.755 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T21:17:36.755Z,1541193456.755 [Default:CheckIn:C.Wait] Stopped
2018-11-02T21:17:36.755Z,1541193456.755 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T21:17:36.755Z,1541193456.755 [Default:CheckIn:D] Running Loop=1
2018-11-02T21:17:37.158Z,1541193457.158 [Default:CheckIn:D] Stopped
2018-11-02T21:17:37.158Z,1541193457.158 [Default:CheckIn:E] Running Loop=1
2018-11-02T21:17:40.453Z,1541193460.453 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 160.418457 min 
2018-11-02T21:17:40.453Z,1541193460.453 [Default:CheckIn:E] Stopped
2018-11-02T21:17:40.453Z,1541193460.453 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T21:17:40.453Z,1541193460.453 [Default:CheckIn] Stopped
2018-11-02T21:17:40.453Z,1541193460.453 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T21:17:40.454Z,1541193460.454 [Default:CheckIn](INFO): Running loop #17
2018-11-02T21:17:40.454Z,1541193460.454 [Default:CheckIn] Running Loop=17
2018-11-02T21:17:40.454Z,1541193460.454 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T21:17:40.454Z,1541193460.454 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T21:17:40.886Z,1541193460.886 [NAL9602](INFO): Powering up
2018-11-02T21:17:52.078Z,1541193472.078 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:18:24.078Z,1541193504.078 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T21:18:24.157Z,1541193504.157 [NAL9602](FAULT): received: 
+CSQ:0

OK412, 0, 0, 0, 0

OK
2018-11-02T21:18:24.157Z,1541193504.157 [NAL9602] Data Fault, FailCount= 4
2018-11-02T21:18:24.157Z,1541193504.157 [NAL9602](ERROR): Data Fault
2018-11-02T21:18:24.200Z,1541193504.200 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T21:18:24.475Z,1541193504.475 [NAL9602](INFO): Powering down
2018-11-02T21:18:25.345Z,1541193505.345 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T21:18:25.345Z,1541193505.345 [NAL9602] No Fault, FailCount= 4
2018-11-02T21:18:54.482Z,1541193534.482 [NAL9602](INFO): Powering up NAL9602
2018-11-02T21:19:05.682Z,1541193545.682 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:22:40.771Z,1541193760.771 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T21:17:40.5Z
2018-11-02T21:22:40.771Z,1541193760.771 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T21:22:40.771Z,1541193760.771 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T21:22:45.635Z,1541193765.635 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0052.lzma
2018-11-02T21:22:46.423Z,1541193766.423 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0052.lzma.bak
2018-11-02T21:22:46.423Z,1541193766.423 [DataOverHttps](INFO): SBD MOMSN=8783964
2018-11-02T21:22:55.246Z,1541193775.246 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T21:22:55.362Z,1541193775.362 [DataOverHttps](INFO): Sending 236 bytes from file Logs/20181102T183334/Express0053.lzma
2018-11-02T21:22:56.155Z,1541193776.155 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0053.lzma.bak
2018-11-02T21:22:56.155Z,1541193776.155 [DataOverHttps](INFO): SBD MOMSN=8783966
2018-11-02T21:22:56.626Z,1541193776.626 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T21:22:56.627Z,1541193776.627 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T21:22:56.627Z,1541193776.627 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T21:23:25.750Z,1541193805.750 [NAL9602](INFO): Powering down
2018-11-02T21:27:57.335Z,1541194077.335 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T21:27:57.335Z,1541194077.335 [Default:CheckIn:C.Wait] Stopped
2018-11-02T21:27:57.335Z,1541194077.335 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T21:27:57.335Z,1541194077.335 [Default:CheckIn:D] Running Loop=1
2018-11-02T21:27:57.748Z,1541194077.748 [Default:CheckIn:D] Stopped
2018-11-02T21:27:57.748Z,1541194077.748 [Default:CheckIn:E] Running Loop=1
2018-11-02T21:27:58.153Z,1541194078.153 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 170.761605 min 
2018-11-02T21:27:58.153Z,1541194078.153 [Default:CheckIn:E] Stopped
2018-11-02T21:27:58.153Z,1541194078.153 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T21:27:58.154Z,1541194078.154 [Default:CheckIn] Stopped
2018-11-02T21:27:58.154Z,1541194078.154 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T21:27:58.154Z,1541194078.154 [Default:CheckIn](INFO): Running loop #18
2018-11-02T21:27:58.154Z,1541194078.154 [Default:CheckIn] Running Loop=18
2018-11-02T21:27:58.154Z,1541194078.154 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T21:27:58.154Z,1541194078.154 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T21:28:01.338Z,1541194081.338 [NAL9602](INFO): Powering up
2018-11-02T21:28:12.490Z,1541194092.490 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:28:13.282Z,1541194093.282 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T21:28:13.282Z,1541194093.282 [NAL9602] Data Fault, FailCount= 5
2018-11-02T21:28:13.282Z,1541194093.282 [NAL9602](ERROR): Data Fault
2018-11-02T21:28:13.360Z,1541194093.360 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T21:28:13.365Z,1541194093.365 [CBIT](CRITICAL): Data Fault in component: NAL9602
2018-11-02T21:28:13.682Z,1541194093.682 [NAL9602](INFO): Powering down
2018-11-02T21:28:13.746Z,1541194093.746 [CBIT](INFO): Critical error at 20181102T212813
2018-11-02T21:30:13.358Z,1541194213.358 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T21:30:13.358Z,1541194213.358 [NAL9602] No Fault, FailCount= 5
2018-11-02T21:30:13.698Z,1541194213.698 [NAL9602](INFO): Powering up NAL9602
2018-11-02T21:30:24.903Z,1541194224.903 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:32:58.231Z,1541194378.231 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T21:27:58.2Z
2018-11-02T21:32:58.231Z,1541194378.231 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T21:32:58.231Z,1541194378.231 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T21:33:02.260Z,1541194382.260 [DataOverHttps](INFO): Sending 69 bytes from file Logs/20181102T183334/Courier0055.lzma
2018-11-02T21:33:03.059Z,1541194383.059 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0055.lzma.bak
2018-11-02T21:33:03.059Z,1541194383.059 [DataOverHttps](INFO): SBD MOMSN=8784033
2018-11-02T21:33:11.914Z,1541194391.914 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20181102T183334/Express0056.lzma
2018-11-02T21:33:12.691Z,1541194392.691 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0056.lzma.bak
2018-11-02T21:33:12.691Z,1541194392.691 [DataOverHttps](INFO): SBD MOMSN=8784036
2018-11-02T21:33:13.177Z,1541194393.177 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T21:33:13.177Z,1541194393.177 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T21:33:13.177Z,1541194393.177 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T21:35:27.978Z,1541194527.978 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T21:35:58.778Z,1541194558.778 [NAL9602](INFO): Powering down
2018-11-02T21:38:13.938Z,1541194693.938 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T21:38:13.939Z,1541194693.939 [Default:CheckIn:C.Wait] Stopped
2018-11-02T21:38:13.939Z,1541194693.939 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T21:38:13.939Z,1541194693.939 [Default:CheckIn:D] Running Loop=1
2018-11-02T21:38:14.332Z,1541194694.332 [Default:CheckIn:D] Stopped
2018-11-02T21:38:14.332Z,1541194694.332 [Default:CheckIn:E] Running Loop=1
2018-11-02T21:38:17.442Z,1541194697.442 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 181.038021 min 
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn:E] Stopped
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn] Stopped
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn](INFO): Running loop #19
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn] Running Loop=19
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T21:38:17.443Z,1541194697.443 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T21:38:17.898Z,1541194697.898 [NAL9602](INFO): Powering up
2018-11-02T21:38:28.698Z,1541194708.698 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:39:00.702Z,1541194740.702 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T21:39:00.777Z,1541194740.777 [NAL9602](FAULT): received: 
+CSQ:0

OK412, 0, 0, 0, 0

OK
2018-11-02T21:39:00.777Z,1541194740.777 [NAL9602] Data Fault, FailCount= 1
2018-11-02T21:39:00.777Z,1541194740.777 [NAL9602](ERROR): Data Fault
2018-11-02T21:39:00.862Z,1541194740.862 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T21:39:01.098Z,1541194741.098 [NAL9602](INFO): Powering down
2018-11-02T21:39:01.950Z,1541194741.950 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T21:39:01.950Z,1541194741.950 [NAL9602] No Fault, FailCount= 1
2018-11-02T21:39:31.486Z,1541194771.486 [NAL9602](INFO): Powering up NAL9602
2018-11-02T21:39:42.686Z,1541194782.686 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:43:18.194Z,1541194998.194 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T21:38:17.4Z
2018-11-02T21:43:18.205Z,1541194998.205 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T21:43:18.205Z,1541194998.205 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T21:43:23.053Z,1541195003.053 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0058.lzma
2018-11-02T21:43:23.855Z,1541195003.855 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0058.lzma.bak
2018-11-02T21:43:23.855Z,1541195003.855 [DataOverHttps](INFO): SBD MOMSN=8784098
2018-11-02T21:43:32.859Z,1541195012.859 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T21:43:32.957Z,1541195012.957 [DataOverHttps](INFO): Sending 233 bytes from file Logs/20181102T183334/Express0059.lzma
2018-11-02T21:43:33.727Z,1541195013.727 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0059.lzma.bak
2018-11-02T21:43:33.727Z,1541195013.727 [DataOverHttps](INFO): SBD MOMSN=8784100
2018-11-02T21:43:34.211Z,1541195014.211 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T21:43:34.211Z,1541195014.211 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T21:43:34.211Z,1541195014.211 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T21:44:03.338Z,1541195043.338 [NAL9602](INFO): Powering down
2018-11-02T21:48:34.639Z,1541195314.639 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T21:48:34.639Z,1541195314.639 [Default:CheckIn:C.Wait] Stopped
2018-11-02T21:48:34.639Z,1541195314.639 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T21:48:34.639Z,1541195314.639 [Default:CheckIn:D] Running Loop=1
2018-11-02T21:48:35.037Z,1541195315.037 [Default:CheckIn:D] Stopped
2018-11-02T21:48:35.037Z,1541195315.037 [Default:CheckIn:E] Running Loop=1
2018-11-02T21:48:35.442Z,1541195315.442 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 191.383105 min 
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn:E] Stopped
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn] Stopped
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn](INFO): Running loop #20
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn] Running Loop=20
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T21:48:35.443Z,1541195315.443 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T21:48:38.928Z,1541195318.928 [NAL9602](INFO): Powering up
2018-11-02T21:48:49.819Z,1541195329.819 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:48:50.618Z,1541195330.618 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T21:48:50.618Z,1541195330.618 [NAL9602] Data Fault, FailCount= 2
2018-11-02T21:48:50.618Z,1541195330.618 [NAL9602](ERROR): Data Fault
2018-11-02T21:48:50.706Z,1541195330.706 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T21:48:51.022Z,1541195331.022 [NAL9602](INFO): Powering down
2018-11-02T21:48:51.870Z,1541195331.870 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T21:48:51.870Z,1541195331.870 [NAL9602] No Fault, FailCount= 2
2018-11-02T21:49:21.422Z,1541195361.422 [NAL9602](INFO): Powering up NAL9602
2018-11-02T21:49:32.618Z,1541195372.618 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:50:58.707Z,1541195458.707 [NAL9602](INFO): SBD MO Status=2, MOMSN=10413, MT Status=2, MTMSN=0
2018-11-02T21:50:58.708Z,1541195458.708 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T21:51:20.307Z,1541195480.307 [NAL9602](INFO): SBD MO Status=2, MOMSN=10413, MT Status=2, MTMSN=0
2018-11-02T21:51:20.307Z,1541195480.307 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T21:51:33.107Z,1541195493.107 [NAL9602](INFO): SBD MO Status=2, MOMSN=10413, MT Status=2, MTMSN=0
2018-11-02T21:51:33.108Z,1541195493.108 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T21:53:00.360Z,1541195580.360 [CommandLine](IMPORTANT): got command failComponent
2018-11-02T21:53:00.360Z,1541195580.360 [CommandLine](IMPORTANT): Failed components:
2018-11-02T21:53:00.360Z,1541195580.360 [CommandLine](IMPORTANT): No failed Components.
2018-11-02T21:53:35.594Z,1541195615.594 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T21:48:35.4Z
2018-11-02T21:53:35.594Z,1541195615.594 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T21:53:35.594Z,1541195615.594 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T21:53:39.236Z,1541195619.236 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0061.lzma
2018-11-02T21:53:40.023Z,1541195620.023 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0061.lzma.bak
2018-11-02T21:53:40.023Z,1541195620.023 [DataOverHttps](INFO): SBD MOMSN=8784158
2018-11-02T21:53:49.031Z,1541195629.031 [DataOverHttps](INFO): Sending 266 bytes from file Logs/20181102T183334/Express0062.lzma
2018-11-02T21:53:49.831Z,1541195629.831 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0062.lzma.bak
2018-11-02T21:53:49.831Z,1541195629.831 [DataOverHttps](INFO): SBD MOMSN=8784161
2018-11-02T21:53:50.322Z,1541195630.322 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T21:53:50.322Z,1541195630.322 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T21:53:50.322Z,1541195630.322 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T21:54:35.630Z,1541195675.630 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T21:55:06.434Z,1541195706.434 [NAL9602](INFO): Powering down
2018-11-02T21:58:50.706Z,1541195930.706 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T21:58:50.706Z,1541195930.706 [Default:CheckIn:C.Wait] Stopped
2018-11-02T21:58:50.706Z,1541195930.706 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T21:58:50.706Z,1541195930.706 [Default:CheckIn:D] Running Loop=1
2018-11-02T21:58:51.109Z,1541195931.109 [Default:CheckIn:D] Stopped
2018-11-02T21:58:51.109Z,1541195931.109 [Default:CheckIn:E] Running Loop=1
2018-11-02T21:58:51.511Z,1541195931.511 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 201.650960 min 
2018-11-02T21:58:51.511Z,1541195931.511 [Default:CheckIn:E] Stopped
2018-11-02T21:58:51.511Z,1541195931.511 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T21:58:51.511Z,1541195931.511 [Default:CheckIn] Stopped
2018-11-02T21:58:51.511Z,1541195931.511 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T21:58:51.512Z,1541195931.512 [Default:CheckIn](INFO): Running loop #21
2018-11-02T21:58:51.512Z,1541195931.512 [Default:CheckIn] Running Loop=21
2018-11-02T21:58:51.512Z,1541195931.512 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T21:58:51.512Z,1541195931.512 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T21:58:54.993Z,1541195934.993 [NAL9602](INFO): Powering up
2018-11-02T21:59:05.874Z,1541195945.874 [NAL9602](INFO): NAL9602 initialized
2018-11-02T21:59:37.870Z,1541195977.870 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T21:59:37.953Z,1541195977.953 [NAL9602](FAULT): received: 
+CSQ:0

OK413, 2, 0, 0, 0

OK
2018-11-02T21:59:37.953Z,1541195977.953 [NAL9602] Data Fault, FailCount= 3
2018-11-02T21:59:37.953Z,1541195977.953 [NAL9602](ERROR): Data Fault
2018-11-02T21:59:38.030Z,1541195978.030 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T21:59:38.267Z,1541195978.267 [NAL9602](INFO): Powering down
2018-11-02T21:59:39.133Z,1541195979.133 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T21:59:39.133Z,1541195979.133 [NAL9602] No Fault, FailCount= 3
2018-11-02T22:00:08.642Z,1541196008.642 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:00:19.442Z,1541196019.442 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:00:20.242Z,1541196020.242 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T22:00:20.242Z,1541196020.242 [NAL9602] Data Fault, FailCount= 4
2018-11-02T22:00:20.242Z,1541196020.242 [NAL9602](ERROR): Data Fault
2018-11-02T22:00:20.325Z,1541196020.325 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T22:00:20.642Z,1541196020.642 [NAL9602](INFO): Powering down
2018-11-02T22:00:21.524Z,1541196021.524 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T22:00:21.524Z,1541196021.524 [NAL9602] No Fault, FailCount= 4
2018-11-02T22:00:51.042Z,1541196051.042 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:01:01.874Z,1541196061.874 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:03:19.611Z,1541196199.611 [NAL9602](INFO): SBD MO Status=2, MOMSN=10413, MT Status=2, MTMSN=0
2018-11-02T22:03:19.612Z,1541196199.612 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T22:03:51.666Z,1541196231.666 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T21:58:51.5Z
2018-11-02T22:03:51.666Z,1541196231.666 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T22:03:51.666Z,1541196231.666 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T22:03:55.690Z,1541196235.690 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0064.lzma
2018-11-02T22:03:56.483Z,1541196236.483 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0064.lzma.bak
2018-11-02T22:03:56.483Z,1541196236.483 [DataOverHttps](INFO): SBD MOMSN=8784233
2018-11-02T22:04:05.367Z,1541196245.367 [DataOverHttps](INFO): Sending 254 bytes from file Logs/20181102T183334/Express0065.lzma
2018-11-02T22:04:06.151Z,1541196246.151 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0065.lzma.bak
2018-11-02T22:04:06.151Z,1541196246.151 [DataOverHttps](INFO): SBD MOMSN=8784235
2018-11-02T22:04:06.636Z,1541196246.636 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T22:04:06.636Z,1541196246.636 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T22:04:06.641Z,1541196246.641 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T22:04:10.075Z,1541196250.075 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T22:04:28.242Z,1541196268.242 [CommandLine](IMPORTANT): got command burn on
2018-11-02T22:04:28.243Z,1541196268.243 [CommandLine](IMPORTANT): Activating dropweight wire
2018-11-02T22:04:40.566Z,1541196280.566 [NAL9602](INFO): Powering down
2018-11-02T22:05:06.938Z,1541196306.938 [CommandLine](IMPORTANT): got command burn off
2018-11-02T22:05:06.939Z,1541196306.939 [CommandLine](IMPORTANT): Deactivating dropweight wire
2018-11-02T22:05:58.204Z,1541196358.204 [CommandLine](IMPORTANT): got command burn 30.000000
2018-11-02T22:06:28.225Z,1541196388.225 [CommandLine](IMPORTANT): Deactivating dropweight wire
2018-11-02T22:09:07.294Z,1541196547.294 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T22:09:07.294Z,1541196547.294 [Default:CheckIn:C.Wait] Stopped
2018-11-02T22:09:07.295Z,1541196547.295 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T22:09:07.295Z,1541196547.295 [Default:CheckIn:D] Running Loop=1
2018-11-02T22:09:07.690Z,1541196547.690 [Default:CheckIn:D] Stopped
2018-11-02T22:09:07.690Z,1541196547.690 [Default:CheckIn:E] Running Loop=1
2018-11-02T22:09:08.101Z,1541196548.101 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 211.927311 min 
2018-11-02T22:09:08.101Z,1541196548.101 [Default:CheckIn:E] Stopped
2018-11-02T22:09:08.101Z,1541196548.101 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T22:09:08.101Z,1541196548.101 [Default:CheckIn] Stopped
2018-11-02T22:09:08.102Z,1541196548.102 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T22:09:08.102Z,1541196548.102 [Default:CheckIn](INFO): Running loop #22
2018-11-02T22:09:08.102Z,1541196548.102 [Default:CheckIn] Running Loop=22
2018-11-02T22:09:08.102Z,1541196548.102 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T22:09:08.102Z,1541196548.102 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T22:09:11.441Z,1541196551.441 [NAL9602](INFO): Powering up
2018-11-02T22:09:22.582Z,1541196562.582 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:09:54.586Z,1541196594.586 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T22:09:54.665Z,1541196594.665 [NAL9602](FAULT): received: 
+CSQ:0

OK413, 2, 0, 0, 0

OK
2018-11-02T22:09:54.665Z,1541196594.665 [NAL9602] Data Fault, FailCount= 5
2018-11-02T22:09:54.665Z,1541196594.665 [NAL9602](ERROR): Data Fault
2018-11-02T22:09:54.742Z,1541196594.742 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T22:09:54.743Z,1541196594.743 [CBIT](CRITICAL): Data Fault in component: NAL9602
2018-11-02T22:09:54.982Z,1541196594.982 [NAL9602](INFO): Powering down
2018-11-02T22:09:55.061Z,1541196595.061 [CBIT](INFO): Critical error at 20181102T220954
2018-11-02T22:11:55.085Z,1541196715.085 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T22:11:55.085Z,1541196715.085 [NAL9602] No Fault, FailCount= 5
2018-11-02T22:11:55.398Z,1541196715.398 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:12:06.598Z,1541196726.598 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:12:07.398Z,1541196727.398 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T22:12:07.398Z,1541196727.398 [NAL9602] Data Fault, FailCount= 1
2018-11-02T22:12:07.398Z,1541196727.398 [NAL9602](ERROR): Data Fault
2018-11-02T22:12:07.470Z,1541196727.470 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T22:12:07.798Z,1541196727.798 [NAL9602](INFO): Powering down
2018-11-02T22:12:11.480Z,1541196731.480 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T22:12:11.480Z,1541196731.480 [NAL9602] No Fault, FailCount= 1
2018-11-02T22:12:37.894Z,1541196757.894 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:12:48.694Z,1541196768.694 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:14:08.104Z,1541196848.104 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T22:09:08.1Z
2018-11-02T22:14:08.104Z,1541196848.104 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T22:14:08.104Z,1541196848.104 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T22:14:11.737Z,1541196851.737 [DataOverHttps](INFO): Sending 69 bytes from file Logs/20181102T183334/Courier0067.lzma
2018-11-02T22:14:12.535Z,1541196852.535 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0067.lzma.bak
2018-11-02T22:14:12.535Z,1541196852.535 [DataOverHttps](INFO): SBD MOMSN=8784300
2018-11-02T22:14:21.428Z,1541196861.428 [DataOverHttps](INFO): Sending 340 bytes from file Logs/20181102T183334/Express0068.lzma
2018-11-02T22:14:22.219Z,1541196862.219 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0068.lzma.bak
2018-11-02T22:14:22.219Z,1541196862.219 [DataOverHttps](INFO): SBD MOMSN=8784303
2018-11-02T22:14:22.707Z,1541196862.707 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T22:14:22.707Z,1541196862.707 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T22:14:22.707Z,1541196862.707 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T22:14:26.152Z,1541196866.152 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T22:14:56.638Z,1541196896.638 [NAL9602](INFO): Powering down
2018-11-02T22:19:23.335Z,1541197163.335 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T22:19:23.335Z,1541197163.335 [Default:CheckIn:C.Wait] Stopped
2018-11-02T22:19:23.335Z,1541197163.335 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T22:19:23.335Z,1541197163.335 [Default:CheckIn:D] Running Loop=1
2018-11-02T22:19:23.731Z,1541197163.731 [Default:CheckIn:D] Stopped
2018-11-02T22:19:23.731Z,1541197163.731 [Default:CheckIn:E] Running Loop=1
2018-11-02T22:19:24.134Z,1541197164.134 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 222.194661 min 
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn:E] Stopped
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn] Stopped
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn](INFO): Running loop #23
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn] Running Loop=23
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T22:19:24.135Z,1541197164.135 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T22:19:27.608Z,1541197167.608 [NAL9602](INFO): Powering up
2018-11-02T22:19:38.498Z,1541197178.498 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:20:10.498Z,1541197210.498 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-11-02T22:20:10.573Z,1541197210.573 [NAL9602](FAULT): received: 
+CSQ:0

OK413, 2, 0, 0, 0

OK
2018-11-02T22:20:10.573Z,1541197210.573 [NAL9602] Data Fault, FailCount= 2
2018-11-02T22:20:10.573Z,1541197210.573 [NAL9602](ERROR): Data Fault
2018-11-02T22:20:10.657Z,1541197210.657 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T22:20:10.898Z,1541197210.898 [NAL9602](INFO): Powering down
2018-11-02T22:20:11.754Z,1541197211.754 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T22:20:11.754Z,1541197211.754 [NAL9602] No Fault, FailCount= 2
2018-11-02T22:20:40.962Z,1541197240.962 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:20:52.162Z,1541197252.162 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:23:28.005Z,1541197408.005 [NAL9602](INFO): SBD MO Status=0, MOMSN=10413, MT Status=0, MTMSN=0
2018-11-02T22:23:28.005Z,1541197408.005 [NAL9602](INFO): No messages in MT queue
2018-11-02T22:23:28.514Z,1541197408.514 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T22:23:28.515Z,1541197408.515 [NAL9602] Data Fault, FailCount= 1
2018-11-02T22:23:28.515Z,1541197408.515 [NAL9602](ERROR): Data Fault
2018-11-02T22:23:28.584Z,1541197408.584 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T22:23:28.914Z,1541197408.914 [NAL9602](INFO): Powering down
2018-11-02T22:23:29.776Z,1541197409.776 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T22:23:29.776Z,1541197409.776 [NAL9602] No Fault, FailCount= 1
2018-11-02T22:23:59.310Z,1541197439.310 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:24:10.510Z,1541197450.510 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:24:24.162Z,1541197464.162 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T22:19:24.1Z
2018-11-02T22:24:24.162Z,1541197464.162 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T22:24:24.162Z,1541197464.162 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T22:24:28.276Z,1541197468.276 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0070.lzma
2018-11-02T22:24:29.075Z,1541197469.075 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0070.lzma.bak
2018-11-02T22:24:29.075Z,1541197469.075 [DataOverHttps](INFO): SBD MOMSN=8784380
2018-11-02T22:24:37.958Z,1541197477.958 [DataOverHttps](INFO): Sending 255 bytes from file Logs/20181102T183334/Express0071.lzma
2018-11-02T22:24:38.739Z,1541197478.739 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0071.lzma.bak
2018-11-02T22:24:38.739Z,1541197478.739 [DataOverHttps](INFO): SBD MOMSN=8784382
2018-11-02T22:24:39.224Z,1541197479.224 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T22:24:39.224Z,1541197479.224 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T22:24:39.224Z,1541197479.224 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T22:24:58.354Z,1541197498.354 [NAL9602](INFO): Powering down
2018-11-02T22:29:39.972Z,1541197779.972 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T22:29:39.972Z,1541197779.972 [Default:CheckIn:C.Wait] Stopped
2018-11-02T22:29:39.973Z,1541197779.973 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T22:29:39.973Z,1541197779.973 [Default:CheckIn:D] Running Loop=1
2018-11-02T22:29:40.380Z,1541197780.380 [Default:CheckIn:D] Stopped
2018-11-02T22:29:40.380Z,1541197780.380 [Default:CheckIn:E] Running Loop=1
2018-11-02T22:29:40.785Z,1541197780.785 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 232.472135 min 
2018-11-02T22:29:40.785Z,1541197780.785 [Default:CheckIn:E] Stopped
2018-11-02T22:29:40.785Z,1541197780.785 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T22:29:40.785Z,1541197780.785 [Default:CheckIn] Stopped
2018-11-02T22:29:40.785Z,1541197780.785 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T22:29:40.786Z,1541197780.786 [Default:CheckIn](INFO): Running loop #24
2018-11-02T22:29:40.786Z,1541197780.786 [Default:CheckIn] Running Loop=24
2018-11-02T22:29:40.786Z,1541197780.786 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T22:29:40.786Z,1541197780.786 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T22:29:44.050Z,1541197784.050 [NAL9602](INFO): Powering up
2018-11-02T22:29:55.222Z,1541197795.222 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:30:49.415Z,1541197849.415 [NAL9602](INFO): SBD MO Status=2, MOMSN=10414, MT Status=2, MTMSN=0
2018-11-02T22:30:49.415Z,1541197849.415 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T22:32:06.275Z,1541197926.275 [NAL9602](INFO): SBD MO Status=2, MOMSN=10414, MT Status=2, MTMSN=0
2018-11-02T22:32:06.275Z,1541197926.275 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T22:32:24.275Z,1541197944.275 [NAL9602](INFO): SBD MO Status=2, MOMSN=10414, MT Status=2, MTMSN=0
2018-11-02T22:32:24.275Z,1541197944.275 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T22:32:44.196Z,1541197964.196 [NAL9602](INFO): SBD MO Status=0, MOMSN=10414, MT Status=0, MTMSN=0
2018-11-02T22:32:44.196Z,1541197964.196 [NAL9602](INFO): No messages in MT queue
2018-11-02T22:34:13.182Z,1541198053.182 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T22:34:13.182Z,1541198053.182 [NAL9602] Data Fault, FailCount= 1
2018-11-02T22:34:13.182Z,1541198053.182 [NAL9602](ERROR): Data Fault
2018-11-02T22:34:13.279Z,1541198053.279 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T22:34:13.586Z,1541198053.586 [NAL9602](INFO): Powering down
2018-11-02T22:34:14.438Z,1541198054.438 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T22:34:14.438Z,1541198054.438 [NAL9602] No Fault, FailCount= 1
2018-11-02T22:34:40.820Z,1541198080.820 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T22:29:40.8Z
2018-11-02T22:34:40.820Z,1541198080.820 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T22:34:40.820Z,1541198080.820 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T22:34:44.376Z,1541198084.376 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:34:44.446Z,1541198084.446 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0073.lzma
2018-11-02T22:34:45.247Z,1541198085.247 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0073.lzma.bak
2018-11-02T22:34:45.247Z,1541198085.247 [DataOverHttps](INFO): SBD MOMSN=8784453
2018-11-02T22:34:54.127Z,1541198094.127 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20181102T183334/Express0074.lzma
2018-11-02T22:34:54.927Z,1541198094.927 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0074.lzma.bak
2018-11-02T22:34:54.927Z,1541198094.927 [DataOverHttps](INFO): SBD MOMSN=8784455
2018-11-02T22:34:55.363Z,1541198095.363 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:34:55.396Z,1541198095.396 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T22:34:55.396Z,1541198095.396 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T22:34:55.396Z,1541198095.396 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T22:35:28.910Z,1541198128.910 [NAL9602](INFO): Powering down
2018-11-02T22:39:55.812Z,1541198395.812 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T22:39:55.813Z,1541198395.813 [Default:CheckIn:C.Wait] Stopped
2018-11-02T22:39:55.813Z,1541198395.813 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T22:39:55.813Z,1541198395.813 [Default:CheckIn:D] Running Loop=1
2018-11-02T22:39:56.223Z,1541198396.223 [Default:CheckIn:D] Stopped
2018-11-02T22:39:56.223Z,1541198396.223 [Default:CheckIn:E] Running Loop=1
2018-11-02T22:39:56.622Z,1541198396.622 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 242.736198 min 
2018-11-02T22:39:56.623Z,1541198396.623 [Default:CheckIn:E] Stopped
2018-11-02T22:39:56.623Z,1541198396.623 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T22:39:56.623Z,1541198396.623 [Default:CheckIn] Stopped
2018-11-02T22:39:56.623Z,1541198396.623 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T22:39:56.623Z,1541198396.623 [Default:CheckIn](INFO): Running loop #25
2018-11-02T22:39:56.623Z,1541198396.623 [Default:CheckIn] Running Loop=25
2018-11-02T22:39:56.624Z,1541198396.624 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T22:39:56.624Z,1541198396.624 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T22:39:59.813Z,1541198399.813 [NAL9602](INFO): Powering up
2018-11-02T22:40:10.954Z,1541198410.954 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:40:24.955Z,1541198424.955 [NAL9602](INFO): SBD MO Status=0, MOMSN=10415, MT Status=0, MTMSN=0
2018-11-02T22:40:24.956Z,1541198424.956 [NAL9602](INFO): No messages in MT queue
2018-11-02T22:40:24.956Z,1541198424.956 [NAL9602](INFO): Failure count cleared after critical for NAL9602
2018-11-02T22:41:48.737Z,1541198508.737 [NAL9602](INFO): GPS fix at 20181102T224147: (36.802573, -121.787642)
2018-11-02T22:41:48.807Z,1541198508.807 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T22:41:48.807Z,1541198508.807 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T22:41:53.247Z,1541198513.247 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20181102T183334/Courier0076.lzma
2018-11-02T22:41:54.015Z,1541198514.015 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0076.lzma.bak
2018-11-02T22:41:54.015Z,1541198514.015 [DataOverHttps](INFO): SBD MOMSN=8784460
2018-11-02T22:42:02.884Z,1541198522.884 [DataOverHttps](INFO): Sending 133 bytes from file Logs/20181102T183334/Express0077.lzma
2018-11-02T22:42:03.639Z,1541198523.639 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0077.lzma.bak
2018-11-02T22:42:03.639Z,1541198523.639 [DataOverHttps](INFO): SBD MOMSN=8784465
2018-11-02T22:42:04.126Z,1541198524.126 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T22:42:04.126Z,1541198524.126 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T22:42:04.126Z,1541198524.126 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T22:42:23.414Z,1541198543.414 [NAL9602](INFO): Powering down
2018-11-02T22:47:04.540Z,1541198824.540 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T22:47:04.540Z,1541198824.540 [Default:CheckIn:C.Wait] Stopped
2018-11-02T22:47:04.540Z,1541198824.540 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T22:47:04.540Z,1541198824.540 [Default:CheckIn:D] Running Loop=1
2018-11-02T22:47:04.951Z,1541198824.951 [Default:CheckIn:D] Stopped
2018-11-02T22:47:04.951Z,1541198824.951 [Default:CheckIn:E] Running Loop=1
2018-11-02T22:47:05.350Z,1541198825.350 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 249.881657 min 
2018-11-02T22:47:05.350Z,1541198825.350 [Default:CheckIn:E] Stopped
2018-11-02T22:47:05.350Z,1541198825.350 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T22:47:05.350Z,1541198825.350 [Default:CheckIn] Stopped
2018-11-02T22:47:05.350Z,1541198825.350 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T22:47:05.350Z,1541198825.350 [Default:CheckIn](INFO): Running loop #26
2018-11-02T22:47:05.351Z,1541198825.351 [Default:CheckIn] Running Loop=26
2018-11-02T22:47:05.351Z,1541198825.351 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T22:47:05.351Z,1541198825.351 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T22:47:08.546Z,1541198828.546 [NAL9602](INFO): Powering up
2018-11-02T22:47:19.686Z,1541198839.686 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:52:05.699Z,1541199125.699 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-02T22:47:05.4Z
2018-11-02T22:52:05.699Z,1541199125.699 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T22:52:05.700Z,1541199125.700 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T22:52:09.308Z,1541199129.308 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T183334/Courier0079.lzma
2018-11-02T22:52:10.071Z,1541199130.071 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0079.lzma.bak
2018-11-02T22:52:10.071Z,1541199130.071 [DataOverHttps](INFO): SBD MOMSN=8784524
2018-11-02T22:52:18.944Z,1541199138.944 [DataOverHttps](INFO): Sending 122 bytes from file Logs/20181102T183334/Express0080.lzma
2018-11-02T22:52:19.731Z,1541199139.731 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0080.lzma.bak
2018-11-02T22:52:19.731Z,1541199139.731 [DataOverHttps](INFO): SBD MOMSN=8784526
2018-11-02T22:52:20.199Z,1541199140.199 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T22:52:20.199Z,1541199140.199 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T22:52:20.199Z,1541199140.199 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T22:52:23.655Z,1541199143.655 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-02T22:52:54.166Z,1541199174.166 [NAL9602](INFO): Powering down
2018-11-02T22:57:20.918Z,1541199440.918 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T22:57:20.918Z,1541199440.918 [Default:CheckIn:C.Wait] Stopped
2018-11-02T22:57:20.918Z,1541199440.918 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T22:57:20.918Z,1541199440.918 [Default:CheckIn:D] Running Loop=1
2018-11-02T22:57:21.304Z,1541199441.304 [Default:CheckIn:D] Stopped
2018-11-02T22:57:21.304Z,1541199441.304 [Default:CheckIn:E] Running Loop=1
2018-11-02T22:57:21.718Z,1541199441.718 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 260.154215 min 
2018-11-02T22:57:21.718Z,1541199441.718 [Default:CheckIn:E] Stopped
2018-11-02T22:57:21.718Z,1541199441.718 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T22:57:21.718Z,1541199441.718 [Default:CheckIn] Stopped
2018-11-02T22:57:21.718Z,1541199441.718 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T22:57:21.719Z,1541199441.719 [Default:CheckIn](INFO): Running loop #27
2018-11-02T22:57:21.719Z,1541199441.719 [Default:CheckIn] Running Loop=27
2018-11-02T22:57:21.719Z,1541199441.719 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T22:57:21.719Z,1541199441.719 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T22:57:25.074Z,1541199445.074 [NAL9602](INFO): Powering up
2018-11-02T22:57:36.250Z,1541199456.250 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:57:37.046Z,1541199457.046 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-11-02T22:57:37.046Z,1541199457.046 [NAL9602] Data Fault, FailCount= 1
2018-11-02T22:57:37.046Z,1541199457.046 [NAL9602](ERROR): Data Fault
2018-11-02T22:57:37.128Z,1541199457.128 [CBIT](ERROR): Data Fault in component: NAL9602
2018-11-02T22:57:37.450Z,1541199457.450 [NAL9602](INFO): Powering down
2018-11-02T22:57:38.305Z,1541199458.305 [CBIT](INFO): Clearing failed state for component NAL9602
2018-11-02T22:57:38.305Z,1541199458.305 [NAL9602] No Fault, FailCount= 1
2018-11-02T22:58:07.453Z,1541199487.453 [NAL9602](INFO): Powering up NAL9602
2018-11-02T22:58:18.650Z,1541199498.650 [NAL9602](INFO): NAL9602 initialized
2018-11-02T22:58:53.451Z,1541199533.451 [NAL9602](INFO): SBD MO Status=2, MOMSN=10416, MT Status=2, MTMSN=0
2018-11-02T22:58:53.452Z,1541199533.452 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T22:59:29.519Z,1541199569.519 [NAL9602](INFO): SBD MO Status=0, MOMSN=10416, MT Status=0, MTMSN=0
2018-11-02T22:59:29.520Z,1541199569.520 [NAL9602](INFO): No messages in MT queue
2018-11-02T23:01:40.894Z,1541199700.894 [NAL9602](INFO): GPS fix at 20181102T230139: (36.802692, -121.788168)
2018-11-02T23:01:40.959Z,1541199700.959 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T23:01:40.959Z,1541199700.959 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T23:01:45.344Z,1541199705.344 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20181102T183334/Courier0082.lzma
2018-11-02T23:01:46.131Z,1541199706.131 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0082.lzma.bak
2018-11-02T23:01:46.131Z,1541199706.131 [DataOverHttps](INFO): SBD MOMSN=8784596
2018-11-02T23:01:55.053Z,1541199715.053 [DataOverHttps](INFO): Sending 227 bytes from file Logs/20181102T183334/Express0083.lzma
2018-11-02T23:01:55.851Z,1541199715.851 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0083.lzma.bak
2018-11-02T23:01:55.851Z,1541199715.851 [DataOverHttps](INFO): SBD MOMSN=8784599
2018-11-02T23:01:56.337Z,1541199716.337 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T23:01:56.337Z,1541199716.337 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T23:01:56.337Z,1541199716.337 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T23:02:15.622Z,1541199735.622 [NAL9602](INFO): Powering down
2018-11-02T23:06:57.089Z,1541200017.089 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T23:06:57.089Z,1541200017.089 [Default:CheckIn:C.Wait] Stopped
2018-11-02T23:06:57.089Z,1541200017.089 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T23:06:57.089Z,1541200017.089 [Default:CheckIn:D] Running Loop=1
2018-11-02T23:06:57.497Z,1541200017.497 [Default:CheckIn:D] Stopped
2018-11-02T23:06:57.497Z,1541200017.497 [Default:CheckIn:E] Running Loop=1
2018-11-02T23:06:57.886Z,1541200017.886 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 269.757422 min 
2018-11-02T23:06:57.887Z,1541200017.887 [Default:CheckIn:E] Stopped
2018-11-02T23:06:57.887Z,1541200017.887 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T23:06:57.887Z,1541200017.887 [Default:CheckIn] Stopped
2018-11-02T23:06:57.887Z,1541200017.887 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T23:06:57.887Z,1541200017.887 [Default:CheckIn](INFO): Running loop #28
2018-11-02T23:06:57.887Z,1541200017.887 [Default:CheckIn] Running Loop=28
2018-11-02T23:06:57.888Z,1541200017.888 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T23:06:57.888Z,1541200017.888 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T23:07:01.078Z,1541200021.078 [NAL9602](INFO): Powering up
2018-11-02T23:07:12.218Z,1541200032.218 [NAL9602](INFO): NAL9602 initialized
2018-11-02T23:08:03.815Z,1541200083.815 [NAL9602](INFO): SBD MO Status=2, MOMSN=10417, MT Status=2, MTMSN=0
2018-11-02T23:08:03.815Z,1541200083.815 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T23:08:31.015Z,1541200111.015 [NAL9602](INFO): SBD MO Status=2, MOMSN=10417, MT Status=2, MTMSN=0
2018-11-02T23:08:31.016Z,1541200111.016 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-11-02T23:08:40.615Z,1541200120.615 [NAL9602](INFO): SBD MO Status=0, MOMSN=10417, MT Status=0, MTMSN=0
2018-11-02T23:08:40.616Z,1541200120.616 [NAL9602](INFO): No messages in MT queue
2018-11-02T23:08:41.818Z,1541200121.818 [NAL9602](INFO): GPS fix at 20181102T230840: (36.802690, -121.787885)
2018-11-02T23:08:41.882Z,1541200121.882 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T23:08:41.882Z,1541200121.882 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-02T23:08:46.431Z,1541200126.431 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181102T183334/Courier0085.lzma
2018-11-02T23:08:47.223Z,1541200127.223 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Courier0085.lzma.bak
2018-11-02T23:08:47.223Z,1541200127.223 [DataOverHttps](INFO): SBD MOMSN=8784665
2018-11-02T23:08:56.055Z,1541200136.055 [DataOverHttps](INFO): Sending 133 bytes from file Logs/20181102T183334/Express0086.lzma
2018-11-02T23:08:56.847Z,1541200136.847 [DataOverHttps](INFO): Moved sent file to Logs/20181102T183334/Express0086.lzma.bak
2018-11-02T23:08:56.847Z,1541200136.847 [DataOverHttps](INFO): SBD MOMSN=8784668
2018-11-02T23:08:57.339Z,1541200137.339 [Default:CheckIn:Read_Iridium] Stopped
2018-11-02T23:08:57.339Z,1541200137.339 [Default:CheckIn:C.Wait] Running Loop=1
2018-11-02T23:08:57.339Z,1541200137.339 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-11-02T23:09:16.622Z,1541200156.622 [NAL9602](INFO): Powering down
2018-11-02T23:13:57.734Z,1541200437.734 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-11-02T23:13:57.734Z,1541200437.734 [Default:CheckIn:C.Wait] Stopped
2018-11-02T23:13:57.734Z,1541200437.734 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-11-02T23:13:57.734Z,1541200437.734 [Default:CheckIn:D] Running Loop=1
2018-11-02T23:13:58.138Z,1541200438.138 [Default:CheckIn:D] Stopped
2018-11-02T23:13:58.138Z,1541200438.138 [Default:CheckIn:E] Running Loop=1
2018-11-02T23:13:58.555Z,1541200438.555 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 276.768132 min 
2018-11-02T23:13:58.555Z,1541200438.555 [Default:CheckIn:E] Stopped
2018-11-02T23:13:58.555Z,1541200438.555 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-11-02T23:13:58.555Z,1541200438.555 [Default:CheckIn] Stopped
2018-11-02T23:13:58.555Z,1541200438.555 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T23:13:58.556Z,1541200438.556 [Default:CheckIn](INFO): Running loop #29
2018-11-02T23:13:58.556Z,1541200438.556 [Default:CheckIn] Running Loop=29
2018-11-02T23:13:58.556Z,1541200438.556 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-02T23:13:58.556Z,1541200438.556 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-02T23:14:01.830Z,1541200441.830 [NAL9602](INFO): Powering up
2018-11-02T23:14:02.866Z,1541200442.866 [CommandLine](IMPORTANT): got command quit
2018-11-02T23:14:03.875Z,1541200443.875 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:03.875Z,1541200443.875 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:03.952Z,1541200443.952 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2018-11-02T23:14:03.953Z,1541200443.953 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:03.953Z,1541200443.953 [CommandLine](INFO): Join timeout helper Thread ID is 1106
2018-11-02T23:14:03.954Z,1541200443.954 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-11-02T23:14:03.954Z,1541200443.954 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:03.954Z,1541200443.954 [NavChartDb](INFO): Join timeout helper Thread ID is 1107
2018-11-02T23:14:04.293Z,1541200444.293 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:04.293Z,1541200444.293 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.300Z,1541200444.300 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-11-02T23:14:04.301Z,1541200444.301 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.301Z,1541200444.301 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1108
2018-11-02T23:14:04.569Z,1541200444.569 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:04.569Z,1541200444.569 [WetLabsBB2FL](INFO): Powering down
2018-11-02T23:14:04.570Z,1541200444.570 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.585Z,1541200444.585 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-11-02T23:14:04.585Z,1541200444.585 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.585Z,1541200444.585 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1109
2018-11-02T23:14:04.741Z,1541200444.741 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:04.823Z,1541200444.823 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-11-02T23:14:04.824Z,1541200444.824 [CTD_Seabird](INFO): Powering down
2018-11-02T23:14:04.826Z,1541200444.826 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.833Z,1541200444.833 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-11-02T23:14:04.833Z,1541200444.833 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.833Z,1541200444.833 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1111
2018-11-02T23:14:04.917Z,1541200444.917 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:04.917Z,1541200444.917 [CTD_NeilBrown](INFO): Powering down
2018-11-02T23:14:04.918Z,1541200444.918 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.933Z,1541200444.933 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2018-11-02T23:14:04.934Z,1541200444.934 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:04.934Z,1541200444.934 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 1112
2018-11-02T23:14:05.209Z,1541200445.209 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:05.209Z,1541200445.209 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-11-02T23:14:05.300Z,1541200445.300 [Rowe_600LCM](INFO): Powering down
2018-11-02T23:14:05.301Z,1541200445.301 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.306Z,1541200445.306 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-11-02T23:14:05.306Z,1541200445.306 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.306Z,1541200445.306 [Radio_Surface](INFO): Join timeout helper Thread ID is 1114
2018-11-02T23:14:05.633Z,1541200445.633 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:05.633Z,1541200445.633 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.645Z,1541200445.645 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-11-02T23:14:05.646Z,1541200445.645 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.646Z,1541200445.646 [logger](INFO): Join timeout helper Thread ID is 1115
2018-11-02T23:14:05.685Z,1541200445.685 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:05.685Z,1541200445.685 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.705Z,1541200445.705 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-11-02T23:14:05.705Z,1541200445.705 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.705Z,1541200445.705 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-11-02T23:14:05.706Z,1541200445.706 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.706Z,1541200445.706 [controlThread](INFO): Join timeout helper Thread ID is 1116
2018-11-02T23:14:05.761Z,1541200445.761 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-02T23:14:05.761Z,1541200445.761 [controlThread](DEBUG): Uninitializing ControlThread
2018-11-02T23:14:05.762Z,1541200445.762 [NAL9602](INFO): Powering down
2018-11-02T23:14:05.763Z,1541200445.763 [PNI_TCM](INFO): Powering down
2018-11-02T23:14:05.849Z,1541200445.849 [Aanderaa_O2](INFO): Powering down
2018-11-02T23:14:05.850Z,1541200445.850 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-11-02T23:14:05.851Z,1541200445.851 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-11-02T23:14:05.852Z,1541200445.852 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-11-02T23:14:05.852Z,1541200445.852 [MissionManager](INFO): Uninitializing Mission Default
2018-11-02T23:14:05.852Z,1541200445.852 [Default] Stopped
2018-11-02T23:14:05.853Z,1541200445.853 [Default](DEBUG): Aggregate::uninitialize Default
2018-11-02T23:14:05.853Z,1541200445.853 [Default:B.GoToSurface] Stopped
2018-11-02T23:14:05.853Z,1541200445.853 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-02T23:14:05.853Z,1541200445.853 [Default:CheckIn] Stopped
2018-11-02T23:14:05.853Z,1541200445.853 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-02T23:14:05.853Z,1541200445.853 [Default:CheckIn:Read_GPS] Stopped
2018-11-02T23:14:05.857Z,1541200445.857 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-11-02T23:14:05.857Z,1541200445.857 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-11-02T23:14:05.857Z,1541200445.857 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-11-02T23:14:05.858Z,1541200445.858 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-11-02T23:14:05.858Z,1541200445.858 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-11-02T23:14:05.858Z,1541200445.858 [BuoyancyServo](INFO): Powering down
2018-11-02T23:14:05.873Z,1541200445.873 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-11-02T23:14:05.873Z,1541200445.873 [ElevatorServo](INFO): Powering down
2018-11-02T23:14:05.874Z,1541200445.874 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-11-02T23:14:05.874Z,1541200445.874 [MassServo](INFO): Powering down
2018-11-02T23:14:05.875Z,1541200445.875 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-11-02T23:14:05.875Z,1541200445.875 [RudderServo](INFO): Powering down
2018-11-02T23:14:05.875Z,1541200445.875 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-11-02T23:14:05.876Z,1541200445.876 [ThrusterServo](INFO): Powering down
2018-11-02T23:14:05.877Z,1541200445.877 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-11-02T23:14:05.877Z,1541200445.877 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-11-02T23:14:05.877Z,1541200445.877 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-11-02T23:14:05.878Z,1541200445.878 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.936Z,1541200445.936 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.942Z,1541200445.942 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.981Z,1541200445.981 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.984Z,1541200445.984 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:05.987Z,1541200445.987 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:06.014Z,1541200446.014 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-02T23:14:06.084Z,1541200446.084 [logger ThreadHandler](INFO): Thread cancelled.