2019-08-16T13:26:49.868Z,1565962009.868 [Supervisor](DEBUG): Initializing supervisor.
2019-08-16T13:26:49.870Z,1565962009.870 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-08-16T13:26:49.871Z,1565962009.871 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-08-16T13:26:49.871Z,1565962009.871 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-08-16T13:26:49.872Z,1565962009.872 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-08-16T13:26:49.873Z,1565962009.873 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-08-16T13:26:49.875Z,1565962009.875 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-08-16T13:26:49.887Z,1565962009.887 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-08-16T13:26:49.888Z,1565962009.888 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-08-16T13:26:49.888Z,1565962009.888 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-08-16T13:26:49.889Z,1565962009.889 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-08-16T13:26:49.890Z,1565962009.890 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-08-16T13:26:49.891Z,1565962009.891 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-08-16T13:26:49.893Z,1565962009.893 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-08-16T13:26:49.893Z,1565962009.893 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-08-16T13:26:49.897Z,1565962009.897 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-08-16T13:26:49.993Z,1565962009.993 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-08-16T13:26:49.995Z,1565962009.995 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-08-16T13:26:50.198Z,1565962010.198 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-08-16T13:26:50.200Z,1565962010.200 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-08-16T13:26:50.336Z,1565962010.336 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-08-16T13:26:50.336Z,1565962010.336 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-08-16T13:26:50.897Z,1565962010.897 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-08-16T13:26:50.897Z,1565962010.897 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-08-16T13:26:51.338Z,1565962011.338 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-08-16T13:26:51.339Z,1565962011.339 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-08-16T13:26:51.813Z,1565962011.813 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-08-16T13:26:51.815Z,1565962011.815 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-08-16T13:26:52.120Z,1565962012.120 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-08-16T13:26:52.121Z,1565962012.121 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-08-16T13:26:52.452Z,1565962012.452 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-08-16T13:26:52.454Z,1565962012.454 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-08-16T13:26:52.848Z,1565962012.848 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-08-16T13:26:52.849Z,1565962012.849 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-08-16T13:26:52.997Z,1565962012.997 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-08-16T13:26:52.998Z,1565962012.998 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-08-16T13:26:53.103Z,1565962013.103 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-08-16T13:26:53.103Z,1565962013.103 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-08-16T13:26:53.186Z,1565962013.186 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-08-16T13:26:53.313Z,1565962013.313 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-08-16T13:26:53.912Z,1565962013.912 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-08-16T13:26:54.170Z,1565962014.170 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-08-16T13:26:54.172Z,1565962014.172 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-08-16T13:26:54.378Z,1565962014.378 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-08-16T13:26:54.380Z,1565962014.380 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2019-08-16T13:26:54.383Z,1565962014.383 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2019-08-16T13:26:54.467Z,1565962014.467 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2019-08-16T13:26:54.696Z,1565962014.696 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-08-16T13:26:54.696Z,1565962014.696 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2019-08-16T13:26:54.793Z,1565962014.793 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2019-08-16T13:26:54.964Z,1565962014.964 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2019-08-16T13:26:55.177Z,1565962015.177 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2019-08-16T13:26:55.263Z,1565962015.263 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2019-08-16T13:26:55.365Z,1565962015.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2019-08-16T13:26:55.460Z,1565962015.460 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2019-08-16T13:26:55.620Z,1565962015.620 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2019-08-16T13:26:55.727Z,1565962015.727 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2019-08-16T13:26:55.825Z,1565962015.825 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-08-16T13:26:55.842Z,1565962015.842 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-08-16T13:26:55.969Z,1565962015.969 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-08-16T13:26:55.971Z,1565962015.971 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-08-16T13:26:56.122Z,1565962016.122 [BuoyancyServo] Loaded
2019-08-16T13:26:56.122Z,1565962016.122 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-08-16T13:26:56.137Z,1565962016.137 [ElevatorServo] Loaded
2019-08-16T13:26:56.137Z,1565962016.137 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-08-16T13:26:56.151Z,1565962016.151 [MassServo] Loaded
2019-08-16T13:26:56.152Z,1565962016.152 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-08-16T13:26:56.167Z,1565962016.167 [RudderServo] Loaded
2019-08-16T13:26:56.167Z,1565962016.167 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-08-16T13:26:56.181Z,1565962016.181 [ThrusterServo] Loaded
2019-08-16T13:26:56.181Z,1565962016.181 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-08-16T13:26:56.182Z,1565962016.182 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-08-16T13:26:56.184Z,1565962016.184 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-08-16T13:26:56.348Z,1565962016.348 [SBIT](DEBUG): Construct Startup Built In Test.
2019-08-16T13:26:56.377Z,1565962016.377 [SBIT] Loaded
2019-08-16T13:26:56.377Z,1565962016.377 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-08-16T13:26:56.378Z,1565962016.378 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-08-16T13:26:56.405Z,1565962016.405 [IBIT] Loaded
2019-08-16T13:26:56.405Z,1565962016.405 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-08-16T13:26:56.408Z,1565962016.408 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-08-16T13:26:56.792Z,1565962016.792 [CBIT] Loaded
2019-08-16T13:26:56.793Z,1565962016.793 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-08-16T13:26:56.793Z,1565962016.793 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-08-16T13:26:56.794Z,1565962016.794 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-08-16T13:26:57.050Z,1565962017.050 [Aanderaa_O2] Loaded
2019-08-16T13:26:57.050Z,1565962017.050 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-08-16T13:26:57.060Z,1565962017.060 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-08-16T13:26:57.065Z,1565962017.065 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-08-16T13:26:57.066Z,1565962017.066 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-08-16T13:26:57.071Z,1565962017.071 [CTD_Seabird](INFO): created writer for : depth
2019-08-16T13:26:57.072Z,1565962017.072 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-08-16T13:26:57.077Z,1565962017.077 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-08-16T13:26:57.077Z,1565962017.077 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-08-16T13:26:57.082Z,1565962017.082 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-08-16T13:26:57.083Z,1565962017.083 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-08-16T13:26:57.088Z,1565962017.088 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-08-16T13:26:57.089Z,1565962017.089 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-08-16T13:26:57.094Z,1565962017.094 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-08-16T13:26:57.095Z,1565962017.095 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-08-16T13:26:57.100Z,1565962017.100 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-08-16T13:26:57.126Z,1565962017.126 [CTD_Seabird] Loaded
2019-08-16T13:26:57.126Z,1565962017.126 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-08-16T13:26:57.127Z,1565962017.127 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066B4E0
2019-08-16T13:26:57.127Z,1565962017.127 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 888
2019-08-16T13:26:57.158Z,1565962017.158 [ESPComponent] Loaded
2019-08-16T13:26:57.158Z,1565962017.158 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-08-16T13:26:57.172Z,1565962017.172 [PAR_Licor] Loaded
2019-08-16T13:26:57.172Z,1565962017.172 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-08-16T13:26:57.219Z,1565962017.219 [WetLabsBB2FL] Loaded
2019-08-16T13:26:57.219Z,1565962017.219 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-08-16T13:26:57.221Z,1565962017.221 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069B4E0
2019-08-16T13:26:57.221Z,1565962017.221 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 889
2019-08-16T13:26:57.222Z,1565962017.222 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-08-16T13:26:57.222Z,1565962017.222 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-08-16T13:26:57.282Z,1565962017.282 [DepthRateCalculator] Loaded
2019-08-16T13:26:57.282Z,1565962017.282 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-08-16T13:26:57.287Z,1565962017.287 [PitchRateCalculator] Loaded
2019-08-16T13:26:57.288Z,1565962017.288 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-08-16T13:26:57.303Z,1565962017.303 [SpeedCalculator] Loaded
2019-08-16T13:26:57.304Z,1565962017.304 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-08-16T13:26:57.324Z,1565962017.324 [TempGradientCalculator] Loaded
2019-08-16T13:26:57.325Z,1565962017.325 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-08-16T13:26:57.330Z,1565962017.330 [YawRateCalculator] Loaded
2019-08-16T13:26:57.331Z,1565962017.331 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-08-16T13:26:57.363Z,1565962017.363 [ElevatorOffsetCalculator] Loaded
2019-08-16T13:26:57.363Z,1565962017.363 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-08-16T13:26:57.364Z,1565962017.364 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-08-16T13:26:57.364Z,1565962017.364 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-08-16T13:26:57.413Z,1565962017.413 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-08-16T13:26:57.413Z,1565962017.413 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-08-16T13:26:57.533Z,1565962017.533 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-08-16T13:26:57.533Z,1565962017.533 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-08-16T13:26:57.554Z,1565962017.554 [NavChart] Loaded
2019-08-16T13:26:57.554Z,1565962017.554 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-08-16T13:26:57.558Z,1565962017.558 [UniversalFixResidualReporter] Loaded
2019-08-16T13:26:57.559Z,1565962017.559 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-08-16T13:26:57.559Z,1565962017.559 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-08-16T13:26:57.561Z,1565962017.561 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-08-16T13:26:58.243Z,1565962018.243 [AHRS_M2] Loaded
2019-08-16T13:26:58.243Z,1565962018.243 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-08-16T13:26:58.387Z,1565962018.387 [DataOverHttps] Loaded
2019-08-16T13:26:58.387Z,1565962018.387 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-08-16T13:26:58.388Z,1565962018.388 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409744E0
2019-08-16T13:26:58.388Z,1565962018.388 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 890
2019-08-16T13:26:58.401Z,1565962018.401 [Depth_Keller] Loaded
2019-08-16T13:26:58.402Z,1565962018.402 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-08-16T13:26:58.406Z,1565962018.406 [DropWeight] Loaded
2019-08-16T13:26:58.407Z,1565962018.407 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-08-16T13:26:58.496Z,1565962018.496 [NAL9602] Loaded
2019-08-16T13:26:58.497Z,1565962018.497 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-08-16T13:26:58.502Z,1565962018.502 [Onboard] Loaded
2019-08-16T13:26:58.502Z,1565962018.502 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-08-16T13:26:58.505Z,1565962018.505 [Radio_Surface] Loaded
2019-08-16T13:26:58.506Z,1565962018.506 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-08-16T13:26:58.507Z,1565962018.507 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A44E0
2019-08-16T13:26:58.507Z,1565962018.507 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 891
2019-08-16T13:26:58.633Z,1565962018.633 [DAT] Loaded
2019-08-16T13:26:58.633Z,1565962018.633 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-08-16T13:27:00.139Z,1565962020.139 [BPC1] Loaded
2019-08-16T13:27:00.139Z,1565962020.139 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-08-16T13:27:00.139Z,1565962020.139 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-08-16T13:27:00.140Z,1565962020.140 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-08-16T13:27:00.250Z,1565962020.250 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-08-16T13:27:00.251Z,1565962020.251 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-08-16T13:27:00.339Z,1565962020.339 [VerticalControl](DEBUG): Construct VerticalControl.
2019-08-16T13:27:00.422Z,1565962020.422 [VerticalControl] Loaded
2019-08-16T13:27:00.423Z,1565962020.423 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-08-16T13:27:00.423Z,1565962020.423 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-08-16T13:27:00.480Z,1565962020.480 [HorizontalControl] Loaded
2019-08-16T13:27:00.480Z,1565962020.480 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-08-16T13:27:00.481Z,1565962020.481 [SpeedControl](DEBUG): Construct SpeedControl.
2019-08-16T13:27:00.483Z,1565962020.483 [SpeedControl] Loaded
2019-08-16T13:27:00.483Z,1565962020.483 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-08-16T13:27:00.484Z,1565962020.484 [LoopControl](DEBUG): Construct LoopControl.
2019-08-16T13:27:00.484Z,1565962020.484 [LoopControl] Loaded
2019-08-16T13:27:00.485Z,1565962020.485 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-08-16T13:27:00.485Z,1565962020.485 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-08-16T13:27:00.486Z,1565962020.486 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-08-16T13:27:00.509Z,1565962020.509 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-08-16T13:27:00.510Z,1565962020.510 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-08-16T13:27:00.846Z,1565962020.846 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-08-16T13:27:00.850Z,1565962020.850 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-08-16T13:27:00.851Z,1565962020.851 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-08-16T13:27:00.858Z,1565962020.858 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-08-16T13:27:00.859Z,1565962020.859 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADF4E0
2019-08-16T13:27:00.859Z,1565962020.859 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 892
2019-08-16T13:27:00.863Z,1565962020.863 [Supervisor](INFO): Main Thread ID is 802
2019-08-16T13:27:00.864Z,1565962020.864 [Supervisor](DEBUG): Running supervisor.
2019-08-16T13:27:00.864Z,1565962020.864 [CommandLine ThreadHandler](INFO): Handler Thread ID is 893
2019-08-16T13:27:00.867Z,1565962020.867 [controlThread ThreadHandler](INFO): Handler Thread ID is 894
2019-08-16T13:27:00.867Z,1565962020.867 [controlThread](DEBUG): Initializing ControlThread
2019-08-16T13:27:00.869Z,1565962020.869 [SBIT](INFO): Initialize SBIT Component.
2019-08-16T13:27:00.869Z,1565962020.869 [SBIT](IMPORTANT): git: 2019-08-13
2019-08-16T13:27:00.869Z,1565962020.869 [SBIT](INFO): git hash: 6b080875362fb71081cecd990260e30fa66d1cc0
2019-08-16T13:27:00.870Z,1565962020.870 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-08-16T13:27:00.871Z,1565962020.871 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-08-16T13:27:00.872Z,1565962020.872 [SBIT](INFO): Beginning SBIT in 88.000000 seconds.
2019-08-16T13:27:00.873Z,1565962020.873 [IBIT](INFO): Initialize IBIT Component.
2019-08-16T13:27:00.873Z,1565962020.873 [CBIT](DEBUG): Initialize CBIT Component.
2019-08-16T13:27:00.874Z,1565962020.874 [logger ThreadHandler](INFO): Handler Thread ID is 895
2019-08-16T13:27:00.884Z,1565962020.884 [CBIT](DEBUG): Initialized mux pins.
2019-08-16T13:27:00.884Z,1565962020.884 [CBIT](DEBUG): Initializing the watchdog timer.
2019-08-16T13:27:00.893Z,1565962020.893 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 896
2019-08-16T13:27:00.893Z,1565962020.893 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-08-16T13:27:00.897Z,1565962020.897 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-08-16T13:27:00.898Z,1565962020.898 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 898
2019-08-16T13:27:00.899Z,1565962020.899 [WetLabsBB2FL](INFO): Powering down
2019-08-16T13:27:00.909Z,1565962020.909 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-08-16T13:27:00.909Z,1565962020.909 [CBIT](DEBUG): Initializing heartbeat.
2019-08-16T13:27:00.929Z,1565962020.929 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 899
2019-08-16T13:27:00.930Z,1565962020.930 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-08-16T13:27:00.941Z,1565962020.941 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 900
2019-08-16T13:27:00.957Z,1565962020.957 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 901
2019-08-16T13:27:00.966Z,1565962020.966 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-08-16T13:27:00.966Z,1565962020.966 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-08-16T13:27:00.966Z,1565962020.966 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-08-16T13:27:00.966Z,1565962020.966 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-08-16T13:27:00.967Z,1565962020.967 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-08-16T13:27:00.967Z,1565962020.967 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-08-16T13:27:00.967Z,1565962020.967 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-08-16T13:27:00.967Z,1565962020.967 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-08-16T13:27:00.967Z,1565962020.967 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-08-16T13:27:00.967Z,1565962020.967 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-08-16T13:27:00.968Z,1565962020.968 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-08-16T13:27:00.968Z,1565962020.968 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-08-16T13:27:00.968Z,1565962020.968 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-08-16T13:27:00.968Z,1565962020.968 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-08-16T13:27:00.969Z,1565962020.969 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-08-16T13:27:00.969Z,1565962020.969 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-08-16T13:27:00.980Z,1565962020.980 [CBIT](DEBUG): Deactivating GF circuits.
2019-08-16T13:27:00.980Z,1565962020.980 [CBIT](DEBUG): Deactivating emergency mode.
2019-08-16T13:27:01.016Z,1565962021.016 [CBIT](DEBUG): Backplane powered.
2019-08-16T13:27:01.021Z,1565962021.021 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-08-16T13:27:01.021Z,1565962021.021 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-08-16T13:27:01.021Z,1565962021.021 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-08-16T13:27:01.022Z,1565962021.022 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-08-16T13:27:01.022Z,1565962021.022 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-08-16T13:27:01.023Z,1565962021.023 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-08-16T13:27:01.024Z,1565962021.024 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-08-16T13:27:01.024Z,1565962021.024 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-08-16T13:27:01.039Z,1565962021.039 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-08-16T13:27:01.049Z,1565962021.049 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-08-16T13:27:01.050Z,1565962021.050 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-08-16T13:27:01.050Z,1565962021.050 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-08-16T13:27:01.051Z,1565962021.051 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-08-16T13:27:01.090Z,1565962021.090 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-16T13:27:01.121Z,1565962021.121 [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-08-16T13:27:01.122Z,1565962021.122 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-08-16T13:27:01.202Z,1565962021.202 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-08-16T13:27:01.203Z,1565962021.203 [Default:A.Wait](DEBUG): Construct Wait.
2019-08-16T13:27:01.205Z,1565962021.205 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-16T13:27:01.228Z,1565962021.228 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-08-16T13:27:01.255Z,1565962021.255 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-08-16T13:27:01.272Z,1565962021.272 [Default:E.Execute](DEBUG): Construct Execute.
2019-08-16T13:27:01.275Z,1565962021.275 [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-08-16T13:27:01.280Z,1565962021.280 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,BPC1,PAR_Licor,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-08-16T13:27:01.317Z,1565962021.317 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-08-16T13:27:01.344Z,1565962021.344 [Radio_Surface](INFO): Powering up
2019-08-16T13:27:01.465Z,1565962021.465 [Depth_Keller](ERROR): Pressure reading out of range: 1895.684326 decibar
2019-08-16T13:27:01.487Z,1565962021.487 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-08-16T13:27:01.487Z,1565962021.487 [DAT](INFO): Powering up
2019-08-16T13:27:01.487Z,1565962021.487 [DAT](DEBUG): Initializing DAT.
2019-08-16T13:27:01.548Z,1565962021.548 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-08-16T13:27:01.565Z,1565962021.565 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-08-16T13:27:01.642Z,1565962021.642 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-16T13:27:01.653Z,1565962021.653 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-16T13:27:01.654Z,1565962021.654 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-08-16T13:27:01.665Z,1565962021.665 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-08-16T13:27:01.666Z,1565962021.666 [MassServo](DEBUG): Initializing EZServoServo.
2019-08-16T13:27:01.677Z,1565962021.677 [MassServo](DEBUG): Initializing MassServo.
2019-08-16T13:27:01.678Z,1565962021.678 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-16T13:27:01.685Z,1565962021.685 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-16T13:27:01.686Z,1565962021.686 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-16T13:27:01.693Z,1565962021.693 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-16T13:27:04.652Z,1565962024.652 [Aanderaa_O2](INFO): Powering down
2019-08-16T13:27:16.676Z,1565962036.676 [DAT](INFO): setting local address to 3
2019-08-16T13:27:17.081Z,1565962037.081 [DAT](INFO): set local address to 3
2019-08-16T13:27:28.786Z,1565962048.786 [NAL9602](INFO): Powering up NAL9602
2019-08-16T13:27:39.694Z,1565962059.694 [NAL9602](INFO): NAL9602 initialized
2019-08-16T13:27:40.515Z,1565962060.515 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:27:58.683Z,1565962078.683 [NAL9602](INFO): SBD MO Status=0, MOMSN=31151, MT Status=0, MTMSN=0
2019-08-16T13:27:58.683Z,1565962078.683 [NAL9602](INFO): No messages in MT queue
2019-08-16T13:27:59.500Z,1565962079.500 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:28:02.736Z,1565962082.736 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:28:03.128Z,1565962083.128 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,132802.00,A,4149.69683,N,08324.71013,W,0.700,67.58,160819,,,A*49
2019-08-16T13:28:03.131Z,1565962083.131 [NAL9602](INFO): GPS fix at 20190816T132802: (41.828280, -83.411835)
2019-08-16T13:28:29.421Z,1565962109.421 [SBIT](IMPORTANT): Beginning Startup BIT
2019-08-16T13:28:29.425Z,1565962109.425 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-16T13:28:35.547Z,1565962115.547 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T13:28:40.469Z,1565962120.469 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.007902
CHAN A1 (24V): -0.018873
CHAN A2 (12V): -0.003236
CHAN A3 (5V): -0.001866
CHAN B0 (3.3V): -0.001564
CHAN B1 (3.15aV): -0.001253
CHAN B2 (3.15bV): -0.001241
CHAN B3 (GND): 0.000067
OPEN: 0.006750
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-16T13:29:22.684Z,1565962162.684 [SBIT](IMPORTANT): SBIT PASSED
2019-08-16T13:29:22.757Z,1565962162.757 [CommandLine](IMPORTANT): got command configSet list
2019-08-16T13:29:22.758Z,1565962162.758 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-16T13:29:22.758Z,1565962162.758 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): BuoyancyServo.fastPumpDepth=5 meter;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): CBIT.stopDepth=10 meter;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): CTD_Seabird.minSalinityBound=0.01 practical_salinity_unit;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=1 bool;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): Express none CTD_Seabird.bin_median_sea_water_salinity;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): Express linearApproximation CTD_Seabird.sea_water_electrical_conductivity 0.001000 siemens_per_meter;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_oxygen_in_sea_water 750.000000 microgram_per_liter;

