2019-04-03T20:57:37.609Z,1554325057.609 [Supervisor](DEBUG): Initializing supervisor.
2019-04-03T20:57:37.612Z,1554325057.612 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-03T20:57:37.613Z,1554325057.613 [SyncHandler](INFO): Protected caller Thread ID is 1118
2019-04-03T20:57:37.613Z,1554325057.613 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-03T20:57:37.614Z,1554325057.614 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-03T20:57:37.615Z,1554325057.615 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1119
2019-04-03T20:57:37.618Z,1554325057.618 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-03T20:57:37.631Z,1554325057.631 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-03T20:57:37.632Z,1554325057.632 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-03T20:57:37.632Z,1554325057.632 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1120
2019-04-03T20:57:37.633Z,1554325057.633 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-03T20:57:37.634Z,1554325057.634 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-03T20:57:37.634Z,1554325057.634 [logger ThreadHandler](INFO): Protected caller Thread ID is 1121
2019-04-03T20:57:37.636Z,1554325057.636 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-03T20:57:37.637Z,1554325057.637 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-03T20:57:37.638Z,1554325057.638 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-03T20:57:38.094Z,1554325058.094 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-03T20:57:38.094Z,1554325058.094 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-03T20:57:38.194Z,1554325058.194 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-03T20:57:38.195Z,1554325058.195 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-03T20:57:38.550Z,1554325058.550 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-03T20:57:38.550Z,1554325058.550 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-03T20:57:38.699Z,1554325058.699 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-03T20:57:38.700Z,1554325058.700 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-03T20:57:38.911Z,1554325058.911 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-03T20:57:38.911Z,1554325058.911 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-03T20:57:39.495Z,1554325059.495 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-03T20:57:39.495Z,1554325059.495 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-03T20:57:39.720Z,1554325059.720 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-03T20:57:39.721Z,1554325059.721 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-03T20:57:39.874Z,1554325059.874 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-03T20:57:39.875Z,1554325059.875 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-03T20:57:40.091Z,1554325060.091 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-03T20:57:40.092Z,1554325060.092 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-03T20:57:40.190Z,1554325060.190 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-03T20:57:40.191Z,1554325060.191 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-03T20:57:40.542Z,1554325060.542 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-03T20:57:40.543Z,1554325060.543 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-03T20:57:40.624Z,1554325060.624 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-03T20:57:40.731Z,1554325060.731 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-03T20:57:40.731Z,1554325060.731 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-03T20:57:41.271Z,1554325061.271 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-03T20:57:41.271Z,1554325061.271 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-03T20:57:41.694Z,1554325061.694 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-03T20:57:41.696Z,1554325061.696 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-03T20:57:41.697Z,1554325061.697 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-03T20:57:41.921Z,1554325061.921 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-03T20:57:42.026Z,1554325062.026 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-03T20:57:42.129Z,1554325062.129 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-03T20:57:42.367Z,1554325062.367 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-03T20:57:42.368Z,1554325062.368 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-03T20:57:42.454Z,1554325062.454 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-03T20:57:42.550Z,1554325062.550 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-03T20:57:42.651Z,1554325062.651 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-03T20:57:42.735Z,1554325062.735 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-03T20:57:42.851Z,1554325062.851 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-03T20:57:43.046Z,1554325063.046 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-03T20:57:43.186Z,1554325063.186 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-03T20:57:43.194Z,1554325063.194 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-03T20:57:43.573Z,1554325063.573 [AHRS_M2] Loaded
2019-04-03T20:57:43.573Z,1554325063.573 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-03T20:57:43.647Z,1554325063.647 [DataOverHttps] Loaded
2019-04-03T20:57:43.648Z,1554325063.648 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-03T20:57:43.649Z,1554325063.649 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2019-04-03T20:57:43.649Z,1554325063.649 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1200
2019-04-03T20:57:43.663Z,1554325063.663 [Depth_Keller] Loaded
2019-04-03T20:57:43.664Z,1554325063.664 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-03T20:57:43.668Z,1554325063.668 [DropWeight] Loaded
2019-04-03T20:57:43.669Z,1554325063.669 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-03T20:57:43.723Z,1554325063.723 [DUSBL_Hydroid] Loaded
2019-04-03T20:57:43.723Z,1554325063.723 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-03T20:57:43.764Z,1554325063.764 [Micromodem] Loaded
2019-04-03T20:57:43.765Z,1554325063.765 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-03T20:57:43.865Z,1554325063.865 [NAL9602] Loaded
2019-04-03T20:57:43.865Z,1554325063.865 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-03T20:57:43.881Z,1554325063.881 [Onboard] Loaded
2019-04-03T20:57:43.882Z,1554325063.882 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-03T20:57:43.888Z,1554325063.888 [PowerOnly] Loaded
2019-04-03T20:57:43.888Z,1554325063.888 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-03T20:57:43.895Z,1554325063.895 [Radio_Surface] Loaded
2019-04-03T20:57:43.895Z,1554325063.895 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-03T20:57:43.896Z,1554325063.896 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2019-04-03T20:57:43.896Z,1554325063.896 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1201
2019-04-03T20:57:43.942Z,1554325063.942 [RDI_Pathfinder] Loaded
2019-04-03T20:57:43.943Z,1554325063.943 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-03T20:57:46.126Z,1554325066.126 [BPC1] Loaded
2019-04-03T20:57:46.127Z,1554325066.127 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-03T20:57:46.127Z,1554325066.127 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-03T20:57:46.128Z,1554325066.128 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-03T20:57:46.140Z,1554325066.140 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-03T20:57:46.141Z,1554325066.141 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-03T20:57:46.249Z,1554325066.249 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-03T20:57:46.250Z,1554325066.250 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-03T20:57:46.271Z,1554325066.271 [NavChart] Loaded
2019-04-03T20:57:46.271Z,1554325066.271 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-03T20:57:46.276Z,1554325066.276 [UniversalFixResidualReporter] Loaded
2019-04-03T20:57:46.276Z,1554325066.276 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-03T20:57:46.276Z,1554325066.276 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-03T20:57:46.277Z,1554325066.277 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-03T20:57:46.380Z,1554325066.380 [BuoyancyServo] Loaded
2019-04-03T20:57:46.380Z,1554325066.380 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-03T20:57:46.396Z,1554325066.396 [ElevatorServo] Loaded
2019-04-03T20:57:46.396Z,1554325066.396 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-03T20:57:46.412Z,1554325066.412 [MassServo] Loaded
2019-04-03T20:57:46.412Z,1554325066.412 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-03T20:57:46.428Z,1554325066.428 [RudderServo] Loaded
2019-04-03T20:57:46.428Z,1554325066.428 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-03T20:57:46.444Z,1554325066.444 [ThrusterServo] Loaded
2019-04-03T20:57:46.444Z,1554325066.444 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-03T20:57:46.445Z,1554325066.445 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-03T20:57:46.445Z,1554325066.445 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-03T20:57:46.696Z,1554325066.696 [CTD_NeilBrown] Loaded
2019-04-03T20:57:46.696Z,1554325066.696 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-03T20:57:46.697Z,1554325066.697 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D04E0
2019-04-03T20:57:46.698Z,1554325066.698 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1202
2019-04-03T20:57:46.744Z,1554325066.744 [WetLabsSeaOWL_UV_A] Loaded
2019-04-03T20:57:46.744Z,1554325066.744 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-03T20:57:46.745Z,1554325066.745 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409004E0
2019-04-03T20:57:46.746Z,1554325066.746 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1203
2019-04-03T20:57:46.746Z,1554325066.746 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-03T20:57:46.747Z,1554325066.747 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-03T20:57:47.021Z,1554325067.021 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-03T20:57:47.022Z,1554325067.022 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-03T20:57:47.063Z,1554325067.063 [DepthRateCalculator] Loaded
2019-04-03T20:57:47.063Z,1554325067.063 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-03T20:57:47.069Z,1554325067.069 [PitchRateCalculator] Loaded
2019-04-03T20:57:47.069Z,1554325067.069 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-03T20:57:47.082Z,1554325067.082 [SpeedCalculator] Loaded
2019-04-03T20:57:47.082Z,1554325067.082 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-03T20:57:47.104Z,1554325067.104 [TempGradientCalculator] Loaded
2019-04-03T20:57:47.104Z,1554325067.104 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-03T20:57:47.110Z,1554325067.110 [YawRateCalculator] Loaded
2019-04-03T20:57:47.110Z,1554325067.110 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-03T20:57:47.152Z,1554325067.152 [ElevatorOffsetCalculator] Loaded
2019-04-03T20:57:47.153Z,1554325067.153 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-03T20:57:47.153Z,1554325067.153 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-03T20:57:47.154Z,1554325067.154 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-03T20:57:47.289Z,1554325067.289 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-03T20:57:47.313Z,1554325067.313 [SBIT] Loaded
2019-04-03T20:57:47.313Z,1554325067.313 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-03T20:57:47.314Z,1554325067.314 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-03T20:57:47.327Z,1554325067.327 [IBIT] Loaded
2019-04-03T20:57:47.327Z,1554325067.327 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-03T20:57:47.331Z,1554325067.331 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-03T20:57:47.475Z,1554325067.475 [CBIT] Loaded
2019-04-03T20:57:47.475Z,1554325067.475 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-03T20:57:47.476Z,1554325067.476 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-03T20:57:47.476Z,1554325067.476 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-03T20:57:47.546Z,1554325067.546 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-03T20:57:47.547Z,1554325067.547 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-03T20:57:47.647Z,1554325067.647 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-03T20:57:47.647Z,1554325067.647 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-03T20:57:47.714Z,1554325067.714 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-03T20:57:47.803Z,1554325067.803 [VerticalControl] Loaded
2019-04-03T20:57:47.803Z,1554325067.803 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-03T20:57:47.804Z,1554325067.804 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-03T20:57:47.864Z,1554325067.864 [HorizontalControl] Loaded
2019-04-03T20:57:47.864Z,1554325067.864 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-03T20:57:47.865Z,1554325067.865 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-03T20:57:47.867Z,1554325067.867 [SpeedControl] Loaded
2019-04-03T20:57:47.867Z,1554325067.867 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-03T20:57:47.868Z,1554325067.868 [LoopControl](DEBUG): Construct LoopControl.
2019-04-03T20:57:47.868Z,1554325067.868 [LoopControl] Loaded
2019-04-03T20:57:47.868Z,1554325067.868 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-03T20:57:47.869Z,1554325067.869 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-03T20:57:47.870Z,1554325067.870 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-03T20:57:47.897Z,1554325067.897 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-03T20:57:47.901Z,1554325067.901 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-03T20:57:47.902Z,1554325067.902 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-03T20:57:47.910Z,1554325067.910 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-03T20:57:47.911Z,1554325067.911 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD04E0
2019-04-03T20:57:47.911Z,1554325067.911 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1204
2019-04-03T20:57:47.916Z,1554325067.916 [Supervisor](INFO): Main Thread ID is 801
2019-04-03T20:57:47.916Z,1554325067.916 [Supervisor](DEBUG): Running supervisor.
2019-04-03T20:57:47.917Z,1554325067.917 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1205
2019-04-03T20:57:47.919Z,1554325067.919 [controlThread ThreadHandler](INFO): Handler Thread ID is 1206
2019-04-03T20:57:47.920Z,1554325067.920 [controlThread](DEBUG): Initializing ControlThread
2019-04-03T20:57:47.928Z,1554325067.928 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-03T20:57:47.928Z,1554325067.928 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-03T20:57:47.930Z,1554325067.930 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-03T20:57:47.930Z,1554325067.930 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-03T20:57:47.930Z,1554325067.930 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-03T20:57:47.931Z,1554325067.931 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-03T20:57:47.931Z,1554325067.931 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-03T20:57:47.931Z,1554325067.931 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-03T20:57:47.932Z,1554325067.932 [SBIT](INFO): Initialize SBIT Component.
2019-04-03T20:57:47.933Z,1554325067.932 [SBIT](IMPORTANT): git: 2019-04-03_docking
2019-04-03T20:57:47.933Z,1554325067.933 [SBIT](INFO): git hash: 4133750a826247d6fa9b310476a882604c466498
2019-04-03T20:57:47.933Z,1554325067.933 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-03T20:57:47.933Z,1554325067.933 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-03T20:57:47.934Z,1554325067.934 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-04-03T20:57:47.935Z,1554325067.935 [IBIT](INFO): Initialize IBIT Component.
2019-04-03T20:57:47.936Z,1554325067.936 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-03T20:57:47.937Z,1554325067.937 [logger ThreadHandler](INFO): Handler Thread ID is 1207
2019-04-03T20:57:47.949Z,1554325067.949 [CBIT](DEBUG): Initialized mux pins.
2019-04-03T20:57:47.949Z,1554325067.949 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-03T20:57:47.957Z,1554325067.957 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1208
2019-04-03T20:57:47.958Z,1554325067.958 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-03T20:57:47.969Z,1554325067.969 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1209
2019-04-03T20:57:47.973Z,1554325067.973 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-03T20:57:47.973Z,1554325067.973 [CBIT](DEBUG): Initializing heartbeat.
2019-04-03T20:57:47.989Z,1554325067.989 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1210
2019-04-03T20:57:47.990Z,1554325067.990 [CTD_NeilBrown](INFO): Powering down
2019-04-03T20:57:48.025Z,1554325068.025 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1211
2019-04-03T20:57:48.026Z,1554325068.026 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-03T20:57:48.045Z,1554325068.045 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-03T20:57:48.045Z,1554325068.045 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-03T20:57:48.050Z,1554325068.050 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1212
2019-04-03T20:57:48.053Z,1554325068.053 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-03T20:57:48.053Z,1554325068.053 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-03T20:57:48.053Z,1554325068.053 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-03T20:57:48.053Z,1554325068.053 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-03T20:57:48.053Z,1554325068.053 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-03T20:57:48.054Z,1554325068.054 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-03T20:57:48.054Z,1554325068.054 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-03T20:57:48.054Z,1554325068.054 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-03T20:57:48.054Z,1554325068.054 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-03T20:57:48.054Z,1554325068.054 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-03T20:57:48.055Z,1554325068.055 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-03T20:57:48.055Z,1554325068.055 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-03T20:57:48.055Z,1554325068.055 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-03T20:57:48.055Z,1554325068.055 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-03T20:57:48.055Z,1554325068.055 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-03T20:57:48.055Z,1554325068.055 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-03T20:57:48.081Z,1554325068.081 [CBIT](DEBUG): Backplane powered.
2019-04-03T20:57:48.081Z,1554325068.081 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-03T20:57:48.083Z,1554325068.083 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-03T20:57:48.083Z,1554325068.083 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-03T20:57:48.084Z,1554325068.084 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-03T20:57:48.085Z,1554325068.085 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-03T20:57:48.095Z,1554325068.095 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-03T20:57:48.118Z,1554325068.118 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-04-03T20:57:48.119Z,1554325068.119 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-03T20:57:48.191Z,1554325068.191 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-03T20:57:48.192Z,1554325068.192 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-03T20:57:48.202Z,1554325068.202 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-03T20:57:48.228Z,1554325068.228 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-03T20:57:48.231Z,1554325068.231 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-03T20:57:48.245Z,1554325068.245 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-03T20:57:48.273Z,1554325068.273 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-04-03T20:57:48.278Z,1554325068.278 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-04-03T20:57:48.289Z,1554325068.289 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-03T20:57:48.323Z,1554325068.323 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-03T20:57:48.324Z,1554325068.324 [DUSBL_Hydroid](INFO): Powering up
2019-04-03T20:57:48.337Z,1554325068.337 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-03T20:57:48.373Z,1554325068.373 [Radio_Surface](INFO): Powering up
2019-04-03T20:57:48.413Z,1554325068.413 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-03T20:57:48.439Z,1554325068.439 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-03T20:57:48.445Z,1554325068.445 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-03T20:57:48.446Z,1554325068.446 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-03T20:57:48.457Z,1554325068.457 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-03T20:57:48.458Z,1554325068.458 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-03T20:57:48.465Z,1554325068.465 [MassServo](DEBUG): Initializing MassServo.
2019-04-03T20:57:48.466Z,1554325068.466 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-03T20:57:48.473Z,1554325068.473 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-03T20:57:48.474Z,1554325068.474 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-03T20:57:48.481Z,1554325068.481 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-03T20:57:48.705Z,1554325068.705 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-04-03T20:57:48.706Z,1554325068.706 [DropWeight] Hardware Fault, FailCount= 1
2019-04-03T20:57:48.706Z,1554325068.706 [DropWeight](ERROR): Hardware Fault
2019-04-03T20:57:48.707Z,1554325068.707 [Micromodem](INFO): Powering up
2019-04-03T20:57:48.707Z,1554325068.707 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-03T20:57:48.745Z,1554325068.745 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-03T20:57:48.753Z,1554325068.753 [CommandLine](FAULT): Scheduling is paused
2019-04-03T20:57:48.754Z,1554325068.754 [CBIT](INFO): Critical error at 20190403T205748
2019-04-03T20:57:48.754Z,1554325068.754 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-04-03T20:57:48.756Z,1554325068.756 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-04-03T20:57:48.757Z,1554325068.757 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-04-03T20:57:49.421Z,1554325069.421 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-03T20:57:49.421Z,1554325069.421 [RudderServo](FAULT): Rudder failed to initialize
2019-04-03T20:57:49.421Z,1554325069.421 [RudderServo] Communications Fault, FailCount= 1
2019-04-03T20:57:49.421Z,1554325069.421 [RudderServo](ERROR): Communications Fault
2019-04-03T20:57:49.530Z,1554325069.530 [CBIT](INFO): Critical error at 20190403T205748
2019-04-03T20:57:49.533Z,1554325069.533 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-03T20:57:49.694Z,1554325069.694 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-03T20:57:49.694Z,1554325069.694 [RudderServo](INFO): Powering down
2019-04-03T20:57:50.376Z,1554325070.376 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-03T20:57:50.502Z,1554325070.502 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-03T20:57:50.506Z,1554325070.506 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-03T20:57:50.506Z,1554325070.506 [RudderServo] No Fault, FailCount= 1
2019-04-03T20:57:53.621Z,1554325073.621 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-04-03T20:58:01.718Z,1554325081.718 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-03T20:58:02.903Z,1554325082.903 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-04-03T20:58:06.542Z,1554325086.542 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-03T20:58:12.604Z,1554325092.604 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-04-03T20:58:14.215Z,1554325094.215 [NAL9602](INFO): Powering up NAL9602
2019-04-03T20:58:16.691Z,1554325096.691 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-03T20:58:16.700Z,1554325096.700 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-03T20:58:22.827Z,1554325102.827 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-04-03T20:58:25.243Z,1554325105.243 [NAL9602](INFO): NAL9602 initialized
2019-04-03T20:58:26.065Z,1554325106.065 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:58:27.777Z,1554325107.777 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.014197
CHAN A1 (24V): -0.026372
CHAN A2 (12V): -0.006986
CHAN A3 (5V): -0.002062
CHAN B0 (3.3V): 0.000129
CHAN B1 (3.15aV): 0.000237
CHAN B2 (3.15bV): 0.000354
CHAN B3 (GND): 0.002172
OPEN: 0.005317
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-03T20:58:32.679Z,1554325112.679 [Micromodem](INFO): Nmea out: $CCTMS,2019-04-03T20:58:33Z,0*76

2019-04-03T20:58:40.772Z,1554325120.772 [NAL9602](INFO): SBD MO Status=0, MOMSN=2621, MT Status=0, MTMSN=0
2019-04-03T20:58:40.772Z,1554325120.772 [NAL9602](INFO): No messages in MT queue
2019-04-03T20:58:41.585Z,1554325121.585 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:58:44.821Z,1554325124.821 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:58:47.645Z,1554325127.645 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:58:50.893Z,1554325130.893 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:58:53.705Z,1554325133.705 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:58:56.937Z,1554325136.937 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:58:59.865Z,1554325139.865 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:59:02.673Z,1554325142.673 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:59:03.065Z,1554325143.065 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205856.00,A,3648.14409,N,12147.22555,W,0.253,0.00,030419,,,A*7E
2019-04-03T20:59:03.068Z,1554325143.068 [NAL9602](INFO): GPS fix at 20190403T205856: (36.802402, -121.787092)
2019-04-03T20:59:10.397Z,1554325150.397 [SBIT](IMPORTANT): SBIT PASSED
2019-04-03T20:59:10.474Z,1554325150.474 [CommandLine](IMPORTANT): got command configSet list
2019-04-03T20:59:10.474Z,1554325150.474 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-03T20:59:10.475Z,1554325150.475 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=75 count;