2019-08-16T13:29:22.759Z,1565962162.759 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=220 cubic_centimeter;

2019-08-16T13:29:22.760Z,1565962162.760 [CommandLine](IMPORTANT): VerticalControl.elevDeadband=0.1 degree;

2019-08-16T13:29:22.760Z,1565962162.760 [CommandLine](IMPORTANT): VerticalControl.kiDepthBuoy=0.3 reciprocal_second;

2019-08-16T13:29:22.760Z,1565962162.760 [CommandLine](IMPORTANT): VerticalControl.massDefault=17 millimeter;

2019-08-16T13:29:23.092Z,1565962163.092 [MissionManager](IMPORTANT): Started mission Startup
2019-08-16T13:29:23.092Z,1565962163.092 [Startup] Running Loop=1
2019-08-16T13:29:23.092Z,1565962163.092 [Startup](DEBUG): Aggregate::initialize Startup
2019-08-16T13:29:23.092Z,1565962163.092 [Startup:A.GoToSurface] Running Loop=1
2019-08-16T13:29:23.092Z,1565962163.092 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-16T13:29:23.093Z,1565962163.093 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-16T13:29:23.093Z,1565962163.093 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-16T13:29:23.094Z,1565962163.094 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-16T13:29:23.094Z,1565962163.094 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-16T13:29:23.095Z,1565962163.095 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-16T13:29:23.096Z,1565962163.096 [Startup:StartupSatComms] Running Loop=1
2019-08-16T13:29:23.096Z,1565962163.096 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-08-16T13:29:23.096Z,1565962163.096 [Startup:StartupSatComms:A] Running Loop=1
2019-08-16T13:29:23.501Z,1565962163.501 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-08-16T13:29:24.692Z,1565962164.692 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:29:25.085Z,1565962165.085 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,132925.00,A,4149.69594,N,08324.71404,W,0.039,72.70,160819,,,D*4C
2019-08-16T13:29:25.087Z,1565962165.087 [NAL9602](INFO): GPS fix at 20190816T132925: (41.828266, -83.411901)
2019-08-16T13:29:25.110Z,1565962165.110 [Startup:StartupSatComms:A] Stopped
2019-08-16T13:29:25.110Z,1565962165.110 [Startup:StartupSatComms:B] Running Loop=1
2019-08-16T13:29:25.532Z,1565962165.532 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-16T13:29:51.115Z,1565962191.115 [NAL9602](INFO): SBD MO Status=2, MOMSN=31152, MT Status=2, MTMSN=0
2019-08-16T13:29:51.115Z,1565962191.115 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T13:30:07.861Z,1565962207.861 [NAL9602](INFO): SBD MO Status=1, MOMSN=31152, MT Status=0, MTMSN=0
2019-08-16T13:30:07.909Z,1565962207.909 [NAL9602](INFO): Sent 25 bytes from file Logs/20190816T124149/Courier0025.lzma
2019-08-16T13:30:07.909Z,1565962207.909 [NAL9602](INFO): Packets left to send: 0
2019-08-16T13:30:23.797Z,1565962223.797 [NAL9602](INFO): SBD MO Status=2, MOMSN=31153, MT Status=2, MTMSN=0
2019-08-16T13:30:23.797Z,1565962223.797 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T13:30:25.467Z,1565962225.467 [Startup:StartupSatComms:B](INFO): Timed out from 2019-08-16T13:29:25.1Z
2019-08-16T13:30:25.467Z,1565962225.467 [Startup:StartupSatComms:B] Stopped
2019-08-16T13:30:25.468Z,1565962225.468 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-08-16T13:30:25.468Z,1565962225.468 [Startup:StartupSatComms] Stopped
2019-08-16T13:30:25.468Z,1565962225.468 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-08-16T13:30:25.469Z,1565962225.469 [Startup](INFO): Completed Startup
2019-08-16T13:30:25.469Z,1565962225.469 [MissionManager](INFO): Startup is completed.
2019-08-16T13:30:25.469Z,1565962225.469 [MissionManager](INFO): Uninitializing Mission Startup
2019-08-16T13:30:25.469Z,1565962225.469 [Startup] Stopped
2019-08-16T13:30:25.469Z,1565962225.469 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-08-16T13:30:25.469Z,1565962225.469 [Startup:A.GoToSurface] Stopped
2019-08-16T13:30:25.469Z,1565962225.469 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-16T13:30:25.858Z,1565962225.858 [MissionManager](IMPORTANT): Started mission Default
2019-08-16T13:30:25.858Z,1565962225.858 [Default] Running Loop=1
2019-08-16T13:30:25.859Z,1565962225.859 [Default](DEBUG): Aggregate::initialize Default
2019-08-16T13:30:25.859Z,1565962225.859 [Default:B.GoToSurface] Running Loop=1
2019-08-16T13:30:25.859Z,1565962225.859 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-16T13:30:25.859Z,1565962225.859 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-16T13:30:25.859Z,1565962225.859 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-16T13:30:25.860Z,1565962225.860 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-16T13:30:25.860Z,1565962225.860 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-16T13:30:25.861Z,1565962225.861 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-16T13:30:25.861Z,1565962225.861 [Default:A.Wait] Running Loop=1
2019-08-16T13:30:25.861Z,1565962225.861 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-16T13:30:38.869Z,1565962238.869 [Default:A.Wait](INFO): Done Waiting.
2019-08-16T13:30:38.869Z,1565962238.869 [Default:A.Wait] Stopped
2019-08-16T13:30:38.869Z,1565962238.869 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T13:30:39.203Z,1565962239.203 [Default:CheckIn] Running Loop=1
2019-08-16T13:30:39.204Z,1565962239.204 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T13:30:39.204Z,1565962239.204 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T13:30:39.624Z,1565962239.624 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-16T13:30:39.722Z,1565962239.722 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004483
2019-08-16T13:30:40.796Z,1565962240.796 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:30:41.196Z,1565962241.196 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133041.00,A,4149.69668,N,08324.71422,W,0.000,72.70,160819,,,A*4D
2019-08-16T13:30:41.198Z,1565962241.198 [NAL9602](INFO): GPS fix at 20190816T133041: (41.828278, -83.411904)
2019-08-16T13:30:41.267Z,1565962241.267 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T13:30:41.267Z,1565962241.267 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T13:30:41.648Z,1565962241.648 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-16T13:30:50.100Z,1565962250.100 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190816T132649/Courier0000.lzma
2019-08-16T13:30:50.902Z,1565962250.902 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0000.lzma.bak
2019-08-16T13:30:50.902Z,1565962250.902 [DataOverHttps](INFO): SBD MOMSN=11581859
2019-08-16T13:31:02.600Z,1565962262.600 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190816T132649/Courier0004.lzma
2019-08-16T13:31:03.406Z,1565962263.406 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0004.lzma.bak
2019-08-16T13:31:03.406Z,1565962263.406 [DataOverHttps](INFO): SBD MOMSN=11581863
2019-08-16T13:31:13.891Z,1565962273.891 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T13:31:14.965Z,1565962274.965 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190816T124149/Express0023.lzma
2019-08-16T13:31:15.766Z,1565962275.766 [DataOverHttps](INFO): Moved sent file to Logs/20190816T124149/Express0023.lzma.bak
2019-08-16T13:31:15.766Z,1565962275.766 [DataOverHttps](INFO): SBD MOMSN=11581866
2019-08-16T13:31:27.093Z,1565962287.093 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20190816T124149/Express0026.lzma
2019-08-16T13:31:27.898Z,1565962287.898 [DataOverHttps](INFO): Moved sent file to Logs/20190816T124149/Express0026.lzma.bak
2019-08-16T13:31:27.898Z,1565962287.898 [DataOverHttps](INFO): SBD MOMSN=11581869
2019-08-16T13:31:41.919Z,1565962301.919 [DataOverHttps](INFO): Sending 1054 bytes from file Logs/20190816T132649/Express0001.lzma
2019-08-16T13:31:42.722Z,1565962302.722 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0001.lzma.bak
2019-08-16T13:31:42.722Z,1565962302.722 [DataOverHttps](INFO): SBD MOMSN=11581873
2019-08-16T13:31:53.976Z,1565962313.976 [DataOverHttps](INFO): Sending 94 bytes from file Logs/20190816T132649/Express0005.lzma
2019-08-16T13:31:54.782Z,1565962314.782 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0005.lzma.bak
2019-08-16T13:31:54.782Z,1565962314.782 [DataOverHttps](INFO): SBD MOMSN=11581900
2019-08-16T13:31:55.538Z,1565962315.538 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T13:31:55.538Z,1565962315.538 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T13:31:55.538Z,1565962315.538 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T13:32:31.325Z,1565962351.325 [DataOverHttps](IMPORTANT): SBD MTMSN=20190816T133231
2019-08-16T13:32:36.260Z,1565962356.260 [DataOverHttps](INFO): Received command:Ibit
2019-08-16T13:32:36.326Z,1565962356.326 [CommandLine](IMPORTANT): got command ibit
2019-08-16T13:32:36.363Z,1565962356.363 [IBIT](IMPORTANT): Beginning Initiated BIT
2019-08-16T13:32:36.363Z,1565962356.363 [IBIT](IMPORTANT): Beginning control surface checks.
2019-08-16T13:32:36.366Z,1565962356.366 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-16T13:32:37.532Z,1565962357.532 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:32:37.935Z,1565962357.935 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133237.00,A,4149.69668,N,08324.71498,W,0.058,72.70,160819,,,D*47
2019-08-16T13:32:37.937Z,1565962357.937 [NAL9602](INFO): GPS fix at 20190816T133237: (41.828278, -83.411916)
2019-08-16T13:32:47.433Z,1565962367.433 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.007079
CHAN A1 (24V): -0.019308
CHAN A2 (12V): -0.003540
CHAN A3 (5V): -0.002230
CHAN B0 (3.3V): -0.000854
CHAN B1 (3.15aV): -0.001431
CHAN B2 (3.15bV): -0.000779
CHAN B3 (GND): -0.000489
OPEN: 0.006674
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-16T13:32:55.084Z,1565962375.084 [NAL9602](INFO): SBD MO Status=1, MOMSN=31153, MT Status=0, MTMSN=0
2019-08-16T13:32:55.084Z,1565962375.084 [NAL9602](INFO): No messages in MT queue
2019-08-16T13:32:55.896Z,1565962375.896 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:32:56.295Z,1565962376.295 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133256.00,A,4149.69633,N,08324.71503,W,0.097,72.70,160819,,,D*4E
2019-08-16T13:32:56.297Z,1565962376.297 [NAL9602](INFO): GPS fix at 20190816T133256: (41.828272, -83.411917)
2019-08-16T13:32:59.137Z,1565962379.137 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:32:59.527Z,1565962379.527 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133259.00,A,4149.69629,N,08324.71513,W,0.058,72.70,160819,,,D*48
2019-08-16T13:32:59.529Z,1565962379.529 [NAL9602](INFO): GPS fix at 20190816T133259: (41.828271, -83.411919)
2019-08-16T13:33:02.364Z,1565962382.364 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:33:02.755Z,1565962382.755 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133302.00,A,4149.69624,N,08324.71527,W,0.019,72.70,160819,,,D*48
2019-08-16T13:33:02.759Z,1565962382.759 [NAL9602](INFO): GPS fix at 20190816T133302: (41.828271, -83.411921)
2019-08-16T13:33:05.188Z,1565962385.188 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:33:05.597Z,1565962385.597 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133305.00,A,4149.69613,N,08324.71530,W,0.039,72.70,160819,,,D*4F
2019-08-16T13:33:05.599Z,1565962385.599 [NAL9602](INFO): GPS fix at 20190816T133305: (41.828269, -83.411922)
2019-08-16T13:33:08.492Z,1565962388.492 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:33:08.813Z,1565962388.813 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133308.00,A,4149.69602,N,08324.71520,W,0.039,72.70,160819,,,D*43
2019-08-16T13:33:08.815Z,1565962388.815 [NAL9602](INFO): GPS fix at 20190816T133308: (41.828267, -83.411920)
2019-08-16T13:33:11.248Z,1565962391.248 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:33:11.641Z,1565962391.641 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133311.00,A,4149.69598,N,08324.71509,W,0.039,72.70,160819,,,D*40
2019-08-16T13:33:11.643Z,1565962391.643 [NAL9602](INFO): GPS fix at 20190816T133311: (41.828266, -83.411918)
2019-08-16T13:33:14.076Z,1565962394.076 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:33:14.479Z,1565962394.479 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133314.00,A,4149.69591,N,08324.71515,W,0.039,72.70,160819,,,D*41
2019-08-16T13:33:14.481Z,1565962394.481 [NAL9602](INFO): GPS fix at 20190816T133314: (41.828265, -83.411919)
2019-08-16T13:33:17.312Z,1565962397.312 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:33:17.703Z,1565962397.703 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133317.00,A,4149.69585,N,08324.71523,W,0.097,72.70,160819,,,D*46
2019-08-16T13:33:17.708Z,1565962397.708 [NAL9602](INFO): GPS fix at 20190816T133317: (41.828264, -83.411920)
2019-08-16T13:33:20.136Z,1565962400.136 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:33:20.529Z,1565962400.529 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133320.00,A,4149.69594,N,08324.71548,W,0.019,72.70,160819,,,D*49
2019-08-16T13:33:20.531Z,1565962400.531 [NAL9602](INFO): GPS fix at 20190816T133320: (41.828266, -83.411925)
2019-08-16T13:33:22.609Z,1565962402.609 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 4
Latitude: 41.828266 Longitude: -83.411926
2019-08-16T13:33:23.029Z,1565962403.029 [IBIT](FAULT): Warning: Battery Data not active. Expected only when running primaries. Threshold checking not active.
2019-08-16T13:33:23.394Z,1565962403.394 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2019-08-16T13:33:23.395Z,1565962403.395 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2019-08-16T13:33:23.395Z,1565962403.395 [IBIT](IMPORTANT): Pressure:9.801734 PSI
2019-08-16T13:33:23.395Z,1565962403.395 [IBIT](IMPORTANT): Humidity:23.769991 %
2019-08-16T13:33:23.877Z,1565962403.877 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2019-08-16T13:33:23.878Z,1565962403.878 [IBIT](IMPORTANT): buoyancyNeutral: 220.000000 cc
2019-08-16T13:33:23.878Z,1565962403.878 [IBIT](IMPORTANT): massDefault: 1.700000 cm
2019-08-16T13:33:23.878Z,1565962403.878 [IBIT](IMPORTANT): stopDepth: 10.000000 m
2019-08-16T13:33:23.878Z,1565962403.878 [IBIT](IMPORTANT): abortDepth: 50.000000 m
2019-08-16T13:33:23.878Z,1565962403.878 [IBIT](IMPORTANT): IBIT PASSED
2019-08-16T13:33:34.703Z,1565962414.703 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-08-16T13:33:34.708Z,1565962414.708 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-08-16T13:33:34.709Z,1565962414.709 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-08-16T13:33:34.712Z,1565962414.712 [BPC1](INFO): Received data from all battery sticks.
2019-08-16T13:33:53.251Z,1565962433.251 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T13:36:56.298Z,1565962616.298 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T13:36:56.298Z,1565962616.298 [Default:CheckIn:C.Wait] Stopped
2019-08-16T13:36:56.298Z,1565962616.298 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T13:36:56.298Z,1565962616.298 [Default:CheckIn:D] Running Loop=1
2019-08-16T13:36:56.708Z,1565962616.708 [Default:CheckIn:D] Stopped
2019-08-16T13:36:56.709Z,1565962616.709 [Default:CheckIn:E] Running Loop=1
2019-08-16T13:36:57.113Z,1565962617.113 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.514167 min 
2019-08-16T13:36:57.113Z,1565962617.113 [Default:CheckIn:E] Stopped
2019-08-16T13:36:57.113Z,1565962617.113 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T13:36:57.113Z,1565962617.113 [Default:CheckIn] Stopped
2019-08-16T13:36:57.113Z,1565962617.113 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T13:36:57.113Z,1565962617.113 [Default:CheckIn](INFO): Running loop #2
2019-08-16T13:36:57.113Z,1565962617.113 [Default:CheckIn] Running Loop=2
2019-08-16T13:36:57.114Z,1565962617.114 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T13:36:57.114Z,1565962617.114 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T13:36:58.716Z,1565962618.716 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:36:59.113Z,1565962619.113 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,133658.00,A,4149.69573,N,08324.71698,W,0.117,72.70,160819,,,D*4B
2019-08-16T13:36:59.115Z,1565962619.115 [NAL9602](INFO): GPS fix at 20190816T133658: (41.828262, -83.411950)
2019-08-16T13:36:59.137Z,1565962619.137 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T13:36:59.137Z,1565962619.137 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T13:37:04.740Z,1565962624.740 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190816T132649/Courier0007.lzma
2019-08-16T13:37:05.546Z,1565962625.546 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0007.lzma.bak
2019-08-16T13:37:05.546Z,1565962625.546 [DataOverHttps](INFO): SBD MOMSN=11581916
2019-08-16T13:37:16.812Z,1565962636.812 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190816T132649/Courier0010.lzma
2019-08-16T13:37:17.618Z,1565962637.618 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0010.lzma.bak
2019-08-16T13:37:17.618Z,1565962637.618 [DataOverHttps](INFO): SBD MOMSN=11581919
2019-08-16T13:37:18.503Z,1565962638.503 [NAL9602](INFO): SBD MO Status=1, MOMSN=31154, MT Status=0, MTMSN=0
2019-08-16T13:37:18.503Z,1565962638.503 [NAL9602](INFO): No messages in MT queue
2019-08-16T13:37:28.869Z,1565962648.869 [DataOverHttps](INFO): Sending 752 bytes from file Logs/20190816T132649/Express0008.lzma
2019-08-16T13:37:29.674Z,1565962649.674 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0008.lzma.bak
2019-08-16T13:37:29.674Z,1565962649.674 [DataOverHttps](INFO): SBD MOMSN=11581921
2019-08-16T13:37:40.844Z,1565962660.844 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190816T132649/Express0009.lzma
2019-08-16T13:37:41.650Z,1565962661.650 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0009.lzma.bak
2019-08-16T13:37:41.650Z,1565962661.650 [DataOverHttps](INFO): SBD MOMSN=11581942
2019-08-16T13:37:49.199Z,1565962669.199 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T13:37:53.152Z,1565962673.152 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190816T132649/Express0011.lzma
2019-08-16T13:37:54.109Z,1565962674.109 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0011.lzma.bak
2019-08-16T13:37:54.109Z,1565962674.109 [DataOverHttps](INFO): SBD MOMSN=11581944
2019-08-16T13:37:54.915Z,1565962674.915 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T13:37:54.915Z,1565962674.915 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T13:37:54.915Z,1565962674.915 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T13:42:55.473Z,1565962975.473 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T13:42:55.473Z,1565962975.473 [Default:CheckIn:C.Wait] Stopped
2019-08-16T13:42:55.473Z,1565962975.473 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T13:42:55.473Z,1565962975.473 [Default:CheckIn:D] Running Loop=1
2019-08-16T13:42:55.858Z,1565962975.858 [Default:CheckIn:D] Stopped
2019-08-16T13:42:55.858Z,1565962975.858 [Default:CheckIn:E] Running Loop=1
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.499990 min 
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn:E] Stopped
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn] Stopped
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn](INFO): Running loop #3
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn] Running Loop=3
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T13:42:56.262Z,1565962976.262 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T13:42:57.876Z,1565962977.876 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:42:58.262Z,1565962978.262 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,134257.00,A,4149.69629,N,08324.71380,W,0.039,72.70,160819,,,D*4A
2019-08-16T13:42:58.264Z,1565962978.264 [NAL9602](INFO): GPS fix at 20190816T134257: (41.828271, -83.411897)
2019-08-16T13:42:58.311Z,1565962978.311 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T13:42:58.311Z,1565962978.311 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T13:43:03.704Z,1565962983.704 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190816T132649/Courier0012.lzma
2019-08-16T13:43:04.510Z,1565962984.510 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0012.lzma.bak
2019-08-16T13:43:04.510Z,1565962984.510 [DataOverHttps](INFO): SBD MOMSN=11581948
2019-08-16T13:43:15.688Z,1565962995.688 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190816T132649/Express0014.lzma
2019-08-16T13:43:16.043Z,1565962996.043 [NAL9602](INFO): SBD MO Status=1, MOMSN=31155, MT Status=0, MTMSN=0
2019-08-16T13:43:16.043Z,1565962996.043 [NAL9602](INFO): No messages in MT queue
2019-08-16T13:43:16.494Z,1565962996.494 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0014.lzma.bak
2019-08-16T13:43:16.494Z,1565962996.494 [DataOverHttps](INFO): SBD MOMSN=11581951
2019-08-16T13:43:17.290Z,1565962997.290 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T13:43:17.290Z,1565962997.290 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T13:43:17.290Z,1565962997.290 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T13:43:46.745Z,1565963026.745 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T13:48:17.853Z,1565963297.853 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T13:48:17.853Z,1565963297.853 [Default:CheckIn:C.Wait] Stopped
2019-08-16T13:48:17.853Z,1565963297.853 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T13:48:17.853Z,1565963297.853 [Default:CheckIn:D] Running Loop=1
2019-08-16T13:48:18.255Z,1565963298.255 [Default:CheckIn:D] Stopped
2019-08-16T13:48:18.255Z,1565963298.255 [Default:CheckIn:E] Running Loop=1
2019-08-16T13:48:18.667Z,1565963298.667 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.873269 min 
2019-08-16T13:48:18.667Z,1565963298.667 [Default:CheckIn:E] Stopped
2019-08-16T13:48:18.668Z,1565963298.668 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T13:48:18.668Z,1565963298.668 [Default:CheckIn] Stopped
2019-08-16T13:48:18.668Z,1565963298.668 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T13:48:18.668Z,1565963298.668 [Default:CheckIn](INFO): Running loop #4
2019-08-16T13:48:18.668Z,1565963298.668 [Default:CheckIn] Running Loop=4
2019-08-16T13:48:18.668Z,1565963298.668 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T13:48:18.668Z,1565963298.668 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T13:48:20.274Z,1565963300.274 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:48:20.655Z,1565963300.655 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,134818.00,A,4149.69513,N,08324.71387,W,0.078,72.70,160819,,,D*43
2019-08-16T13:48:20.657Z,1565963300.657 [NAL9602](INFO): GPS fix at 20190816T134818: (41.828252, -83.411898)
2019-08-16T13:48:20.691Z,1565963300.691 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T13:48:20.691Z,1565963300.691 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T13:48:23.736Z,1565963303.736 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190816T132649/Courier0016.lzma
2019-08-16T13:48:24.542Z,1565963304.542 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0016.lzma.bak
2019-08-16T13:48:24.542Z,1565963304.542 [DataOverHttps](INFO): SBD MOMSN=11581964
2019-08-16T13:48:35.792Z,1565963315.792 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190816T132649/Express0017.lzma
2019-08-16T13:48:36.598Z,1565963316.598 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0017.lzma.bak
2019-08-16T13:48:36.598Z,1565963316.598 [DataOverHttps](INFO): SBD MOMSN=11581971
2019-08-16T13:48:37.747Z,1565963317.747 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T13:48:37.747Z,1565963317.747 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T13:48:37.747Z,1565963317.747 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T13:48:42.967Z,1565963322.967 [NAL9602](INFO): SBD MO Status=2, MOMSN=31156, MT Status=2, MTMSN=0
2019-08-16T13:48:42.967Z,1565963322.967 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T13:48:59.951Z,1565963339.951 [NAL9602](INFO): SBD MO Status=2, MOMSN=31156, MT Status=2, MTMSN=0
2019-08-16T13:48:59.951Z,1565963339.951 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T13:49:18.131Z,1565963358.131 [NAL9602](INFO): SBD MO Status=2, MOMSN=31156, MT Status=2, MTMSN=0
2019-08-16T13:49:18.131Z,1565963358.131 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T13:49:56.912Z,1565963396.912 [NAL9602](INFO): SBD MO Status=2, MOMSN=31156, MT Status=2, MTMSN=0
2019-08-16T13:49:56.913Z,1565963396.913 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T13:50:48.671Z,1565963448.671 [NAL9602](INFO): SBD MO Status=1, MOMSN=31156, MT Status=0, MTMSN=0
2019-08-16T13:50:48.671Z,1565963448.671 [NAL9602](INFO): No messages in MT queue
2019-08-16T13:51:19.365Z,1565963479.365 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T13:53:38.392Z,1565963618.392 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T13:53:38.392Z,1565963618.392 [Default:CheckIn:C.Wait] Stopped
2019-08-16T13:53:38.393Z,1565963618.393 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T13:53:38.393Z,1565963618.393 [Default:CheckIn:D] Running Loop=1
2019-08-16T13:53:38.779Z,1565963618.779 [Default:CheckIn:D] Stopped
2019-08-16T13:53:38.779Z,1565963618.779 [Default:CheckIn:E] Running Loop=1
2019-08-16T13:53:39.179Z,1565963619.179 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.215338 min 
2019-08-16T13:53:39.179Z,1565963619.179 [Default:CheckIn:E] Stopped
2019-08-16T13:53:39.179Z,1565963619.179 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T13:53:39.179Z,1565963619.179 [Default:CheckIn] Stopped
2019-08-16T13:53:39.179Z,1565963619.179 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T13:53:39.180Z,1565963619.180 [Default:CheckIn](INFO): Running loop #5
2019-08-16T13:53:39.180Z,1565963619.180 [Default:CheckIn] Running Loop=5
2019-08-16T13:53:39.180Z,1565963619.180 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T13:53:39.180Z,1565963619.180 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T13:53:40.788Z,1565963620.788 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:53:41.185Z,1565963621.185 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,135338.00,A,4149.69612,N,08324.71489,W,0.058,72.70,160819,,,D*42
2019-08-16T13:53:41.187Z,1565963621.187 [NAL9602](INFO): GPS fix at 20190816T135338: (41.828269, -83.411915)
2019-08-16T13:53:41.232Z,1565963621.232 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T13:53:41.232Z,1565963621.232 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T13:53:46.560Z,1565963626.560 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190816T132649/Courier0019.lzma
2019-08-16T13:53:47.366Z,1565963627.366 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0019.lzma.bak
2019-08-16T13:53:47.366Z,1565963627.366 [DataOverHttps](INFO): SBD MOMSN=11581984
2019-08-16T13:53:58.508Z,1565963638.508 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190816T132649/Express0020.lzma
2019-08-16T13:53:59.314Z,1565963639.314 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0020.lzma.bak
2019-08-16T13:53:59.314Z,1565963639.314 [DataOverHttps](INFO): SBD MOMSN=11581987
2019-08-16T13:54:00.203Z,1565963640.203 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T13:54:00.203Z,1565963640.203 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T13:54:00.203Z,1565963640.203 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T13:54:13.103Z,1565963653.103 [NAL9602](INFO): SBD MO Status=1, MOMSN=31157, MT Status=0, MTMSN=0
2019-08-16T13:54:13.103Z,1565963653.103 [NAL9602](INFO): No messages in MT queue
2019-08-16T13:54:43.840Z,1565963683.840 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T13:59:00.763Z,1565963940.763 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T13:59:00.763Z,1565963940.763 [Default:CheckIn:C.Wait] Stopped
2019-08-16T13:59:00.763Z,1565963940.763 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T13:59:00.763Z,1565963940.763 [Default:CheckIn:D] Running Loop=1
2019-08-16T13:59:01.175Z,1565963941.175 [Default:CheckIn:D] Stopped
2019-08-16T13:59:01.175Z,1565963941.175 [Default:CheckIn:E] Running Loop=1
2019-08-16T13:59:01.579Z,1565963941.579 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.588609 min 
2019-08-16T13:59:01.579Z,1565963941.579 [Default:CheckIn:E] Stopped
2019-08-16T13:59:01.579Z,1565963941.579 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T13:59:01.580Z,1565963941.580 [Default:CheckIn] Stopped
2019-08-16T13:59:01.580Z,1565963941.580 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T13:59:01.580Z,1565963941.580 [Default:CheckIn](INFO): Running loop #6
2019-08-16T13:59:01.580Z,1565963941.580 [Default:CheckIn] Running Loop=6
2019-08-16T13:59:01.580Z,1565963941.580 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T13:59:01.580Z,1565963941.580 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T13:59:03.176Z,1565963943.176 [NAL9602](DEBUG): Fix Requested
2019-08-16T13:59:03.577Z,1565963943.577 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,135900.00,A,4149.50836,N,08324.27778,W,8.145,126.50,160819,,,D*78
2019-08-16T13:59:03.579Z,1565963943.579 [NAL9602](INFO): GPS fix at 20190816T135900: (41.825139, -83.404630)
2019-08-16T13:59:03.607Z,1565963943.607 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T13:59:03.607Z,1565963943.607 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T13:59:08.920Z,1565963948.920 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190816T132649/Courier0022.lzma
2019-08-16T13:59:09.726Z,1565963949.726 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0022.lzma.bak
2019-08-16T13:59:09.726Z,1565963949.726 [DataOverHttps](INFO): SBD MOMSN=11581994
2019-08-16T13:59:22.564Z,1565963962.564 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20190816T132649/Express0023.lzma
2019-08-16T13:59:23.370Z,1565963963.370 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0023.lzma.bak
2019-08-16T13:59:23.370Z,1565963963.370 [DataOverHttps](INFO): SBD MOMSN=11581997
2019-08-16T13:59:24.214Z,1565963964.214 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T13:59:24.214Z,1565963964.214 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T13:59:24.214Z,1565963964.214 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T13:59:26.615Z,1565963966.615 [NAL9602](INFO): SBD MO Status=1, MOMSN=31158, MT Status=0, MTMSN=0
2019-08-16T13:59:26.615Z,1565963966.615 [NAL9602](INFO): No messages in MT queue
2019-08-16T13:59:57.306Z,1565963997.306 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T14:04:24.785Z,1565964264.785 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T14:04:24.785Z,1565964264.785 [Default:CheckIn:C.Wait] Stopped
2019-08-16T14:04:24.785Z,1565964264.785 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T14:04:24.786Z,1565964264.786 [Default:CheckIn:D] Running Loop=1
2019-08-16T14:04:25.188Z,1565964265.188 [Default:CheckIn:D] Stopped
2019-08-16T14:04:25.188Z,1565964265.188 [Default:CheckIn:E] Running Loop=1
2019-08-16T14:04:25.605Z,1565964265.605 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 33.988829 min 
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn:E] Stopped
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn] Stopped
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn](INFO): Running loop #7
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn] Running Loop=7
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T14:04:25.606Z,1565964265.606 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T14:04:27.192Z,1565964267.192 [NAL9602](DEBUG): Fix Requested
2019-08-16T14:04:27.587Z,1565964267.587 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,140424.00,A,4148.77699,N,08323.26888,W,18.097,139.74,160819,,,D*4F
2019-08-16T14:04:27.589Z,1565964267.589 [NAL9602](INFO): GPS fix at 20190816T140424: (41.812950, -83.387815)
2019-08-16T14:04:27.611Z,1565964267.611 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T14:04:27.611Z,1565964267.611 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T14:04:29.207Z,1565964269.207 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-08-16T14:04:33.180Z,1565964273.180 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190816T132649/Courier0025.lzma
2019-08-16T14:04:33.986Z,1565964273.986 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0025.lzma.bak
2019-08-16T14:04:33.986Z,1565964273.986 [DataOverHttps](INFO): SBD MOMSN=11582006
2019-08-16T14:04:45.932Z,1565964285.932 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20190816T132649/Express0026.lzma
2019-08-16T14:04:46.738Z,1565964286.738 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0026.lzma.bak
2019-08-16T14:04:46.738Z,1565964286.738 [DataOverHttps](INFO): SBD MOMSN=11582009
2019-08-16T14:04:48.593Z,1565964288.593 [NAL9602](INFO): SBD MO Status=2, MOMSN=31159, MT Status=2, MTMSN=0
2019-08-16T14:04:48.593Z,1565964288.593 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T14:04:48.623Z,1565964288.623 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T14:04:48.623Z,1565964288.623 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T14:04:48.623Z,1565964288.623 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T14:05:07.177Z,1565964307.177 [NAL9602](INFO): SBD MO Status=2, MOMSN=31159, MT Status=2, MTMSN=0
2019-08-16T14:05:07.177Z,1565964307.177 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T14:05:19.705Z,1565964319.705 [NAL9602](INFO): SBD MO Status=1, MOMSN=31159, MT Status=0, MTMSN=0
2019-08-16T14:05:19.705Z,1565964319.705 [NAL9602](INFO): No messages in MT queue
2019-08-16T14:05:50.406Z,1565964350.406 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T14:09:49.189Z,1565964589.189 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T14:09:49.189Z,1565964589.189 [Default:CheckIn:C.Wait] Stopped
2019-08-16T14:09:49.189Z,1565964589.189 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T14:09:49.189Z,1565964589.189 [Default:CheckIn:D] Running Loop=1
2019-08-16T14:09:49.605Z,1565964589.605 [Default:CheckIn:D] Stopped
2019-08-16T14:09:49.605Z,1565964589.605 [Default:CheckIn:E] Running Loop=1
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.395772 min 
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn:E] Stopped
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn] Stopped
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn](INFO): Running loop #8
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn] Running Loop=8
2019-08-16T14:09:49.999Z,1565964589.999 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T14:09:49.000Z,1565964590.000 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T14:09:51.596Z,1565964591.596 [NAL9602](DEBUG): Fix Requested
2019-08-16T14:09:51.994Z,1565964591.994 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,140948.00,A,4147.46341,N,08322.04761,W,17.650,140.33,160819,,,D*43
2019-08-16T14:09:51.997Z,1565964591.997 [NAL9602](INFO): GPS fix at 20190816T140948: (41.791057, -83.367460)
2019-08-16T14:09:52.020Z,1565964592.020 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T14:09:52.020Z,1565964592.020 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T14:09:53.665Z,1565964593.665 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-08-16T14:09:57.448Z,1565964597.448 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190816T132649/Courier0028.lzma
2019-08-16T14:09:58.254Z,1565964598.254 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0028.lzma.bak
2019-08-16T14:09:58.254Z,1565964598.254 [DataOverHttps](INFO): SBD MOMSN=11582014
2019-08-16T14:10:03.307Z,1565964603.307 [NAL9602](INFO): SBD MO Status=1, MOMSN=31160, MT Status=0, MTMSN=0
2019-08-16T14:10:03.307Z,1565964603.307 [NAL9602](INFO): No messages in MT queue
2019-08-16T14:10:09.448Z,1565964609.448 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190816T132649/Express0029.lzma
2019-08-16T14:10:10.254Z,1565964610.254 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0029.lzma.bak
2019-08-16T14:10:10.254Z,1565964610.254 [DataOverHttps](INFO): SBD MOMSN=11582017
2019-08-16T14:10:11.427Z,1565964611.427 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T14:10:11.427Z,1565964611.427 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T14:10:11.427Z,1565964611.427 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T14:10:34.005Z,1565964634.005 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T14:15:11.991Z,1565964911.991 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T14:15:11.991Z,1565964911.991 [Default:CheckIn:C.Wait] Stopped
2019-08-16T14:15:11.991Z,1565964911.991 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T14:15:11.991Z,1565964911.991 [Default:CheckIn:D] Running Loop=1
2019-08-16T14:15:12.402Z,1565964912.402 [Default:CheckIn:D] Stopped
2019-08-16T14:15:12.402Z,1565964912.402 [Default:CheckIn:E] Running Loop=1
2019-08-16T14:15:12.819Z,1565964912.819 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 44.775720 min 
2019-08-16T14:15:12.819Z,1565964912.819 [Default:CheckIn:E] Stopped
2019-08-16T14:15:12.819Z,1565964912.819 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T14:15:12.819Z,1565964912.819 [Default:CheckIn] Stopped
2019-08-16T14:15:12.819Z,1565964912.819 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T14:15:12.819Z,1565964912.819 [Default:CheckIn](INFO): Running loop #9
2019-08-16T14:15:12.820Z,1565964912.820 [Default:CheckIn] Running Loop=9
2019-08-16T14:15:12.820Z,1565964912.820 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T14:15:12.820Z,1565964912.820 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T14:15:14.428Z,1565964914.428 [NAL9602](DEBUG): Fix Requested
2019-08-16T14:15:14.803Z,1565964914.803 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,141510.00,A,4146.19502,N,08320.75185,W,18.000,137.17,160819,,,D*4B
2019-08-16T14:15:14.805Z,1565964914.805 [NAL9602](INFO): GPS fix at 20190816T141510: (41.769917, -83.345864)
2019-08-16T14:15:14.827Z,1565964914.827 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T14:15:14.827Z,1565964914.827 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T14:15:20.324Z,1565964920.324 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190816T132649/Courier0031.lzma
2019-08-16T14:15:21.130Z,1565964921.130 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0031.lzma.bak
2019-08-16T14:15:21.130Z,1565964921.130 [DataOverHttps](INFO): SBD MOMSN=11582027
2019-08-16T14:15:32.428Z,1565964932.428 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190816T132649/Express0032.lzma
2019-08-16T14:15:33.234Z,1565964933.234 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0032.lzma.bak
2019-08-16T14:15:33.234Z,1565964933.234 [DataOverHttps](INFO): SBD MOMSN=11582030
2019-08-16T14:15:34.235Z,1565964934.235 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T14:15:34.235Z,1565964934.235 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T14:15:34.235Z,1565964934.235 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T14:15:35.003Z,1565964935.003 [NAL9602](INFO): SBD MO Status=1, MOMSN=31161, MT Status=0, MTMSN=0
2019-08-16T14:15:35.003Z,1565964935.003 [NAL9602](INFO): No messages in MT queue
2019-08-16T14:16:05.714Z,1565964965.714 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T14:20:34.794Z,1565965234.794 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T14:20:34.794Z,1565965234.794 [Default:CheckIn:C.Wait] Stopped
2019-08-16T14:20:34.794Z,1565965234.794 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T14:20:34.795Z,1565965234.795 [Default:CheckIn:D] Running Loop=1
2019-08-16T14:20:35.199Z,1565965235.199 [Default:CheckIn:D] Stopped
2019-08-16T14:20:35.199Z,1565965235.199 [Default:CheckIn:E] Running Loop=1
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.155680 min 
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn:E] Stopped
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn] Stopped
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn](INFO): Running loop #10
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn] Running Loop=10
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T14:20:35.602Z,1565965235.602 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T14:20:37.208Z,1565965237.208 [NAL9602](DEBUG): Fix Requested
2019-08-16T14:20:37.601Z,1565965237.601 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,142033.00,A,4145.16263,N,08319.15463,W,17.689,145.25,160819,,,D*4D
2019-08-16T14:20:37.603Z,1565965237.603 [NAL9602](INFO): GPS fix at 20190816T142033: (41.752710, -83.319244)
2019-08-16T14:20:37.627Z,1565965237.627 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T14:20:37.627Z,1565965237.627 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T14:20:42.924Z,1565965242.924 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190816T132649/Courier0034.lzma
2019-08-16T14:20:43.730Z,1565965243.730 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0034.lzma.bak
2019-08-16T14:20:43.730Z,1565965243.730 [DataOverHttps](INFO): SBD MOMSN=11582043
2019-08-16T14:20:58.156Z,1565965258.156 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190816T132649/Express0035.lzma
2019-08-16T14:20:58.235Z,1565965258.235 [NAL9602](INFO): SBD MO Status=2, MOMSN=31162, MT Status=2, MTMSN=0
2019-08-16T14:20:58.235Z,1565965258.235 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-16T14:20:58.962Z,1565965258.962 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Express0035.lzma.bak
2019-08-16T14:20:58.962Z,1565965258.962 [DataOverHttps](INFO): SBD MOMSN=11582046
2019-08-16T14:20:59.879Z,1565965259.879 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T14:20:59.879Z,1565965259.879 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T14:20:59.879Z,1565965259.879 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T14:21:29.333Z,1565965289.333 [NAL9602](INFO): SBD MO Status=1, MOMSN=31162, MT Status=0, MTMSN=0
2019-08-16T14:21:29.333Z,1565965289.333 [NAL9602](INFO): No messages in MT queue
2019-08-16T14:22:00.037Z,1565965320.037 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T14:26:00.437Z,1565965560.437 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-16T14:26:00.437Z,1565965560.437 [Default:CheckIn:C.Wait] Stopped
2019-08-16T14:26:00.437Z,1565965560.437 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-16T14:26:00.438Z,1565965560.438 [Default:CheckIn:D] Running Loop=1
2019-08-16T14:26:00.847Z,1565965560.847 [Default:CheckIn:D] Stopped
2019-08-16T14:26:00.847Z,1565965560.847 [Default:CheckIn:E] Running Loop=1
2019-08-16T14:26:01.250Z,1565965561.250 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.583142 min 
2019-08-16T14:26:01.250Z,1565965561.250 [Default:CheckIn:E] Stopped
2019-08-16T14:26:01.251Z,1565965561.251 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-16T14:26:01.251Z,1565965561.251 [Default:CheckIn] Stopped
2019-08-16T14:26:01.251Z,1565965561.251 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-16T14:26:01.251Z,1565965561.251 [Default:CheckIn](INFO): Running loop #11
2019-08-16T14:26:01.251Z,1565965561.251 [Default:CheckIn] Running Loop=11
2019-08-16T14:26:01.251Z,1565965561.251 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-16T14:26:01.251Z,1565965561.251 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-16T14:26:02.852Z,1565965562.852 [NAL9602](DEBUG): Fix Requested
2019-08-16T14:26:03.251Z,1565965563.251 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,142558.00,A,4144.51743,N,08318.41667,W,0.622,140.14,160819,,,D*76
2019-08-16T14:26:03.253Z,1565965563.253 [NAL9602](INFO): GPS fix at 20190816T142558: (41.741957, -83.306945)
2019-08-16T14:26:03.275Z,1565965563.275 [Default:CheckIn:Read_GPS] Stopped
2019-08-16T14:26:03.275Z,1565965563.275 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-16T14:26:05.276Z,1565965565.276 [NAL9602](ERROR): parseGSV uart error: serial buffer full
2019-08-16T14:26:08.828Z,1565965568.828 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190816T132649/Courier0037.lzma
2019-08-16T14:26:09.634Z,1565965569.634 [DataOverHttps](INFO): Moved sent file to Logs/20190816T132649/Courier0037.lzma.bak
2019-08-16T14:26:09.634Z,1565965569.634 [DataOverHttps](INFO): SBD MOMSN=11582067
2019-08-16T14:26:20.215Z,1565965580.215 [NAL9602](INFO): SBD MO Status=1, MOMSN=31163, MT Status=0, MTMSN=0
2019-08-16T14:26:20.215Z,1565965580.215 [NAL9602](INFO): No messages in MT queue
2019-08-16T14:26:50.915Z,1565965610.915 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T14:27:17.033Z,1565965637.033 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-16T14:27:47.737Z,1565965667.737 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-16T14:28:49.145Z,1565965729.145 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-16T14:29:16.213Z,1565965756.213 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.315247
2019-08-16T14:29:38.148Z,1565965778.148 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003034
2019-08-16T14:29:38.719Z,1565965778.719 [NAL9602](INFO): SBD MO Status=1, MOMSN=31164, MT Status=0, MTMSN=0
2019-08-16T14:29:38.769Z,1565965778.769 [NAL9602](INFO): Sent 136 bytes from file Logs/20190816T132649/Express0038.lzma
2019-08-16T14:29:38.769Z,1565965778.769 [NAL9602](INFO): Packets left to send: 0
2019-08-16T14:29:39.143Z,1565965779.143 [Default:CheckIn:Read_Iridium] Stopped
2019-08-16T14:29:39.143Z,1565965779.143 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-16T14:29:39.143Z,1565965779.143 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-16T14:30:09.407Z,1565965809.407 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-16T14:32:56.233Z,1565965976.233 [DataOverHttps](IMPORTANT): SBD MTMSN=20190816T143250