2019-04-03T20:59:10.475Z,1554325150.475 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-04-03T20:59:10.475Z,1554325150.475 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-04-03T20:59:10.475Z,1554325150.475 [CommandLine](IMPORTANT): Express linearApproximation TrackAcousticContact.contact_latitude 0.000500 angular_degree;

2019-04-03T20:59:10.475Z,1554325150.475 [CommandLine](IMPORTANT): Express linearApproximation TrackAcousticContact.contact_longitude 0.000500 angular_degree;

2019-04-03T20:59:10.475Z,1554325150.475 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-04-03T20:59:10.475Z,1554325150.475 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-04-03T20:59:10.783Z,1554325150.783 [MissionManager](IMPORTANT): Started mission Startup
2019-04-03T20:59:10.783Z,1554325150.783 [Startup] Running Loop=1
2019-04-03T20:59:10.784Z,1554325150.784 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-03T20:59:10.784Z,1554325150.784 [Startup:A.GoToSurface] Running Loop=1
2019-04-03T20:59:10.784Z,1554325150.784 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-03T20:59:10.784Z,1554325150.784 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-03T20:59:10.785Z,1554325150.785 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-03T20:59:10.785Z,1554325150.785 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-03T20:59:10.786Z,1554325150.786 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-03T20:59:10.786Z,1554325150.786 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-03T20:59:10.788Z,1554325150.788 [Startup:StartupSatComms] Running Loop=1
2019-04-03T20:59:10.788Z,1554325150.788 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-03T20:59:10.788Z,1554325150.788 [Startup:StartupSatComms:A] Running Loop=1
2019-04-03T20:59:11.212Z,1554325151.212 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-03T20:59:12.369Z,1554325152.369 [NAL9602](DEBUG): Fix Requested
2019-04-03T20:59:12.774Z,1554325152.774 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205905.00,A,3648.14174,N,12147.22386,W,0.117,0.00,030419,,,A*7D
2019-04-03T20:59:12.781Z,1554325152.781 [NAL9602](INFO): GPS fix at 20190403T205905: (36.802362, -121.787064)
2019-04-03T20:59:12.828Z,1554325152.828 [Startup:StartupSatComms:A] Stopped
2019-04-03T20:59:12.828Z,1554325152.828 [Startup:StartupSatComms:B] Running Loop=1
2019-04-03T20:59:13.208Z,1554325153.208 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-03T20:59:30.016Z,1554325170.016 [NAL9602](INFO): SBD MO Status=1, MOMSN=2622, MT Status=0, MTMSN=0
2019-04-03T20:59:30.065Z,1554325170.065 [NAL9602](INFO): Sent 25 bytes from file Logs/20190403T203507/Courier0018.lzma
2019-04-03T20:59:30.065Z,1554325170.065 [NAL9602](INFO): Packets left to send: 0
2019-04-03T20:59:40.584Z,1554325180.584 [NAL9602](INFO): SBD MO Status=1, MOMSN=2623, MT Status=0, MTMSN=0
2019-04-03T20:59:40.633Z,1554325180.633 [NAL9602](INFO): Sent 304 bytes from file Logs/20190403T205737/Courier0000.lzma
2019-04-03T20:59:40.633Z,1554325180.633 [NAL9602](INFO): Packets left to send: 0
2019-04-03T20:59:47.136Z,1554325187.136 [NAL9602](INFO): SBD MO Status=1, MOMSN=2624, MT Status=0, MTMSN=0
2019-04-03T20:59:47.185Z,1554325187.185 [NAL9602](INFO): Sent 204 bytes from file Logs/20190403T203507/Express0020.lzma
2019-04-03T20:59:47.185Z,1554325187.185 [NAL9602](INFO): Packets left to send: 0
2019-04-03T20:59:56.624Z,1554325196.624 [NAL9602](INFO): SBD MO Status=1, MOMSN=2625, MT Status=0, MTMSN=0
2019-04-03T20:59:56.673Z,1554325196.673 [NAL9602](INFO): Sent 332 bytes from file Logs/20190403T205737/Express0001.lzma
2019-04-03T20:59:56.673Z,1554325196.673 [NAL9602](INFO): Packets left to send: 2
2019-04-03T21:00:06.400Z,1554325206.400 [NAL9602](INFO): SBD MO Status=1, MOMSN=2626, MT Status=0, MTMSN=0
2019-04-03T21:00:06.449Z,1554325206.449 [NAL9602](INFO): Sent 332 bytes from file Logs/20190403T205737/Express0001.lzma
2019-04-03T21:00:06.449Z,1554325206.449 [NAL9602](INFO): Packets left to send: 1
2019-04-03T21:00:12.973Z,1554325212.973 [Startup:StartupSatComms:B](INFO): Timed out from 2019-04-03T20:59:12.8Z
2019-04-03T21:00:12.973Z,1554325212.973 [Startup:StartupSatComms:B] Stopped
2019-04-03T21:00:12.973Z,1554325212.973 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-03T21:00:12.973Z,1554325212.973 [Startup:StartupSatComms] Stopped
2019-04-03T21:00:12.973Z,1554325212.973 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-03T21:00:12.974Z,1554325212.974 [Startup](INFO): Completed Startup
2019-04-03T21:00:12.974Z,1554325212.974 [MissionManager](INFO): Startup is completed.
2019-04-03T21:00:12.974Z,1554325212.974 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-03T21:00:12.974Z,1554325212.974 [Startup] Stopped
2019-04-03T21:00:12.974Z,1554325212.974 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-03T21:00:12.975Z,1554325212.975 [Startup:A.GoToSurface] Stopped
2019-04-03T21:00:12.975Z,1554325212.975 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-03T21:00:13.377Z,1554325213.377 [MissionManager](IMPORTANT): Started mission Default
2019-04-03T21:00:13.378Z,1554325213.378 [Default] Running Loop=1
2019-04-03T21:00:13.378Z,1554325213.378 [Default](DEBUG): Aggregate::initialize Default
2019-04-03T21:00:13.378Z,1554325213.378 [Default:B.GoToSurface] Running Loop=1
2019-04-03T21:00:13.378Z,1554325213.378 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-03T21:00:13.378Z,1554325213.378 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-03T21:00:13.378Z,1554325213.378 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-03T21:00:13.379Z,1554325213.379 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-03T21:00:13.379Z,1554325213.379 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-03T21:00:13.379Z,1554325213.379 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-03T21:00:13.380Z,1554325213.380 [Default:A.Wait] Running Loop=1
2019-04-03T21:00:13.380Z,1554325213.380 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:00:15.416Z,1554325215.416 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-04-03T21:00:20.232Z,1554325220.232 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:00:21.420Z,1554325221.420 [NAL9602](INFO): SBD MO Status=2, MOMSN=2627, MT Status=2, MTMSN=0
2019-04-03T21:00:21.420Z,1554325221.420 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:00:26.726Z,1554325226.726 [Default:A.Wait](INFO): Done Waiting.
2019-04-03T21:00:26.726Z,1554325226.726 [Default:A.Wait] Stopped
2019-04-03T21:00:26.726Z,1554325226.726 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:00:27.098Z,1554325227.098 [Default:CheckIn] Running Loop=1
2019-04-03T21:00:27.098Z,1554325227.098 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:00:27.098Z,1554325227.098 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:00:27.502Z,1554325227.502 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-03T21:00:28.705Z,1554325228.705 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:00:29.100Z,1554325229.100 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210022.00,A,3648.14168,N,12147.22879,W,0.058,0.00,030419,,,A*79
2019-04-03T21:00:29.102Z,1554325229.102 [NAL9602](INFO): GPS fix at 20190403T210022: (36.802361, -121.787147)
2019-04-03T21:00:29.127Z,1554325229.127 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:00:29.127Z,1554325229.127 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:00:29.572Z,1554325229.572 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-03T21:00:29.942Z,1554325229.942 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:00:40.092Z,1554325240.092 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:00:50.196Z,1554325250.196 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:00:50.572Z,1554325250.572 [NAL9602](INFO): SBD MO Status=1, MOMSN=2627, MT Status=0, MTMSN=0
2019-04-03T21:00:50.621Z,1554325250.621 [NAL9602](INFO): Sent 63 bytes from file Logs/20190403T205737/Courier0004.lzma
2019-04-03T21:00:50.621Z,1554325250.621 [NAL9602](INFO): Packets left to send: 0
2019-04-03T21:00:59.939Z,1554325259.939 [NAL9602](INFO): SBD MO Status=1, MOMSN=2628, MT Status=0, MTMSN=0
2019-04-03T21:00:59.989Z,1554325259.989 [NAL9602](INFO): Sent 281 bytes from file Logs/20190403T205737/Express0001.lzma
2019-04-03T21:00:59.989Z,1554325259.989 [NAL9602](INFO): Packets left to send: 0
2019-04-03T21:01:00.019Z,1554325260.019 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:01:10.731Z,1554325270.731 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004852
2019-04-03T21:01:11.376Z,1554325271.376 [NAL9602](INFO): SBD MO Status=1, MOMSN=2629, MT Status=0, MTMSN=0
2019-04-03T21:01:11.429Z,1554325271.429 [NAL9602](INFO): Sent 94 bytes from file Logs/20190403T205737/Express0005.lzma
2019-04-03T21:01:11.429Z,1554325271.429 [NAL9602](INFO): Packets left to send: 0
2019-04-03T21:01:11.558Z,1554325271.558 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:01:11.558Z,1554325271.558 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:01:11.558Z,1554325271.558 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:01:11.806Z,1554325271.806 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:01:21.916Z,1554325281.916 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:01:31.998Z,1554325291.998 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:01:41.709Z,1554325301.709 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:01:42.078Z,1554325302.078 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:01:51.800Z,1554325311.800 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:02:01.904Z,1554325321.904 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:02:11.997Z,1554325331.997 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:02:21.704Z,1554325341.704 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:02:31.398Z,1554325351.398 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:02:41.501Z,1554325361.501 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:04:41.877Z,1554325481.877 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-03T21:04:41.877Z,1554325481.877 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040314131496,35.0, -0.1,   0.0,1448.9A,  0.00,   0.00,   0.00,   0.00,   0.00
2019-04-03T21:05:12.988Z,1554325512.988 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T21:05:12.993Z,1554325512.993 [BPC1](INFO): Calculating totals. Valid battery stick count: 52. Valid reserve battery stick count: 4.
2019-04-03T21:05:12.996Z,1554325512.996 [BPC1](INFO): Received data from all battery sticks.
2019-04-03T21:06:11.980Z,1554325571.980 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:06:11.980Z,1554325571.980 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:06:11.980Z,1554325571.980 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:06:11.980Z,1554325571.980 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:06:12.381Z,1554325572.381 [Default:CheckIn:D] Stopped
2019-04-03T21:06:12.381Z,1554325572.381 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:06:12.793Z,1554325572.793 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.983382 min 
2019-04-03T21:06:12.793Z,1554325572.793 [Default:CheckIn:E] Stopped
2019-04-03T21:06:12.794Z,1554325572.794 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:06:12.794Z,1554325572.794 [Default:CheckIn] Stopped
2019-04-03T21:06:12.794Z,1554325572.794 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:06:12.794Z,1554325572.794 [Default:CheckIn](INFO): Running loop #2
2019-04-03T21:06:12.794Z,1554325572.794 [Default:CheckIn] Running Loop=2
2019-04-03T21:06:12.794Z,1554325572.794 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:06:12.794Z,1554325572.794 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:06:14.389Z,1554325574.389 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:06:14.784Z,1554325574.784 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210608.00,A,3648.14138,N,12147.22926,W,0.000,0.00,030419,,,D*71
2019-04-03T21:06:14.786Z,1554325574.786 [NAL9602](INFO): GPS fix at 20190403T210608: (36.802356, -121.787154)
2019-04-03T21:06:14.839Z,1554325574.839 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:06:14.839Z,1554325574.839 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:06:20.396Z,1554325580.396 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190403T205737/Courier0007.lzma
2019-04-03T21:06:21.202Z,1554325581.202 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0007.lzma.bak
2019-04-03T21:06:21.202Z,1554325581.202 [DataOverHttps](INFO): SBD MOMSN=10407874
2019-04-03T21:06:32.788Z,1554325592.788 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20190403T205737/Express0008.lzma
2019-04-03T21:06:33.594Z,1554325593.594 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0008.lzma.bak
2019-04-03T21:06:33.595Z,1554325593.595 [DataOverHttps](INFO): SBD MOMSN=10407877
2019-04-03T21:06:34.208Z,1554325594.208 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:06:34.208Z,1554325594.208 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:06:34.208Z,1554325594.208 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:06:49.932Z,1554325609.932 [NAL9602](INFO): SBD MO Status=2, MOMSN=2630, MT Status=2, MTMSN=0
2019-04-03T21:06:49.932Z,1554325609.932 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:07:33.156Z,1554325653.156 [NAL9602](INFO): SBD MO Status=0, MOMSN=2630, MT Status=0, MTMSN=0
2019-04-03T21:07:33.157Z,1554325653.157 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:08:03.866Z,1554325683.866 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:09:45.693Z,1554325785.693 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-03T21:09:45.694Z,1554325785.694 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   02.98
2019-04-03T21:11:34.807Z,1554325894.807 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:11:34.807Z,1554325894.807 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:11:34.807Z,1554325894.807 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:11:34.807Z,1554325894.807 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:11:35.181Z,1554325895.181 [Default:CheckIn:D] Stopped
2019-04-03T21:11:35.181Z,1554325895.181 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.363391 min 
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn:E] Stopped
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn] Stopped
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn](INFO): Running loop #3
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn] Running Loop=3
2019-04-03T21:11:35.600Z,1554325895.600 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:11:35.601Z,1554325895.601 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:11:37.193Z,1554325897.193 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:11:37.586Z,1554325897.586 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211131.00,A,3648.14154,N,12147.22978,W,0.078,0.00,030419,,,D*73
2019-04-03T21:11:37.588Z,1554325897.588 [NAL9602](INFO): GPS fix at 20190403T211131: (36.802359, -121.787163)
2019-04-03T21:11:37.649Z,1554325897.649 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:11:37.649Z,1554325897.649 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:11:43.336Z,1554325903.336 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190403T205737/Courier0010.lzma
2019-04-03T21:11:44.142Z,1554325904.142 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0010.lzma.bak
2019-04-03T21:11:44.143Z,1554325904.143 [DataOverHttps](INFO): SBD MOMSN=10407882
2019-04-03T21:11:52.953Z,1554325912.953 [NAL9602](INFO): SBD MO Status=0, MOMSN=2631, MT Status=0, MTMSN=0
2019-04-03T21:11:52.954Z,1554325912.954 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:11:57.480Z,1554325917.480 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190403T205737/Express0011.lzma
2019-04-03T21:11:58.302Z,1554325918.302 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0011.lzma.bak
2019-04-03T21:11:58.303Z,1554325918.303 [DataOverHttps](INFO): SBD MOMSN=10407885
2019-04-03T21:11:59.054Z,1554325919.054 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:11:59.054Z,1554325919.054 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:11:59.054Z,1554325919.054 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:12:23.658Z,1554325943.658 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:12:48.749Z,1554325968.749 [CBIT](INFO): Clearing failed state for component DropWeight
2019-04-03T21:12:48.749Z,1554325968.749 [DropWeight] No Fault, FailCount= 1
2019-04-03T21:16:59.621Z,1554326219.621 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:16:59.622Z,1554326219.622 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:16:59.622Z,1554326219.622 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:16:59.622Z,1554326219.622 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:17:00.040Z,1554326220.040 [Default:CheckIn:D] Stopped
2019-04-03T21:17:00.040Z,1554326220.040 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:17:00.426Z,1554326220.426 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.777698 min 
2019-04-03T21:17:00.426Z,1554326220.426 [Default:CheckIn:E] Stopped
2019-04-03T21:17:00.426Z,1554326220.426 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:17:00.426Z,1554326220.426 [Default:CheckIn] Stopped
2019-04-03T21:17:00.426Z,1554326220.426 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:17:00.427Z,1554326220.427 [Default:CheckIn](INFO): Running loop #4
2019-04-03T21:17:00.427Z,1554326220.427 [Default:CheckIn] Running Loop=4
2019-04-03T21:17:00.427Z,1554326220.427 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:17:00.427Z,1554326220.427 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:17:02.029Z,1554326222.029 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:17:02.420Z,1554326222.420 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211656.00,A,3648.13945,N,12147.23199,W,0.019,0.00,030419,,,D*7B
2019-04-03T21:17:02.423Z,1554326222.423 [NAL9602](INFO): GPS fix at 20190403T211656: (36.802324, -121.787200)
2019-04-03T21:17:02.450Z,1554326222.450 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:17:02.450Z,1554326222.450 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:17:08.300Z,1554326228.300 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190403T205737/Courier0013.lzma
2019-04-03T21:17:09.106Z,1554326229.106 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0013.lzma.bak
2019-04-03T21:17:09.107Z,1554326229.107 [DataOverHttps](INFO): SBD MOMSN=10408155
2019-04-03T21:17:20.564Z,1554326240.564 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190403T205737/Express0014.lzma
2019-04-03T21:17:21.370Z,1554326241.370 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0014.lzma.bak
2019-04-03T21:17:21.371Z,1554326241.371 [DataOverHttps](INFO): SBD MOMSN=10408158
2019-04-03T21:17:21.852Z,1554326241.852 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:17:21.852Z,1554326241.852 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:17:21.853Z,1554326241.853 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:17:27.872Z,1554326247.872 [NAL9602](INFO): SBD MO Status=0, MOMSN=2632, MT Status=0, MTMSN=0
2019-04-03T21:17:27.872Z,1554326247.872 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:17:58.575Z,1554326278.575 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:22:22.420Z,1554326542.420 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:22:22.420Z,1554326542.420 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:22:22.420Z,1554326542.420 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:22:22.420Z,1554326542.420 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:22:22.823Z,1554326542.823 [Default:CheckIn:D] Stopped
2019-04-03T21:22:22.823Z,1554326542.823 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:22:23.224Z,1554326543.224 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.157426 min 
2019-04-03T21:22:23.224Z,1554326543.224 [Default:CheckIn:E] Stopped
2019-04-03T21:22:23.224Z,1554326543.224 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:22:23.224Z,1554326543.224 [Default:CheckIn] Stopped
2019-04-03T21:22:23.225Z,1554326543.225 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:22:23.225Z,1554326543.225 [Default:CheckIn](INFO): Running loop #5
2019-04-03T21:22:23.225Z,1554326543.225 [Default:CheckIn] Running Loop=5
2019-04-03T21:22:23.225Z,1554326543.225 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:22:23.225Z,1554326543.225 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:22:24.829Z,1554326544.829 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:22:25.217Z,1554326545.217 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212219.00,A,3648.14141,N,12147.22886,W,0.019,0.00,030419,,,D*7A
2019-04-03T21:22:25.219Z,1554326545.219 [NAL9602](INFO): GPS fix at 20190403T212219: (36.802357, -121.787148)
2019-04-03T21:22:25.252Z,1554326545.252 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:22:25.252Z,1554326545.252 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:22:31.104Z,1554326551.104 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190403T205737/Courier0016.lzma
2019-04-03T21:22:31.910Z,1554326551.910 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0016.lzma.bak
2019-04-03T21:22:31.911Z,1554326551.911 [DataOverHttps](INFO): SBD MOMSN=10408166
2019-04-03T21:22:43.664Z,1554326563.664 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190403T205737/Express0017.lzma
2019-04-03T21:22:44.477Z,1554326564.477 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0017.lzma.bak
2019-04-03T21:22:44.478Z,1554326564.478 [DataOverHttps](INFO): SBD MOMSN=10408169
2019-04-03T21:22:45.056Z,1554326565.056 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:22:45.056Z,1554326565.056 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:22:45.056Z,1554326565.056 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:23:29.052Z,1554326609.052 [NAL9602](INFO): SBD MO Status=2, MOMSN=2633, MT Status=2, MTMSN=0
2019-04-03T21:23:29.052Z,1554326609.052 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:25:32.676Z,1554326732.676 [NAL9602](INFO): SBD MO Status=2, MOMSN=2633, MT Status=2, MTMSN=0
2019-04-03T21:25:32.676Z,1554326732.676 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:25:52.068Z,1554326752.068 [NAL9602](INFO): SBD MO Status=2, MOMSN=2633, MT Status=2, MTMSN=0
2019-04-03T21:25:52.068Z,1554326752.068 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:26:40.548Z,1554326800.548 [NAL9602](INFO): SBD MO Status=2, MOMSN=2633, MT Status=2, MTMSN=0
2019-04-03T21:26:40.548Z,1554326800.548 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:27:05.000Z,1554326826.000 [NAL9602](INFO): SBD MO Status=2, MOMSN=2633, MT Status=2, MTMSN=0
2019-04-03T21:27:06.000Z,1554326826.000 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:27:23.772Z,1554326843.772 [NAL9602](INFO): SBD MO Status=0, MOMSN=2633, MT Status=0, MTMSN=0
2019-04-03T21:27:23.773Z,1554326843.773 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:27:45.637Z,1554326865.637 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:27:45.637Z,1554326865.637 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:27:45.637Z,1554326865.637 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:27:45.637Z,1554326865.637 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:27:46.037Z,1554326866.037 [Default:CheckIn:D] Stopped
2019-04-03T21:27:46.037Z,1554326866.037 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:27:46.425Z,1554326866.425 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.544051 min 
2019-04-03T21:27:46.425Z,1554326866.425 [Default:CheckIn:E] Stopped
2019-04-03T21:27:46.425Z,1554326866.425 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:27:46.426Z,1554326866.426 [Default:CheckIn] Stopped
2019-04-03T21:27:46.426Z,1554326866.426 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:27:46.426Z,1554326866.426 [Default:CheckIn](INFO): Running loop #6
2019-04-03T21:27:46.426Z,1554326866.426 [Default:CheckIn] Running Loop=6
2019-04-03T21:27:46.426Z,1554326866.426 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:27:46.426Z,1554326866.426 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:27:48.041Z,1554326868.041 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:27:48.420Z,1554326868.420 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212742.00,A,3648.13781,N,12147.22969,W,0.097,0.00,030419,,,D*7A
2019-04-03T21:27:48.423Z,1554326868.423 [NAL9602](INFO): GPS fix at 20190403T212742: (36.802297, -121.787161)
2019-04-03T21:27:48.472Z,1554326868.472 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:27:48.472Z,1554326868.472 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:27:50.071Z,1554326870.071 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T21:27:54.240Z,1554326874.240 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190403T205737/Courier0019.lzma
2019-04-03T21:27:55.046Z,1554326875.046 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0019.lzma.bak
2019-04-03T21:27:55.046Z,1554326875.046 [DataOverHttps](INFO): SBD MOMSN=10408449
2019-04-03T21:28:06.480Z,1554326886.480 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190403T205737/Express0020.lzma
2019-04-03T21:28:07.278Z,1554326887.278 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0020.lzma.bak
2019-04-03T21:28:07.279Z,1554326887.279 [DataOverHttps](INFO): SBD MOMSN=10408454
2019-04-03T21:28:07.855Z,1554326887.855 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:28:07.855Z,1554326887.855 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:28:07.855Z,1554326887.855 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:28:20.754Z,1554326900.754 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:29:29.876Z,1554326969.876 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-03T21:29:29.876Z,1554326969.876 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   886.85
2019-04-03T21:29:31.878Z,1554326971.878 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-03T21:29:31.879Z,1554326971.879 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190403143.0, -0.1,   0.0,1448.9,  0
2019-04-03T21:32:49.876Z,1554327169.876 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-04-03T21:33:08.434Z,1554327188.434 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:33:08.434Z,1554327188.434 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:33:08.434Z,1554327188.434 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:33:08.434Z,1554327188.434 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:33:08.848Z,1554327188.848 [Default:CheckIn:D] Stopped
2019-04-03T21:33:08.848Z,1554327188.848 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:33:09.245Z,1554327189.245 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.924506 min 
2019-04-03T21:33:09.245Z,1554327189.245 [Default:CheckIn:E] Stopped
2019-04-03T21:33:09.245Z,1554327189.245 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:33:09.246Z,1554327189.246 [Default:CheckIn] Stopped
2019-04-03T21:33:09.246Z,1554327189.246 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:33:09.246Z,1554327189.246 [Default:CheckIn](INFO): Running loop #7
2019-04-03T21:33:09.246Z,1554327189.246 [Default:CheckIn] Running Loop=7
2019-04-03T21:33:09.246Z,1554327189.246 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:33:09.246Z,1554327189.246 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:33:10.861Z,1554327190.861 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:33:11.245Z,1554327191.245 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213305.00,A,3648.14077,N,12147.22818,W,0.019,0.00,030419,,,D*74
2019-04-03T21:33:11.247Z,1554327191.247 [NAL9602](INFO): GPS fix at 20190403T213305: (36.802346, -121.787136)
2019-04-03T21:33:11.270Z,1554327191.270 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:33:11.271Z,1554327191.271 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:33:17.084Z,1554327197.084 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190403T205737/Courier0022.lzma
2019-04-03T21:33:17.890Z,1554327197.890 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0022.lzma.bak
2019-04-03T21:33:17.891Z,1554327197.891 [DataOverHttps](INFO): SBD MOMSN=10408460
2019-04-03T21:33:29.720Z,1554327209.720 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190403T205737/Express0023.lzma
2019-04-03T21:33:30.526Z,1554327210.526 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0023.lzma.bak
2019-04-03T21:33:30.527Z,1554327210.527 [DataOverHttps](INFO): SBD MOMSN=10408463
2019-04-03T21:33:31.072Z,1554327211.072 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:33:31.072Z,1554327211.072 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:33:31.072Z,1554327211.072 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:34:52.244Z,1554327292.244 [NAL9602](INFO): SBD MO Status=2, MOMSN=2634, MT Status=2, MTMSN=0
2019-04-03T21:34:52.244Z,1554327292.244 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:35:46.380Z,1554327346.380 [NAL9602](INFO): SBD MO Status=2, MOMSN=2634, MT Status=2, MTMSN=0
2019-04-03T21:35:46.381Z,1554327346.381 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:36:47.378Z,1554327407.378 [NAL9602](INFO): SBD MO Status=0, MOMSN=2634, MT Status=0, MTMSN=0
2019-04-03T21:36:47.378Z,1554327407.378 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:37:18.086Z,1554327438.086 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:37:31.034Z,1554327451.034 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-03T21:37:31.035Z,1554327451.035 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.0076
2019-04-03T21:37:57.697Z,1554327477.697 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-04-03T21:37:57.697Z,1554327477.697 [RDI_Pathfinder](ERROR): Failed to parse:
:RA0,2394.75
2019-04-03T21:38:31.647Z,1554327511.647 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:38:31.647Z,1554327511.647 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:38:31.647Z,1554327511.647 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:38:31.647Z,1554327511.647 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:38:32.048Z,1554327512.048 [Default:CheckIn:D] Stopped
2019-04-03T21:38:32.048Z,1554327512.048 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:38:32.447Z,1554327512.447 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.311169 min 
2019-04-03T21:38:32.448Z,1554327512.448 [Default:CheckIn:E] Stopped
2019-04-03T21:38:32.448Z,1554327512.448 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:38:32.448Z,1554327512.448 [Default:CheckIn] Stopped
2019-04-03T21:38:32.449Z,1554327512.449 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:38:32.450Z,1554327512.450 [Default:CheckIn](INFO): Running loop #8
2019-04-03T21:38:32.450Z,1554327512.450 [Default:CheckIn] Running Loop=8
2019-04-03T21:38:32.450Z,1554327512.450 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:38:32.451Z,1554327512.451 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:38:34.053Z,1554327514.053 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:38:34.456Z,1554327514.456 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213828.00,A,3648.14050,N,12147.22998,W,0.039,0.00,030419,,,D*7E
2019-04-03T21:38:34.464Z,1554327514.464 [NAL9602](INFO): GPS fix at 20190403T213828: (36.802342, -121.787166)
2019-04-03T21:38:34.528Z,1554327514.528 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:38:34.528Z,1554327514.528 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:38:36.063Z,1554327516.063 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T21:38:48.188Z,1554327528.188 [NAL9602](INFO): SBD MO Status=0, MOMSN=2635, MT Status=0, MTMSN=0
2019-04-03T21:38:48.188Z,1554327528.188 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:38:53.632Z,1554327533.632 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190403T205737/Courier0025.lzma
2019-04-03T21:38:54.442Z,1554327534.442 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0025.lzma.bak
2019-04-03T21:38:54.442Z,1554327534.442 [DataOverHttps](INFO): SBD MOMSN=10408739
2019-04-03T21:39:05.605Z,1554327545.605 [CommandLine](IMPORTANT): got command burn on
2019-04-03T21:39:05.606Z,1554327545.606 [CommandLine](IMPORTANT): Activating dropweight wire
2019-04-03T21:39:06.224Z,1554327546.224 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190403T205737/Express0026.lzma
2019-04-03T21:39:06.768Z,1554327546.768 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-04-03T21:39:06.768Z,1554327546.768 [DropWeight] Hardware Fault, FailCount= 1
2019-04-03T21:39:06.768Z,1554327546.768 [DropWeight](ERROR): Hardware Fault
2019-04-03T21:39:06.884Z,1554327546.884 [CBIT](INFO): Critical error at 20190403T213906
2019-04-03T21:39:06.891Z,1554327546.891 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-04-03T21:39:06.891Z,1554327546.891 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-04-03T21:39:07.030Z,1554327547.030 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0026.lzma.bak
2019-04-03T21:39:07.031Z,1554327547.031 [DataOverHttps](INFO): SBD MOMSN=10408742
2019-04-03T21:39:07.210Z,1554327547.210 [CBIT](INFO): Critical error at 20190403T213906
2019-04-03T21:39:07.612Z,1554327547.612 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:39:07.612Z,1554327547.612 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:39:07.612Z,1554327547.612 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:39:16.758Z,1554327556.758 [CommandLine](IMPORTANT): got command burn off
2019-04-03T21:39:16.758Z,1554327556.758 [CommandLine](IMPORTANT): Deactivating dropweight wire
2019-04-03T21:39:18.891Z,1554327558.891 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:40:13.861Z,1554327613.861 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-03T21:40:13.861Z,1554327613.861 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040314484696,35.0, -0.1,   0.0, 0
2019-04-03T21:41:56.888Z,1554327716.888 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-03T21:41:56.888Z,1554327716.888 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040314502996,31,   0.0,1448.9,  0
2019-04-03T21:44:08.177Z,1554327848.177 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:44:08.177Z,1554327848.177 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:44:08.177Z,1554327848.177 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:44:08.177Z,1554327848.177 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:44:08.584Z,1554327848.584 [Default:CheckIn:D] Stopped
2019-04-03T21:44:08.585Z,1554327848.585 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:44:08.996Z,1554327848.996 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.920113 min 
2019-04-03T21:44:08.996Z,1554327848.996 [Default:CheckIn:E] Stopped
2019-04-03T21:44:08.996Z,1554327848.996 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:44:08.996Z,1554327848.996 [Default:CheckIn] Stopped
2019-04-03T21:44:08.996Z,1554327848.996 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:44:08.997Z,1554327848.997 [Default:CheckIn](INFO): Running loop #9
2019-04-03T21:44:08.997Z,1554327848.997 [Default:CheckIn] Running Loop=9
2019-04-03T21:44:08.997Z,1554327848.997 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:44:08.997Z,1554327848.997 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:44:10.593Z,1554327850.593 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:44:10.988Z,1554327850.988 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214405.00,A,3648.13402,N,12147.22910,W,0.000,0.00,030419,,,D*74
2019-04-03T21:44:10.991Z,1554327850.991 [NAL9602](INFO): GPS fix at 20190403T214405: (36.802234, -121.787152)
2019-04-03T21:44:11.043Z,1554327851.043 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:44:11.043Z,1554327851.043 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:44:11.832Z,1554327851.832 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:44:11.832Z,1554327851.832 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:44:11.832Z,1554327851.832 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:44:13.010Z,1554327853.010 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T21:44:43.306Z,1554327883.306 [NAL9602](INFO): SBD MO Status=0, MOMSN=2636, MT Status=0, MTMSN=0
2019-04-03T21:44:43.306Z,1554327883.306 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:45:14.010Z,1554327914.010 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:48:24.831Z,1554328104.831 [CommandLine](IMPORTANT): got command burn on
2019-04-03T21:48:24.831Z,1554328104.831 [CommandLine](IMPORTANT): Activating dropweight wire
2019-04-03T21:48:30.397Z,1554328110.397 [CommandLine](IMPORTANT): got command burn off
2019-04-03T21:48:30.397Z,1554328110.397 [CommandLine](IMPORTANT): Deactivating dropweight wire
2019-04-03T21:49:12.407Z,1554328152.407 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:49:12.408Z,1554328152.408 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:49:12.408Z,1554328152.408 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:49:12.408Z,1554328152.408 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:49:12.804Z,1554328152.804 [Default:CheckIn:D] Stopped
2019-04-03T21:49:12.804Z,1554328152.804 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:49:13.207Z,1554328153.207 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.990430 min 
2019-04-03T21:49:13.207Z,1554328153.207 [Default:CheckIn:E] Stopped
2019-04-03T21:49:13.208Z,1554328153.208 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:49:13.208Z,1554328153.208 [Default:CheckIn] Stopped
2019-04-03T21:49:13.208Z,1554328153.208 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:49:13.208Z,1554328153.208 [Default:CheckIn](INFO): Running loop #10
2019-04-03T21:49:13.208Z,1554328153.208 [Default:CheckIn] Running Loop=10
2019-04-03T21:49:13.208Z,1554328153.208 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:49:13.208Z,1554328153.208 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:49:14.813Z,1554328154.813 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:49:15.197Z,1554328155.197 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214909.00,A,3648.14050,N,12147.22864,W,0.078,202.26,030419,,,D*78
2019-04-03T21:49:15.200Z,1554328155.200 [NAL9602](INFO): GPS fix at 20190403T214909: (36.802342, -121.787144)
2019-04-03T21:49:15.244Z,1554328155.244 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:49:15.244Z,1554328155.244 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:49:17.222Z,1554328157.222 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T21:49:20.756Z,1554328160.756 [DataOverHttps](INFO): Sending 138 bytes from file Logs/20190403T205737/Courier0028.lzma
2019-04-03T21:49:21.563Z,1554328161.563 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0028.lzma.bak
2019-04-03T21:49:21.563Z,1554328161.563 [DataOverHttps](INFO): SBD MOMSN=10408860
2019-04-03T21:49:41.472Z,1554328181.472 [NAL9602](INFO): SBD MO Status=2, MOMSN=2637, MT Status=2, MTMSN=0
2019-04-03T21:49:41.472Z,1554328181.472 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:50:18.188Z,1554328218.188 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190403T205737/Courier0031.lzma
2019-04-03T21:50:18.994Z,1554328218.994 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0031.lzma.bak
2019-04-03T21:50:18.995Z,1554328218.995 [DataOverHttps](INFO): SBD MOMSN=10409129
2019-04-03T21:50:30.873Z,1554328230.873 [DataOverHttps](INFO): Sending 188 bytes from file Logs/20190403T205737/Express0029.lzma
2019-04-03T21:50:31.678Z,1554328231.678 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0029.lzma.bak
2019-04-03T21:50:31.679Z,1554328231.679 [DataOverHttps](INFO): SBD MOMSN=10409132
2019-04-03T21:50:43.373Z,1554328243.373 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20190403T205737/Express0032.lzma
2019-04-03T21:50:44.179Z,1554328244.179 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0032.lzma.bak
2019-04-03T21:50:44.179Z,1554328244.179 [DataOverHttps](INFO): SBD MOMSN=10409139
2019-04-03T21:50:44.928Z,1554328244.928 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:50:44.928Z,1554328244.928 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:50:44.928Z,1554328244.928 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:51:35.388Z,1554328295.388 [NAL9602](INFO): SBD MO Status=0, MOMSN=2637, MT Status=0, MTMSN=0
2019-04-03T21:51:35.388Z,1554328295.388 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:52:06.090Z,1554328326.090 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T21:54:06.941Z,1554328446.941 [CBIT](INFO): Clearing failed state for component DropWeight
2019-04-03T21:54:06.941Z,1554328446.941 [DropWeight] No Fault, FailCount= 1
2019-04-03T21:55:45.507Z,1554328545.507 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T21:55:45.507Z,1554328545.507 [Default:CheckIn:C.Wait] Stopped
2019-04-03T21:55:45.507Z,1554328545.507 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T21:55:45.507Z,1554328545.507 [Default:CheckIn:D] Running Loop=1
2019-04-03T21:55:45.889Z,1554328545.889 [Default:CheckIn:D] Stopped
2019-04-03T21:55:45.889Z,1554328545.889 [Default:CheckIn:E] Running Loop=1
2019-04-03T21:55:46.296Z,1554328546.296 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.541858 min 
2019-04-03T21:55:46.296Z,1554328546.296 [Default:CheckIn:E] Stopped
2019-04-03T21:55:46.296Z,1554328546.296 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T21:55:46.296Z,1554328546.296 [Default:CheckIn] Stopped
2019-04-03T21:55:46.297Z,1554328546.297 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T21:55:46.297Z,1554328546.297 [Default:CheckIn](INFO): Running loop #11
2019-04-03T21:55:46.297Z,1554328546.297 [Default:CheckIn] Running Loop=11
2019-04-03T21:55:46.297Z,1554328546.297 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T21:55:46.297Z,1554328546.297 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T21:55:47.920Z,1554328547.920 [NAL9602](DEBUG): Fix Requested
2019-04-03T21:55:48.288Z,1554328548.288 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215542.00,A,3648.14160,N,12147.22847,W,0.019,202.26,030419,,,D*7E
2019-04-03T21:55:48.291Z,1554328548.291 [NAL9602](INFO): GPS fix at 20190403T215542: (36.802360, -121.787141)
2019-04-03T21:55:48.320Z,1554328548.320 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T21:55:48.320Z,1554328548.320 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T21:55:50.055Z,1554328550.055 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T21:55:54.596Z,1554328554.596 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190403T205737/Courier0034.lzma
2019-04-03T21:55:55.403Z,1554328555.403 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0034.lzma.bak
2019-04-03T21:55:55.403Z,1554328555.403 [DataOverHttps](INFO): SBD MOMSN=10409172
2019-04-03T21:56:06.816Z,1554328566.816 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190403T205737/Express0035.lzma
2019-04-03T21:56:07.622Z,1554328567.622 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0035.lzma.bak
2019-04-03T21:56:07.623Z,1554328567.623 [DataOverHttps](INFO): SBD MOMSN=10409175
2019-04-03T21:56:08.254Z,1554328568.254 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T21:56:08.254Z,1554328568.254 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T21:56:08.254Z,1554328568.254 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T21:56:13.486Z,1554328573.486 [NAL9602](INFO): SBD MO Status=2, MOMSN=2638, MT Status=2, MTMSN=0
2019-04-03T21:56:13.486Z,1554328573.486 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T21:56:30.049Z,1554328590.049 [NAL9602](INFO): SBD MO Status=0, MOMSN=2638, MT Status=0, MTMSN=0
2019-04-03T21:56:30.049Z,1554328590.049 [NAL9602](INFO): No messages in MT queue
2019-04-03T21:57:00.750Z,1554328620.750 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T22:00:08.649Z,1554328808.649 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-04-03T22:00:08.649Z,1554328808.649 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,     ,        +0.00,        +0.00,   0.00,3726.42
2019-04-03T22:01:08.835Z,1554328868.835 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T22:01:08.835Z,1554328868.835 [Default:CheckIn:C.Wait] Stopped
2019-04-03T22:01:08.835Z,1554328868.835 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T22:01:08.835Z,1554328868.835 [Default:CheckIn:D] Running Loop=1
2019-04-03T22:01:09.236Z,1554328869.236 [Default:CheckIn:D] Stopped
2019-04-03T22:01:09.236Z,1554328869.236 [Default:CheckIn:E] Running Loop=1
2019-04-03T22:01:09.647Z,1554328869.647 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.930965 min 
2019-04-03T22:01:09.647Z,1554328869.647 [Default:CheckIn:E] Stopped
2019-04-03T22:01:09.648Z,1554328869.648 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T22:01:09.648Z,1554328869.648 [Default:CheckIn] Stopped
2019-04-03T22:01:09.648Z,1554328869.648 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T22:01:09.648Z,1554328869.648 [Default:CheckIn](INFO): Running loop #12
2019-04-03T22:01:09.648Z,1554328869.648 [Default:CheckIn] Running Loop=12
2019-04-03T22:01:09.648Z,1554328869.648 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T22:01:09.648Z,1554328869.648 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T22:01:11.241Z,1554328871.241 [NAL9602](DEBUG): Fix Requested
2019-04-03T22:01:11.633Z,1554328871.633 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220105.00,A,3648.16424,N,12147.21351,W,0.136,21.96,030419,,,D*43
2019-04-03T22:01:11.635Z,1554328871.635 [NAL9602](INFO): GPS fix at 20190403T220105: (36.802737, -121.786892)
2019-04-03T22:01:11.668Z,1554328871.668 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T22:01:11.668Z,1554328871.668 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T22:01:13.254Z,1554328873.254 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T22:01:25.373Z,1554328885.373 [NAL9602](INFO): SBD MO Status=0, MOMSN=2639, MT Status=0, MTMSN=0
2019-04-03T22:01:25.373Z,1554328885.373 [NAL9602](INFO): No messages in MT queue
2019-04-03T22:01:29.022Z,1554328889.022 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-04-03T22:01:48.641Z,1554328908.641 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190403T205737/Courier0037.lzma
2019-04-03T22:01:49.438Z,1554328909.438 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0037.lzma.bak
2019-04-03T22:01:49.439Z,1554328909.439 [DataOverHttps](INFO): SBD MOMSN=10409463
2019-04-03T22:01:56.071Z,1554328916.071 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T22:02:00.860Z,1554328920.860 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190403T205737/Express0038.lzma
2019-04-03T22:02:01.666Z,1554328921.666 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0038.lzma.bak
2019-04-03T22:02:01.667Z,1554328921.667 [DataOverHttps](INFO): SBD MOMSN=10409466
2019-04-03T22:02:02.156Z,1554328922.156 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T22:02:02.156Z,1554328922.156 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T22:02:02.156Z,1554328922.156 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T22:02:58.722Z,1554328978.722 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-04-03T22:02:58.722Z,1554328978.722 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.0.38
2019-04-03T22:07:02.778Z,1554329222.778 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T22:07:02.778Z,1554329222.778 [Default:CheckIn:C.Wait] Stopped
2019-04-03T22:07:02.779Z,1554329222.779 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T22:07:02.779Z,1554329222.779 [Default:CheckIn:D] Running Loop=1
2019-04-03T22:07:03.142Z,1554329223.142 [Default:CheckIn:D] Stopped
2019-04-03T22:07:03.142Z,1554329223.142 [Default:CheckIn:E] Running Loop=1
2019-04-03T22:07:03.558Z,1554329223.558 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.829411 min 
2019-04-03T22:07:03.558Z,1554329223.558 [Default:CheckIn:E] Stopped
2019-04-03T22:07:03.558Z,1554329223.558 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T22:07:03.558Z,1554329223.558 [Default:CheckIn] Stopped
2019-04-03T22:07:03.558Z,1554329223.558 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T22:07:03.559Z,1554329223.559 [Default:CheckIn](INFO): Running loop #13
2019-04-03T22:07:03.559Z,1554329223.559 [Default:CheckIn] Running Loop=13
2019-04-03T22:07:03.559Z,1554329223.559 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T22:07:03.559Z,1554329223.559 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T22:07:05.153Z,1554329225.153 [NAL9602](DEBUG): Fix Requested
2019-04-03T22:07:05.544Z,1554329225.544 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220659.00,A,3648.16949,N,12147.21699,W,0.097,21.96,030419,,,D*40
2019-04-03T22:07:05.547Z,1554329225.547 [NAL9602](INFO): GPS fix at 20190403T220659: (36.802825, -121.786950)
2019-04-03T22:07:05.600Z,1554329225.600 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T22:07:05.600Z,1554329225.600 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T22:07:07.182Z,1554329227.182 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T22:07:11.463Z,1554329231.463 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190403T205737/Courier0040.lzma
2019-04-03T22:07:12.246Z,1554329232.246 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0040.lzma.bak
2019-04-03T22:07:12.247Z,1554329232.247 [DataOverHttps](INFO): SBD MOMSN=10409516
2019-04-03T22:07:18.870Z,1554329238.870 [NAL9602](INFO): SBD MO Status=0, MOMSN=2640, MT Status=0, MTMSN=0
2019-04-03T22:07:18.870Z,1554329238.870 [NAL9602](INFO): No messages in MT queue
2019-04-03T22:07:24.244Z,1554329244.244 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190403T205737/Express0041.lzma
2019-04-03T22:07:25.050Z,1554329245.050 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0041.lzma.bak
2019-04-03T22:07:25.051Z,1554329245.051 [DataOverHttps](INFO): SBD MOMSN=10409519
2019-04-03T22:07:25.772Z,1554329245.772 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T22:07:25.772Z,1554329245.772 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T22:07:25.772Z,1554329245.772 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T22:07:45.958Z,1554329265.958 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:07:49.578Z,1554329269.578 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T22:07:56.054Z,1554329276.054 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:08:06.158Z,1554329286.158 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:08:16.254Z,1554329296.254 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:08:25.954Z,1554329305.954 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:08:36.054Z,1554329316.054 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:08:45.756Z,1554329325.756 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:08:51.010Z,1554329331.010 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-03T22:08:51.010Z,1554329331.010 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040315172296,35.0, -0.1,   0.     +0.00,   0.00,4247.26
2019-04-03T22:08:55.492Z,1554329335.492 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:09:05.141Z,1554329345.141 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:09:14.844Z,1554329354.844 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:09:24.938Z,1554329364.938 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:09:33.839Z,1554329373.839 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-03T22:09:33.839Z,1554329373.839 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-04-03T22:09:34.661Z,1554329374.661 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:09:44.323Z,1554329384.323 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:09:54.031Z,1554329394.031 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:10:03.734Z,1554329403.734 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:11:56.858Z,1554329516.858 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-04-03T22:12:26.344Z,1554329546.344 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T22:12:26.344Z,1554329546.344 [Default:CheckIn:C.Wait] Stopped
2019-04-03T22:12:26.345Z,1554329546.345 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T22:12:26.345Z,1554329546.345 [Default:CheckIn:D] Running Loop=1
2019-04-03T22:12:26.764Z,1554329546.764 [Default:CheckIn:D] Stopped
2019-04-03T22:12:26.764Z,1554329546.764 [Default:CheckIn:E] Running Loop=1
2019-04-03T22:12:27.158Z,1554329547.158 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 72.223104 min 
2019-04-03T22:12:27.158Z,1554329547.158 [Default:CheckIn:E] Stopped
2019-04-03T22:12:27.158Z,1554329547.158 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T22:12:27.158Z,1554329547.158 [Default:CheckIn] Stopped
2019-04-03T22:12:27.158Z,1554329547.158 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T22:12:27.158Z,1554329547.158 [Default:CheckIn](INFO): Running loop #14
2019-04-03T22:12:27.159Z,1554329547.159 [Default:CheckIn] Running Loop=14
2019-04-03T22:12:27.159Z,1554329547.159 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T22:12:27.159Z,1554329547.159 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T22:12:28.753Z,1554329548.753 [NAL9602](DEBUG): Fix Requested
2019-04-03T22:12:29.148Z,1554329549.148 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221223.00,A,3648.34060,N,12147.10956,W,5.151,359.55,030419,,,D*79
2019-04-03T22:12:29.151Z,1554329549.151 [NAL9602](INFO): GPS fix at 20190403T221223: (36.805677, -121.785159)
2019-04-03T22:12:29.186Z,1554329549.186 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T22:12:29.186Z,1554329549.186 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T22:12:31.208Z,1554329551.208 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-04-03T22:12:39.276Z,1554329559.276 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-03T22:12:39.282Z,1554329559.282 [BPC1](INFO): Calculating totals. Valid battery stick count: 52. Valid reserve battery stick count: 4.
2019-04-03T22:12:39.284Z,1554329559.284 [BPC1](INFO): Received data from all battery sticks.
2019-04-03T22:12:53.384Z,1554329573.384 [NAL9602](INFO): SBD MO Status=2, MOMSN=2641, MT Status=2, MTMSN=0
2019-04-03T22:12:53.384Z,1554329573.384 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T22:13:02.684Z,1554329582.684 [NAL9602](INFO): SBD MO Status=0, MOMSN=2641, MT Status=0, MTMSN=0
2019-04-03T22:13:02.684Z,1554329582.684 [NAL9602](INFO): No messages in MT queue
2019-04-03T22:13:18.768Z,1554329598.768 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190403T205737/Courier0043.lzma
2019-04-03T22:13:19.575Z,1554329599.575 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0043.lzma.bak
2019-04-03T22:13:19.575Z,1554329599.575 [DataOverHttps](INFO): SBD MOMSN=10409778
2019-04-03T22:13:31.152Z,1554329611.152 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190403T205737/Express0044.lzma
2019-04-03T22:13:31.958Z,1554329611.958 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0044.lzma.bak
2019-04-03T22:13:31.959Z,1554329611.959 [DataOverHttps](INFO): SBD MOMSN=10409783
2019-04-03T22:13:32.611Z,1554329612.611 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T22:13:32.611Z,1554329612.611 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T22:13:32.611Z,1554329612.611 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T22:13:33.379Z,1554329613.379 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T22:14:15.844Z,1554329655.844 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-03T22:14:15.845Z,1554329655.845 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-32768-32768,-32768,-32768,V
2019-04-03T22:18:33.181Z,1554329913.181 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T22:18:33.181Z,1554329913.181 [Default:CheckIn:C.Wait] Stopped
2019-04-03T22:18:33.182Z,1554329913.182 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T22:18:33.182Z,1554329913.182 [Default:CheckIn:D] Running Loop=1
2019-04-03T22:18:33.612Z,1554329913.612 [Default:CheckIn:D] Stopped
2019-04-03T22:18:33.612Z,1554329913.612 [Default:CheckIn:E] Running Loop=1
2019-04-03T22:18:33.982Z,1554329913.982 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 78.337240 min 
2019-04-03T22:18:33.982Z,1554329913.982 [Default:CheckIn:E] Stopped
2019-04-03T22:18:33.982Z,1554329913.982 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T22:18:33.982Z,1554329913.982 [Default:CheckIn] Stopped
2019-04-03T22:18:33.982Z,1554329913.982 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T22:18:33.983Z,1554329913.983 [Default:CheckIn](INFO): Running loop #15
2019-04-03T22:18:33.983Z,1554329913.983 [Default:CheckIn] Running Loop=15
2019-04-03T22:18:33.983Z,1554329913.983 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T22:18:33.983Z,1554329913.983 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T22:18:35.585Z,1554329915.585 [NAL9602](DEBUG): Fix Requested
2019-04-03T22:18:35.981Z,1554329915.981 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221830.00,A,3648.13841,N,12147.80588,W,13.276,221.56,030419,,,D*45
2019-04-03T22:18:35.983Z,1554329915.983 [NAL9602](INFO): GPS fix at 20190403T221830: (36.802307, -121.796765)
2019-04-03T22:18:36.023Z,1554329916.023 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T22:18:36.023Z,1554329916.023 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T22:18:41.885Z,1554329921.885 [DataOverHttps](INFO): Sending 79 bytes from file Logs/20190403T205737/Courier0046.lzma
2019-04-03T22:18:42.690Z,1554329922.690 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0046.lzma.bak
2019-04-03T22:18:42.691Z,1554329922.691 [DataOverHttps](INFO): SBD MOMSN=10409803
2019-04-03T22:18:54.166Z,1554329934.166 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190403T205737/Express0047.lzma
2019-04-03T22:18:54.971Z,1554329934.971 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0047.lzma.bak
2019-04-03T22:18:54.971Z,1554329934.971 [DataOverHttps](INFO): SBD MOMSN=10409807
2019-04-03T22:18:55.458Z,1554329935.458 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T22:18:55.458Z,1554329935.458 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T22:18:55.459Z,1554329935.459 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T22:19:01.475Z,1554329941.475 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-03T22:19:01.475Z,1554329941.475 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-2768,V
2019-04-03T22:19:09.512Z,1554329949.512 [NAL9602](INFO): SBD MO Status=0, MOMSN=2642, MT Status=0, MTMSN=0
2019-04-03T22:19:09.512Z,1554329949.512 [NAL9602](INFO): No messages in MT queue
2019-04-03T22:19:40.219Z,1554329980.219 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T22:23:55.993Z,1554330235.993 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T22:23:55.993Z,1554330235.993 [Default:CheckIn:C.Wait] Stopped
2019-04-03T22:23:55.993Z,1554330235.993 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T22:23:55.994Z,1554330235.994 [Default:CheckIn:D] Running Loop=1
2019-04-03T22:23:56.405Z,1554330236.405 [Default:CheckIn:D] Stopped
2019-04-03T22:23:56.405Z,1554330236.405 [Default:CheckIn:E] Running Loop=1
2019-04-03T22:23:56.803Z,1554330236.803 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 83.717122 min 
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn:E] Stopped
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn] Stopped
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn](INFO): Running loop #16
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn] Running Loop=16
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T22:23:56.804Z,1554330236.804 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T22:23:58.393Z,1554330238.393 [NAL9602](DEBUG): Fix Requested
2019-04-03T22:23:58.792Z,1554330238.792 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222352.00,A,3647.14185,N,12149.11167,W,18.019,235.35,030419,,,D*43
2019-04-03T22:23:58.795Z,1554330238.795 [NAL9602](INFO): GPS fix at 20190403T222352: (36.785697, -121.818528)
2019-04-03T22:23:58.828Z,1554330238.828 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T22:23:58.828Z,1554330238.828 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T22:24:04.732Z,1554330244.732 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190403T205737/Courier0049.lzma
2019-04-03T22:24:05.538Z,1554330245.538 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0049.lzma.bak
2019-04-03T22:24:05.539Z,1554330245.539 [DataOverHttps](INFO): SBD MOMSN=10409823
2019-04-03T22:24:34.749Z,1554330274.749 [NAL9602](INFO): SBD MO Status=2, MOMSN=2643, MT Status=2, MTMSN=0
2019-04-03T22:24:34.749Z,1554330274.749 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T22:24:43.638Z,1554330283.638 [NAL9602](INFO): SBD MO Status=0, MOMSN=2643, MT Status=0, MTMSN=0
2019-04-03T22:24:43.638Z,1554330283.638 [NAL9602](INFO): No messages in MT queue
2019-04-03T22:24:50.472Z,1554330290.472 [DataOverHttps](INFO): Sending 137 bytes from file Logs/20190403T205737/Express0050.lzma
2019-04-03T22:24:51.279Z,1554330291.279 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0050.lzma.bak
2019-04-03T22:24:51.279Z,1554330291.279 [DataOverHttps](INFO): SBD MOMSN=10410080
2019-04-03T22:24:51.763Z,1554330291.763 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T22:24:51.763Z,1554330291.763 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T22:24:51.763Z,1554330291.763 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T22:25:14.349Z,1554330314.349 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T22:27:43.454Z,1554330463.454 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-03T22:27:43.455Z,1554330463.455 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-3768,V
2019-04-03T22:29:52.321Z,1554330592.321 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T22:29:52.321Z,1554330592.321 [Default:CheckIn:C.Wait] Stopped
2019-04-03T22:29:52.321Z,1554330592.321 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T22:29:52.321Z,1554330592.321 [Default:CheckIn:D] Running Loop=1
2019-04-03T22:29:52.736Z,1554330592.736 [Default:CheckIn:D] Stopped
2019-04-03T22:29:52.736Z,1554330592.736 [Default:CheckIn:E] Running Loop=1
2019-04-03T22:29:53.132Z,1554330593.132 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 89.655965 min 
2019-04-03T22:29:53.132Z,1554330593.132 [Default:CheckIn:E] Stopped
2019-04-03T22:29:53.132Z,1554330593.132 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T22:29:53.132Z,1554330593.132 [Default:CheckIn] Stopped
2019-04-03T22:29:53.133Z,1554330593.133 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T22:29:53.133Z,1554330593.133 [Default:CheckIn](INFO): Running loop #17
2019-04-03T22:29:53.133Z,1554330593.133 [Default:CheckIn] Running Loop=17
2019-04-03T22:29:53.133Z,1554330593.133 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T22:29:53.133Z,1554330593.133 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T22:29:54.737Z,1554330594.737 [NAL9602](DEBUG): Fix Requested
2019-04-03T22:29:55.124Z,1554330595.124 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222949.00,A,3646.07493,N,12150.11532,W,8.397,241.80,030419,,,D*77
2019-04-03T22:29:55.127Z,1554330595.127 [NAL9602](INFO): GPS fix at 20190403T222949: (36.767916, -121.835255)
2019-04-03T22:29:55.150Z,1554330595.150 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T22:29:55.150Z,1554330595.150 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T22:29:57.166Z,1554330597.166 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T22:30:00.724Z,1554330600.724 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190403T205737/Courier0052.lzma
2019-04-03T22:30:01.531Z,1554330601.531 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Courier0052.lzma.bak
2019-04-03T22:30:01.531Z,1554330601.531 [DataOverHttps](INFO): SBD MOMSN=10410099
2019-04-03T22:30:14.008Z,1554330614.008 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20190403T205737/Express0053.lzma
2019-04-03T22:30:14.814Z,1554330614.814 [DataOverHttps](INFO): Moved sent file to Logs/20190403T205737/Express0053.lzma.bak
2019-04-03T22:30:14.815Z,1554330614.815 [DataOverHttps](INFO): SBD MOMSN=10410102
2019-04-03T22:30:15.352Z,1554330615.352 [Default:CheckIn:Read_Iridium] Stopped
2019-04-03T22:30:15.352Z,1554330615.352 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-03T22:30:15.352Z,1554330615.352 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-03T22:30:19.780Z,1554330619.780 [NAL9602](INFO): SBD MO Status=2, MOMSN=2644, MT Status=2, MTMSN=0
2019-04-03T22:30:19.781Z,1554330619.781 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-03T22:30:41.588Z,1554330641.588 [NAL9602](INFO): SBD MO Status=0, MOMSN=2644, MT Status=0, MTMSN=0
2019-04-03T22:30:41.588Z,1554330641.588 [NAL9602](INFO): No messages in MT queue
2019-04-03T22:31:12.287Z,1554330672.287 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-03T22:31:40.181Z,1554330700.181 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-03T22:31:40.181Z,1554330700.181 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-04-03T22:31:41.813Z,1554330701.813 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -22.00 mm (1 active estimators).
2019-04-03T22:32:31.185Z,1554330751.185 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-04-03T22:32:31.589Z,1554330751.589 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.227493
2019-04-03T22:33:06.333Z,1554330786.333 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-04-03T22:33:41.481Z,1554330821.481 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-04-03T22:34:16.629Z,1554330856.629 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-04-03T22:34:51.777Z,1554330891.777 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-04-03T22:35:15.984Z,1554330915.984 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-03T22:35:15.984Z,1554330915.984 [Default:CheckIn:C.Wait] Stopped
2019-04-03T22:35:15.984Z,1554330915.984 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-03T22:35:15.984Z,1554330915.984 [Default:CheckIn:D] Running Loop=1
2019-04-03T22:35:16.386Z,1554330916.386 [Default:CheckIn:D] Stopped
2019-04-03T22:35:16.386Z,1554330916.386 [Default:CheckIn:E] Running Loop=1
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 95.050130 min 
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn:E] Stopped
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn] Stopped
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn](INFO): Running loop #18
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn] Running Loop=18
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-03T22:35:16.796Z,1554330916.796 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-03T22:35:18.393Z,1554330918.393 [NAL9602](DEBUG): Fix Requested
2019-04-03T22:35:18.788Z,1554330918.788 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223512.00,A,3646.05214,N,12150.14646,W,0.486,64.84,030419,,,D*44
2019-04-03T22:35:18.791Z,1554330918.791 [NAL9602](INFO): GPS fix at 20190403T223512: (36.767536, -121.835774)
2019-04-03T22:35:18.846Z,1554330918.846 [Default:CheckIn:Read_GPS] Stopped
2019-04-03T22:35:18.847Z,1554330918.847 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-03T22:35:20.006Z,1554330920.006 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-04-03T22:35:26.925Z,1554330926.925 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-04-03T22:35:34.612Z,1554330934.612 [NAL9602](INFO): SBD MO Status=1, MOMSN=2645, MT Status=0, MTMSN=0
2019-04-03T22:35:34.665Z,1554330934.665 [NAL9602](INFO): Sent 61 bytes from file Logs/20190403T205737/Courier0055.lzma
2019-04-03T22:35:34.665Z,1554330934.665 [NAL9602](INFO): Packets left to send: 0
2019-04-03T22:35:37.350Z,1554330937.350 [DataOverHttps](IMPORTANT): SBD MTMSN=20190403T223531
2019-04-03T22:35:37.354Z,1554330937.354 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003629
2019-04-03T22:35:42.921Z,1554330942.921 [DataOverHttps](INFO): Received command:restart logs