2019-08-07T16:22:06.933Z,1565194926.933 [Supervisor](DEBUG): Initializing supervisor. 2019-08-07T16:22:06.936Z,1565194926.936 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-08-07T16:22:06.936Z,1565194926.936 [SyncHandler](INFO): Protected caller Thread ID is 1149 2019-08-07T16:22:06.937Z,1565194926.937 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-08-07T16:22:06.938Z,1565194926.938 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-08-07T16:22:06.938Z,1565194926.938 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1150 2019-08-07T16:22:06.941Z,1565194926.941 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-08-07T16:22:06.952Z,1565194926.952 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-08-07T16:22:06.954Z,1565194926.954 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-08-07T16:22:06.954Z,1565194926.954 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1151 2019-08-07T16:22:06.955Z,1565194926.955 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-08-07T16:22:06.956Z,1565194926.956 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-08-07T16:22:06.956Z,1565194926.956 [logger ThreadHandler](INFO): Protected caller Thread ID is 1152 2019-08-07T16:22:06.958Z,1565194926.958 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-08-07T16:22:06.958Z,1565194926.958 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-08-07T16:22:06.960Z,1565194926.960 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-08-07T16:22:07.161Z,1565194927.161 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-08-07T16:22:07.162Z,1565194927.162 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-08-07T16:22:07.241Z,1565194927.241 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-08-07T16:22:07.680Z,1565194927.680 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-08-07T16:22:07.680Z,1565194927.680 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-08-07T16:22:08.017Z,1565194928.017 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-08-07T16:22:08.018Z,1565194928.018 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-08-07T16:22:08.113Z,1565194928.113 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-08-07T16:22:08.114Z,1565194928.114 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-08-07T16:22:08.413Z,1565194928.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-08-07T16:22:08.414Z,1565194928.414 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-08-07T16:22:08.609Z,1565194928.609 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-08-07T16:22:08.609Z,1565194928.609 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-08-07T16:22:09.065Z,1565194929.065 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-08-07T16:22:09.066Z,1565194929.066 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-08-07T16:22:09.171Z,1565194929.171 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-08-07T16:22:09.171Z,1565194929.171 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-08-07T16:22:09.271Z,1565194929.271 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-08-07T16:22:09.271Z,1565194929.271 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-08-07T16:22:09.875Z,1565194929.875 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-08-07T16:22:09.876Z,1565194929.876 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-08-07T16:22:10.273Z,1565194930.273 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-08-07T16:22:10.274Z,1565194930.274 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-08-07T16:22:10.470Z,1565194930.470 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-08-07T16:22:10.470Z,1565194930.470 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-08-07T16:22:10.616Z,1565194930.616 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-08-07T16:22:10.616Z,1565194930.616 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-08-07T16:22:10.766Z,1565194930.766 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-08-07T16:22:10.768Z,1565194930.768 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2019-08-07T16:22:10.768Z,1565194930.768 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2019-08-07T16:22:10.859Z,1565194930.859 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2019-08-07T16:22:10.944Z,1565194930.944 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2019-08-07T16:22:11.055Z,1565194931.055 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2019-08-07T16:22:11.360Z,1565194931.360 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2019-08-07T16:22:11.484Z,1565194931.484 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2019-08-07T16:22:11.631Z,1565194931.631 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2019-08-07T16:22:12.017Z,1565194932.017 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2019-08-07T16:22:12.093Z,1565194932.093 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2019-08-07T16:22:12.263Z,1565194932.263 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2019-08-07T16:22:12.399Z,1565194932.399 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2019-08-07T16:22:12.519Z,1565194932.519 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2019-08-07T16:22:12.750Z,1565194932.750 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-08-07T16:22:12.750Z,1565194932.750 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-08-07T16:22:12.760Z,1565194932.760 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-08-07T16:22:12.827Z,1565194932.827 [VerticalControl](DEBUG): Construct VerticalControl. 2019-08-07T16:22:12.941Z,1565194932.941 [VerticalControl] Loaded 2019-08-07T16:22:12.941Z,1565194932.941 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-08-07T16:22:12.942Z,1565194932.942 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-08-07T16:22:13.011Z,1565194933.011 [HorizontalControl] Loaded 2019-08-07T16:22:13.011Z,1565194933.011 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-08-07T16:22:13.012Z,1565194933.012 [SpeedControl](DEBUG): Construct SpeedControl. 2019-08-07T16:22:13.017Z,1565194933.017 [SpeedControl] Loaded 2019-08-07T16:22:13.018Z,1565194933.018 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-08-07T16:22:13.018Z,1565194933.018 [LoopControl](DEBUG): Construct LoopControl. 2019-08-07T16:22:13.019Z,1565194933.019 [LoopControl] Loaded 2019-08-07T16:22:13.019Z,1565194933.019 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-08-07T16:22:13.020Z,1565194933.020 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-08-07T16:22:13.020Z,1565194933.020 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-08-07T16:22:13.033Z,1565194933.033 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-08-07T16:22:13.034Z,1565194933.034 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-08-07T16:22:13.132Z,1565194933.132 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-08-07T16:22:13.132Z,1565194933.132 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-08-07T16:22:13.260Z,1565194933.260 [BuoyancyServo] Loaded 2019-08-07T16:22:13.260Z,1565194933.260 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-08-07T16:22:13.271Z,1565194933.271 [ElevatorServo] Loaded 2019-08-07T16:22:13.272Z,1565194933.272 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-08-07T16:22:13.283Z,1565194933.283 [MassServo] Loaded 2019-08-07T16:22:13.283Z,1565194933.283 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-08-07T16:22:13.294Z,1565194933.294 [RudderServo] Loaded 2019-08-07T16:22:13.294Z,1565194933.294 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-08-07T16:22:13.306Z,1565194933.306 [ThrusterServo] Loaded 2019-08-07T16:22:13.306Z,1565194933.306 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-08-07T16:22:13.306Z,1565194933.306 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-08-07T16:22:13.307Z,1565194933.307 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-08-07T16:22:13.415Z,1565194933.415 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-08-07T16:22:13.415Z,1565194933.415 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-08-07T16:22:13.436Z,1565194933.436 [NavChart] Loaded 2019-08-07T16:22:13.436Z,1565194933.436 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-08-07T16:22:13.440Z,1565194933.440 [UniversalFixResidualReporter] Loaded 2019-08-07T16:22:13.441Z,1565194933.441 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-08-07T16:22:13.441Z,1565194933.441 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-08-07T16:22:13.442Z,1565194933.442 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-08-07T16:22:13.513Z,1565194933.513 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-08-07T16:22:13.513Z,1565194933.513 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-08-07T16:22:13.865Z,1565194933.865 [AHRS_M2] Loaded 2019-08-07T16:22:13.865Z,1565194933.865 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-08-07T16:22:13.940Z,1565194933.940 [DataOverHttps] Loaded 2019-08-07T16:22:13.941Z,1565194933.941 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-08-07T16:22:13.942Z,1565194933.942 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087D4E0 2019-08-07T16:22:13.942Z,1565194933.942 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1234 2019-08-07T16:22:13.955Z,1565194933.955 [Depth_Keller] Loaded 2019-08-07T16:22:13.956Z,1565194933.956 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-08-07T16:22:13.961Z,1565194933.961 [DropWeight] Loaded 2019-08-07T16:22:13.961Z,1565194933.961 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-08-07T16:22:14.112Z,1565194934.112 [NAL9602] Loaded 2019-08-07T16:22:14.113Z,1565194934.113 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-08-07T16:22:14.128Z,1565194934.128 [Onboard] Loaded 2019-08-07T16:22:14.129Z,1565194934.129 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-08-07T16:22:14.132Z,1565194934.132 [Radio_Surface] Loaded 2019-08-07T16:22:14.132Z,1565194934.132 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-08-07T16:22:14.133Z,1565194934.133 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408AD4E0 2019-08-07T16:22:14.134Z,1565194934.134 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1235 2019-08-07T16:22:15.637Z,1565194935.637 [BPC1] Loaded 2019-08-07T16:22:15.637Z,1565194935.637 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-08-07T16:22:15.638Z,1565194935.638 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-08-07T16:22:15.638Z,1565194935.638 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-08-07T16:22:15.680Z,1565194935.680 [DepthRateCalculator] Loaded 2019-08-07T16:22:15.680Z,1565194935.680 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-08-07T16:22:15.686Z,1565194935.686 [PitchRateCalculator] Loaded 2019-08-07T16:22:15.686Z,1565194935.686 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-08-07T16:22:15.698Z,1565194935.698 [SpeedCalculator] Loaded 2019-08-07T16:22:15.698Z,1565194935.698 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-08-07T16:22:15.719Z,1565194935.719 [TempGradientCalculator] Loaded 2019-08-07T16:22:15.720Z,1565194935.720 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-08-07T16:22:15.725Z,1565194935.725 [YawRateCalculator] Loaded 2019-08-07T16:22:15.725Z,1565194935.725 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-08-07T16:22:15.755Z,1565194935.755 [ElevatorOffsetCalculator] Loaded 2019-08-07T16:22:15.755Z,1565194935.755 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-08-07T16:22:15.755Z,1565194935.755 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-08-07T16:22:15.756Z,1565194935.756 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-08-07T16:22:15.940Z,1565194935.940 [Aanderaa_O2] Loaded 2019-08-07T16:22:15.940Z,1565194935.940 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2019-08-07T16:22:15.952Z,1565194935.952 [CANONSampler] Loaded 2019-08-07T16:22:15.953Z,1565194935.953 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread. 2019-08-07T16:22:16.037Z,1565194936.037 [CTD_NeilBrown] Loaded 2019-08-07T16:22:16.037Z,1565194936.037 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-08-07T16:22:16.038Z,1565194936.038 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409AF4E0 2019-08-07T16:22:16.039Z,1565194936.039 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1236 2019-08-07T16:22:16.048Z,1565194936.048 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2019-08-07T16:22:16.053Z,1565194936.053 [CTD_Seabird](INFO): created writer for : sea_water_density 2019-08-07T16:22:16.055Z,1565194936.055 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2019-08-07T16:22:16.059Z,1565194936.059 [CTD_Seabird](INFO): created writer for : depth 2019-08-07T16:22:16.060Z,1565194936.060 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2019-08-07T16:22:16.065Z,1565194936.065 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2019-08-07T16:22:16.066Z,1565194936.066 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2019-08-07T16:22:16.070Z,1565194936.070 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2019-08-07T16:22:16.071Z,1565194936.071 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2019-08-07T16:22:16.076Z,1565194936.076 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2019-08-07T16:22:16.077Z,1565194936.077 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2019-08-07T16:22:16.082Z,1565194936.082 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2019-08-07T16:22:16.082Z,1565194936.082 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2019-08-07T16:22:16.087Z,1565194936.087 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2019-08-07T16:22:16.114Z,1565194936.114 [CTD_Seabird] Loaded 2019-08-07T16:22:16.115Z,1565194936.115 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2019-08-07T16:22:16.116Z,1565194936.116 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409DF4E0 2019-08-07T16:22:16.116Z,1565194936.116 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1237 2019-08-07T16:22:16.131Z,1565194936.131 [PAR_Licor] Loaded 2019-08-07T16:22:16.131Z,1565194936.131 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-08-07T16:22:16.179Z,1565194936.179 [WetLabsBB2FL] Loaded 2019-08-07T16:22:16.179Z,1565194936.179 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2019-08-07T16:22:16.180Z,1565194936.180 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A0F4E0 2019-08-07T16:22:16.181Z,1565194936.181 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1238 2019-08-07T16:22:16.181Z,1565194936.181 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-08-07T16:22:16.182Z,1565194936.182 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-08-07T16:22:16.300Z,1565194936.300 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-08-07T16:22:16.301Z,1565194936.301 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-08-07T16:22:16.598Z,1565194936.598 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-08-07T16:22:16.599Z,1565194936.599 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-08-07T16:22:16.733Z,1565194936.733 [SBIT](DEBUG): Construct Startup Built In Test. 2019-08-07T16:22:16.744Z,1565194936.744 [SBIT] Loaded 2019-08-07T16:22:16.745Z,1565194936.745 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-08-07T16:22:16.745Z,1565194936.745 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-08-07T16:22:16.757Z,1565194936.757 [IBIT] Loaded 2019-08-07T16:22:16.758Z,1565194936.758 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-08-07T16:22:16.761Z,1565194936.761 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-08-07T16:22:16.900Z,1565194936.900 [CBIT] Loaded 2019-08-07T16:22:16.900Z,1565194936.900 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-08-07T16:22:16.901Z,1565194936.901 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-08-07T16:22:16.904Z,1565194936.904 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-08-07T16:22:16.905Z,1565194936.905 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-08-07T16:22:16.912Z,1565194936.912 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-08-07T16:22:16.913Z,1565194936.913 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B0E4E0 2019-08-07T16:22:16.914Z,1565194936.914 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1239 2019-08-07T16:22:16.918Z,1565194936.918 [Supervisor](INFO): Main Thread ID is 803 2019-08-07T16:22:16.919Z,1565194936.919 [Supervisor](DEBUG): Running supervisor. 2019-08-07T16:22:16.919Z,1565194936.919 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1240 2019-08-07T16:22:16.921Z,1565194936.921 [controlThread ThreadHandler](INFO): Handler Thread ID is 1241 2019-08-07T16:22:16.922Z,1565194936.922 [controlThread](DEBUG): Initializing ControlThread 2019-08-07T16:22:16.923Z,1565194936.923 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-08-07T16:22:16.924Z,1565194936.924 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-08-07T16:22:16.925Z,1565194936.925 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-08-07T16:22:16.925Z,1565194936.925 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-08-07T16:22:16.927Z,1565194936.927 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-08-07T16:22:16.928Z,1565194936.928 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-08-07T16:22:16.932Z,1565194936.932 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-08-07T16:22:16.932Z,1565194936.932 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-08-07T16:22:16.932Z,1565194936.932 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-08-07T16:22:16.933Z,1565194936.933 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-08-07T16:22:16.933Z,1565194936.933 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-08-07T16:22:16.933Z,1565194936.933 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-08-07T16:22:16.938Z,1565194936.938 [SBIT](INFO): Initialize SBIT Component. 2019-08-07T16:22:16.938Z,1565194936.938 [SBIT](IMPORTANT): git: 2019-08-07 2019-08-07T16:22:16.938Z,1565194936.938 [SBIT](INFO): git hash: 49f01da6f65cabd29e5588026e609de99f82dc0c 2019-08-07T16:22:16.939Z,1565194936.939 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-08-07T16:22:16.940Z,1565194936.940 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018 2019-08-07T16:22:16.941Z,1565194936.941 [SBIT](INFO): Beginning SBIT in 36.000000 seconds. 2019-08-07T16:22:16.942Z,1565194936.942 [IBIT](INFO): Initialize IBIT Component. 2019-08-07T16:22:16.943Z,1565194936.943 [CBIT](DEBUG): Initialize CBIT Component. 2019-08-07T16:22:16.944Z,1565194936.944 [logger ThreadHandler](INFO): Handler Thread ID is 1242 2019-08-07T16:22:16.953Z,1565194936.953 [CBIT](DEBUG): Initialized mux pins. 2019-08-07T16:22:16.954Z,1565194936.954 [CBIT](DEBUG): Initializing the watchdog timer. 2019-08-07T16:22:16.962Z,1565194936.962 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1243 2019-08-07T16:22:16.963Z,1565194936.963 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-08-07T16:22:16.974Z,1565194936.974 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1244 2019-08-07T16:22:16.978Z,1565194936.978 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-08-07T16:22:16.978Z,1565194936.978 [CBIT](DEBUG): Initializing heartbeat. 2019-08-07T16:22:16.986Z,1565194936.986 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1245 2019-08-07T16:22:16.987Z,1565194936.987 [CTD_NeilBrown](INFO): Powering down 2019-08-07T16:22:17.006Z,1565194937.006 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1246 2019-08-07T16:22:17.007Z,1565194937.007 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2019-08-07T16:22:17.014Z,1565194937.014 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20 2019-08-07T16:22:17.018Z,1565194937.018 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1248 2019-08-07T16:22:17.019Z,1565194937.019 [WetLabsBB2FL](INFO): Powering down 2019-08-07T16:22:17.047Z,1565194937.047 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1249 2019-08-07T16:22:17.050Z,1565194937.050 [CBIT](DEBUG): Deactivating GF circuits. 2019-08-07T16:22:17.050Z,1565194937.050 [CBIT](DEBUG): Deactivating emergency mode. 2019-08-07T16:22:17.051Z,1565194937.051 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-08-07T16:22:17.051Z,1565194937.051 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-08-07T16:22:17.052Z,1565194937.052 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-08-07T16:22:17.052Z,1565194937.052 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-08-07T16:22:17.052Z,1565194937.052 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-08-07T16:22:17.052Z,1565194937.052 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-08-07T16:22:17.052Z,1565194937.052 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-08-07T16:22:17.053Z,1565194937.053 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-08-07T16:22:17.053Z,1565194937.053 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-08-07T16:22:17.053Z,1565194937.053 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-08-07T16:22:17.053Z,1565194937.053 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-08-07T16:22:17.053Z,1565194937.053 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-08-07T16:22:17.054Z,1565194937.054 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-08-07T16:22:17.054Z,1565194937.054 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-08-07T16:22:17.054Z,1565194937.054 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-08-07T16:22:17.054Z,1565194937.054 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-08-07T16:22:17.085Z,1565194937.085 [CBIT](DEBUG): Backplane powered. 2019-08-07T16:22:17.086Z,1565194937.086 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-08-07T16:22:17.096Z,1565194937.096 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-08-07T16:22:17.107Z,1565194937.107 [MissionManager](DEBUG): 2019-08-07T16:22:17.108Z,1565194937.108 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-08-07T16:22:17.183Z,1565194937.183 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-08-07T16:22:17.184Z,1565194937.184 [Default:A.Wait](DEBUG): Construct Wait. 2019-08-07T16:22:17.206Z,1565194937.206 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-08-07T16:22:17.229Z,1565194937.229 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-08-07T16:22:17.231Z,1565194937.231 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-08-07T16:22:17.245Z,1565194937.245 [Default:E.Execute](DEBUG): Construct Execute. 2019-08-07T16:22:17.248Z,1565194937.248 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2019-08-07T16:22:17.270Z,1565194937.270 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,BPC1,Aanderaa_O2,CANONSampler,PAR_Licor,Depth_Keller,PAR_Licor,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-07T16:22:17.275Z,1565194937.275 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-08-07T16:22:17.324Z,1565194937.324 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar 2019-08-07T16:22:17.374Z,1565194937.374 [CANONSampler](INFO): Powering down 2019-08-07T16:22:17.378Z,1565194937.378 [Radio_Surface](INFO): Powering up 2019-08-07T16:22:17.562Z,1565194937.562 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-08-07T16:22:17.591Z,1565194937.591 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-08-07T16:22:17.598Z,1565194937.598 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-08-07T16:22:17.599Z,1565194937.599 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-08-07T16:22:17.606Z,1565194937.606 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-08-07T16:22:17.607Z,1565194937.607 [MassServo](DEBUG): Initializing EZServoServo. 2019-08-07T16:22:17.614Z,1565194937.614 [MassServo](DEBUG): Initializing MassServo. 2019-08-07T16:22:17.615Z,1565194937.615 [RudderServo](DEBUG): Initializing EZServoServo. 2019-08-07T16:22:17.622Z,1565194937.622 [RudderServo](DEBUG): Initializing RudderServo. 2019-08-07T16:22:17.623Z,1565194937.623 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-08-07T16:22:17.630Z,1565194937.630 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-08-07T16:22:18.466Z,1565194938.466 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-08-07T16:22:18.466Z,1565194938.466 [RudderServo](FAULT): Rudder failed to initialize 2019-08-07T16:22:18.466Z,1565194938.466 [RudderServo] Communications Fault, FailCount= 1 2019-08-07T16:22:18.466Z,1565194938.466 [RudderServo](ERROR): Communications Fault 2019-08-07T16:22:18.591Z,1565194938.591 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-08-07T16:22:18.783Z,1565194938.783 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-08-07T16:22:18.783Z,1565194938.783 [RudderServo](INFO): Powering down 2019-08-07T16:22:19.456Z,1565194939.456 [RudderServo](DEBUG): Initializing EZServoServo. 2019-08-07T16:22:19.574Z,1565194939.574 [RudderServo](DEBUG): Initializing RudderServo. 2019-08-07T16:22:19.578Z,1565194939.578 [CBIT](INFO): Clearing failed state for component RudderServo 2019-08-07T16:22:19.579Z,1565194939.579 [RudderServo] No Fault, FailCount= 1 2019-08-07T16:22:20.826Z,1565194940.826 [Aanderaa_O2](INFO): Powering down 2019-08-07T16:22:24.038Z,1565194944.038 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit. 2019-08-07T16:22:44.471Z,1565194964.471 [NAL9602](INFO): Powering up NAL9602 2019-08-07T16:22:53.412Z,1565194973.412 [SBIT](IMPORTANT): Beginning Startup BIT 2019-08-07T16:22:53.420Z,1565194973.420 [CBIT](IMPORTANT): Beginning ground fault scan 2019-08-07T16:22:55.379Z,1565194975.379 [NAL9602](INFO): NAL9602 initialized 2019-08-07T16:22:56.370Z,1565194976.370 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:23:04.142Z,1565194984.142 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 4.657929 CHAN A1 (24V): -0.133991 CHAN A2 (12V): -0.002189 CHAN A3 (5V): -0.001671 CHAN B0 (3.3V): 0.000155 CHAN B1 (3.15aV): -0.000270 CHAN B2 (3.15bV): 4.767929 CHAN B3 (GND): 0.000118 OPEN: -0.000292 Full Scale Calc: 4.765 mA, -1.589 mA 2019-08-07T16:23:19.937Z,1565194999.937 [NAL9602](INFO): SBD MO Status=2, MOMSN=15864, MT Status=2, MTMSN=0 2019-08-07T16:23:19.937Z,1565194999.937 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:23:29.228Z,1565195009.228 [NAL9602](INFO): SBD MO Status=0, MOMSN=15864, MT Status=0, MTMSN=0 2019-08-07T16:23:29.228Z,1565195009.228 [NAL9602](INFO): No messages in MT queue 2019-08-07T16:23:30.045Z,1565195010.045 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:23:30.441Z,1565195010.441 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162323.00,A,3648.14676,N,12147.22616,W,0.544,184.27,070819,,,A*7A 2019-08-07T16:23:30.444Z,1565195010.444 [NAL9602](INFO): GPS fix at 20190807T162323: (36.802446, -121.787103) 2019-08-07T16:23:46.763Z,1565195026.763 [SBIT](IMPORTANT): SBIT PASSED 2019-08-07T16:23:46.818Z,1565195026.818 [CommandLine](IMPORTANT): got command configSet list 2019-08-07T16:23:46.818Z,1565195026.818 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-08-07T16:23:46.819Z,1565195026.819 [CommandLine](IMPORTANT): CANONSampler.loadAtStartup=1 bool; 2019-08-07T16:23:46.819Z,1565195026.819 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle=1 bool; 2019-08-07T16:23:46.819Z,1565195026.819 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool; 2019-08-07T16:23:46.819Z,1565195026.819 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool; 2019-08-07T16:23:46.820Z,1565195026.820 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=0 bool; 2019-08-07T16:23:46.820Z,1565195026.820 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-08-07T16:23:46.820Z,1565195026.820 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=200 cubic_centimeter; 2019-08-07T16:23:46.820Z,1565195026.820 [CommandLine](IMPORTANT): VerticalControl.massDefault=-4 millimeter; 2019-08-07T16:23:46.820Z,1565195026.820 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-31 millimeter; 2019-08-07T16:23:46.820Z,1565195026.820 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=30 millimeter; 2019-08-07T16:23:47.166Z,1565195027.166 [MissionManager](IMPORTANT): Started mission Startup 2019-08-07T16:23:47.166Z,1565195027.166 [Startup] Running Loop=1 2019-08-07T16:23:47.166Z,1565195027.166 [Startup](DEBUG): Aggregate::initialize Startup 2019-08-07T16:23:47.166Z,1565195027.166 [Startup:A.GoToSurface] Running Loop=1 2019-08-07T16:23:47.167Z,1565195027.167 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-08-07T16:23:47.167Z,1565195027.167 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-08-07T16:23:47.168Z,1565195027.168 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-08-07T16:23:47.168Z,1565195027.168 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-08-07T16:23:47.168Z,1565195027.168 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-08-07T16:23:47.169Z,1565195027.169 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-08-07T16:23:47.174Z,1565195027.174 [Startup:StartupSatComms] Running Loop=1 2019-08-07T16:23:47.174Z,1565195027.174 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-08-07T16:23:47.174Z,1565195027.174 [Startup:StartupSatComms:A] Running Loop=1 2019-08-07T16:23:47.584Z,1565195027.584 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-08-07T16:23:48.757Z,1565195028.757 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:23:49.156Z,1565195029.156 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162342.00,A,3648.14819,N,12147.22569,W,0.816,311.47,070819,,,A*73 2019-08-07T16:23:49.159Z,1565195029.159 [NAL9602](INFO): GPS fix at 20190807T162342: (36.802470, -121.787095) 2019-08-07T16:23:49.184Z,1565195029.184 [Startup:StartupSatComms:A] Stopped 2019-08-07T16:23:49.184Z,1565195029.184 [Startup:StartupSatComms:B] Running Loop=1 2019-08-07T16:23:49.598Z,1565195029.598 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-08-07T16:24:11.032Z,1565195051.032 [NAL9602](INFO): SBD MO Status=1, MOMSN=15865, MT Status=0, MTMSN=0 2019-08-07T16:24:11.082Z,1565195051.082 [NAL9602](INFO): Sent 64 bytes from file Logs/20190807T151639/Courier0043.lzma 2019-08-07T16:24:11.082Z,1565195051.082 [NAL9602](INFO): Packets left to send: 0 2019-08-07T16:24:21.582Z,1565195061.582 [NAL9602](INFO): SBD MO Status=1, MOMSN=15866, MT Status=0, MTMSN=0 2019-08-07T16:24:21.638Z,1565195061.638 [NAL9602](INFO): Sent 25 bytes from file Logs/20190807T151639/Courier0046.lzma 2019-08-07T16:24:21.638Z,1565195061.638 [NAL9602](INFO): Packets left to send: 0 2019-08-07T16:24:36.000Z,1565195077.000 [NAL9602](INFO): SBD MO Status=1, MOMSN=15867, MT Status=0, MTMSN=0 2019-08-07T16:24:37.050Z,1565195077.050 [NAL9602](INFO): Sent 214 bytes from file Logs/20190807T162206/Courier0000.lzma 2019-08-07T16:24:37.050Z,1565195077.050 [NAL9602](INFO): Packets left to send: 0 2019-08-07T16:24:47.584Z,1565195087.584 [NAL9602](INFO): SBD MO Status=1, MOMSN=15868, MT Status=0, MTMSN=0 2019-08-07T16:24:47.634Z,1565195087.634 [NAL9602](INFO): Sent 57 bytes from file Logs/20190807T151639/Express0030.lzma 2019-08-07T16:24:47.634Z,1565195087.634 [NAL9602](INFO): Packets left to send: 0 2019-08-07T16:24:50.434Z,1565195090.434 [Startup:StartupSatComms:B](INFO): Timed out from 2019-08-07T16:23:49.2Z 2019-08-07T16:24:50.434Z,1565195090.434 [Startup:StartupSatComms:B] Stopped 2019-08-07T16:24:50.434Z,1565195090.434 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-08-07T16:24:50.434Z,1565195090.434 [Startup:StartupSatComms] Stopped 2019-08-07T16:24:50.434Z,1565195090.434 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-08-07T16:24:50.435Z,1565195090.435 [Startup](INFO): Completed Startup 2019-08-07T16:24:50.435Z,1565195090.435 [MissionManager](INFO): Startup is completed. 2019-08-07T16:24:50.435Z,1565195090.435 [MissionManager](INFO): Uninitializing Mission Startup 2019-08-07T16:24:50.435Z,1565195090.435 [Startup] Stopped 2019-08-07T16:24:50.435Z,1565195090.435 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-08-07T16:24:50.435Z,1565195090.435 [Startup:A.GoToSurface] Stopped 2019-08-07T16:24:50.436Z,1565195090.436 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-08-07T16:24:50.554Z,1565195090.554 [MissionManager](IMPORTANT): Started mission Default 2019-08-07T16:24:50.554Z,1565195090.554 [Default] Running Loop=1 2019-08-07T16:24:50.554Z,1565195090.554 [Default](DEBUG): Aggregate::initialize Default 2019-08-07T16:24:50.554Z,1565195090.554 [Default:B.GoToSurface] Running Loop=1 2019-08-07T16:24:50.554Z,1565195090.554 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-08-07T16:24:50.555Z,1565195090.555 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-08-07T16:24:50.555Z,1565195090.555 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-08-07T16:24:50.555Z,1565195090.555 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-08-07T16:24:50.556Z,1565195090.556 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-08-07T16:24:50.556Z,1565195090.556 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-08-07T16:24:50.556Z,1565195090.556 [Default:A.Wait] Running Loop=1 2019-08-07T16:24:50.556Z,1565195090.556 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-08-07T16:24:57.740Z,1565195097.740 [NAL9602](INFO): SBD MO Status=1, MOMSN=15869, MT Status=0, MTMSN=0 2019-08-07T16:24:57.787Z,1565195097.787 [NAL9602](INFO): Sent 99 bytes from file Logs/20190807T151639/Express0032.lzma 2019-08-07T16:24:57.787Z,1565195097.787 [NAL9602](INFO): Packets left to send: 0 2019-08-07T16:25:03.816Z,1565195103.816 [Default:A.Wait](INFO): Done Waiting. 2019-08-07T16:25:03.816Z,1565195103.816 [Default:A.Wait] Stopped 2019-08-07T16:25:03.816Z,1565195103.816 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-08-07T16:25:04.226Z,1565195104.226 [Default:CheckIn] Running Loop=1 2019-08-07T16:25:04.227Z,1565195104.227 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-07T16:25:04.227Z,1565195104.227 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-07T16:25:04.630Z,1565195104.630 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-08-07T16:25:05.825Z,1565195105.825 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:25:06.220Z,1565195106.220 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162458.00,A,3648.15607,N,12147.21957,W,0.525,14.32,070819,,,A*44 2019-08-07T16:25:06.222Z,1565195106.222 [NAL9602](INFO): GPS fix at 20190807T162458: (36.802601, -121.786993) 2019-08-07T16:25:06.247Z,1565195106.247 [Default:CheckIn:Read_GPS] Stopped 2019-08-07T16:25:06.247Z,1565195106.247 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-07T16:25:06.674Z,1565195106.674 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-08-07T16:25:30.970Z,1565195130.970 [NAL9602](INFO): SBD MO Status=1, MOMSN=15870, MT Status=0, MTMSN=0 2019-08-07T16:25:31.026Z,1565195131.026 [NAL9602](INFO): Sent 63 bytes from file Logs/20190807T162206/Courier0004.lzma 2019-08-07T16:25:31.026Z,1565195131.026 [NAL9602](INFO): Packets left to send: 0 2019-08-07T16:25:39.112Z,1565195139.112 [NAL9602](INFO): SBD MO Status=1, MOMSN=15871, MT Status=0, MTMSN=0 2019-08-07T16:25:39.166Z,1565195139.166 [NAL9602](INFO): Sent 332 bytes from file Logs/20190807T151639/Express0035.lzma 2019-08-07T16:25:39.166Z,1565195139.166 [NAL9602](INFO): Packets left to send: 1 2019-08-07T16:25:46.520Z,1565195146.520 [NAL9602](INFO): SBD MO Status=1, MOMSN=15872, MT Status=0, MTMSN=0 2019-08-07T16:25:46.574Z,1565195146.574 [NAL9602](INFO): Sent 23 bytes from file Logs/20190807T151639/Express0035.lzma 2019-08-07T16:25:46.574Z,1565195146.574 [NAL9602](INFO): Packets left to send: 0 2019-08-07T16:25:57.579Z,1565195157.579 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004736 2019-08-07T16:25:58.704Z,1565195158.704 [NAL9602](INFO): SBD MO Status=2, MOMSN=15873, MT Status=2, MTMSN=0 2019-08-07T16:25:58.704Z,1565195158.704 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:26:02.769Z,1565195162.769 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190807T151639/Express0038.lzma 2019-08-07T16:26:03.575Z,1565195163.575 [DataOverHttps](INFO): Moved sent file to Logs/20190807T151639/Express0038.lzma.bak 2019-08-07T16:26:03.575Z,1565195163.575 [DataOverHttps](INFO): SBD MOMSN=11534937 2019-08-07T16:26:14.713Z,1565195174.713 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190807T151639/Express0041.lzma 2019-08-07T16:26:15.519Z,1565195175.519 [DataOverHttps](INFO): Moved sent file to Logs/20190807T151639/Express0041.lzma.bak 2019-08-07T16:26:15.519Z,1565195175.519 [DataOverHttps](INFO): SBD MOMSN=11534941 2019-08-07T16:26:26.666Z,1565195186.666 [DataOverHttps](INFO): Sending 958 bytes from file Logs/20190807T151639/Express0044.lzma 2019-08-07T16:26:27.471Z,1565195187.471 [DataOverHttps](INFO): Moved sent file to Logs/20190807T151639/Express0044.lzma.bak 2019-08-07T16:26:27.472Z,1565195187.472 [DataOverHttps](INFO): SBD MOMSN=11534948 2019-08-07T16:26:29.415Z,1565195189.415 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-07T16:26:40.153Z,1565195200.153 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190807T151639/Express0047.lzma 2019-08-07T16:26:40.959Z,1565195200.959 [DataOverHttps](INFO): Moved sent file to Logs/20190807T151639/Express0047.lzma.bak 2019-08-07T16:26:40.959Z,1565195200.959 [DataOverHttps](INFO): SBD MOMSN=11534985 2019-08-07T16:26:52.246Z,1565195212.246 [DataOverHttps](INFO): Sending 890 bytes from file Logs/20190807T162206/Express0001.lzma 2019-08-07T16:26:53.051Z,1565195213.051 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Express0001.lzma.bak 2019-08-07T16:26:53.051Z,1565195213.051 [DataOverHttps](INFO): SBD MOMSN=11534987 2019-08-07T16:27:04.305Z,1565195224.305 [DataOverHttps](INFO): Sending 95 bytes from file Logs/20190807T162206/Express0005.lzma 2019-08-07T16:27:05.111Z,1565195225.111 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Express0005.lzma.bak 2019-08-07T16:27:05.112Z,1565195225.112 [DataOverHttps](INFO): SBD MOMSN=11535010 2019-08-07T16:27:05.790Z,1565195225.790 [Default:CheckIn:Read_Iridium] Stopped 2019-08-07T16:27:05.790Z,1565195225.790 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-07T16:27:05.790Z,1565195225.790 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-07T16:29:45.772Z,1565195385.772 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-08-07T16:29:45.775Z,1565195385.775 [BPC1](INFO): Received data from all battery sticks. 2019-08-07T16:32:06.385Z,1565195526.385 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-07T16:32:06.386Z,1565195526.386 [Default:CheckIn:C.Wait] Stopped 2019-08-07T16:32:06.386Z,1565195526.386 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-07T16:32:06.386Z,1565195526.386 [Default:CheckIn:D] Running Loop=1 2019-08-07T16:32:06.783Z,1565195526.783 [Default:CheckIn:D] Stopped 2019-08-07T16:32:06.784Z,1565195526.784 [Default:CheckIn:E] Running Loop=1 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.270487 min 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn:E] Stopped 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn] Stopped 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn](INFO): Running loop #2 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn] Running Loop=2 2019-08-07T16:32:07.198Z,1565195527.198 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-07T16:32:07.199Z,1565195527.199 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-07T16:32:08.794Z,1565195528.794 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:32:09.188Z,1565195529.188 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163202.00,A,3648.34063,N,12147.12371,W,4.587,2.03,070819,,,D*79 2019-08-07T16:32:09.191Z,1565195529.191 [NAL9602](INFO): GPS fix at 20190807T163202: (36.805677, -121.785395) 2019-08-07T16:32:09.246Z,1565195529.246 [Default:CheckIn:Read_GPS] Stopped 2019-08-07T16:32:09.246Z,1565195529.246 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-07T16:32:12.285Z,1565195532.285 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190807T162206/Courier0007.lzma 2019-08-07T16:32:13.091Z,1565195533.091 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Courier0007.lzma.bak 2019-08-07T16:32:13.091Z,1565195533.091 [DataOverHttps](INFO): SBD MOMSN=11535032 2019-08-07T16:32:24.049Z,1565195544.049 [DataOverHttps](INFO): Sending 166 bytes from file Logs/20190807T162206/Express0008.lzma 2019-08-07T16:32:24.855Z,1565195544.855 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Express0008.lzma.bak 2019-08-07T16:32:24.855Z,1565195544.855 [DataOverHttps](INFO): SBD MOMSN=11535035 2019-08-07T16:32:25.462Z,1565195545.462 [Default:CheckIn:Read_Iridium] Stopped 2019-08-07T16:32:25.462Z,1565195545.462 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-07T16:32:25.462Z,1565195545.462 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-07T16:32:32.332Z,1565195552.332 [NAL9602](INFO): SBD MO Status=2, MOMSN=15873, MT Status=2, MTMSN=0 2019-08-07T16:32:32.332Z,1565195552.332 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:32:56.316Z,1565195576.316 [CommandLine](IMPORTANT): got command gfscan 2019-08-07T16:32:56.639Z,1565195576.639 [CBIT](IMPORTANT): Beginning ground fault scan 2019-08-07T16:32:57.792Z,1565195577.792 [NAL9602](INFO): SBD MO Status=2, MOMSN=15873, MT Status=2, MTMSN=0 2019-08-07T16:32:57.792Z,1565195577.792 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:33:07.534Z,1565195587.534 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.006617 CHAN A1 (24V): -0.133350 CHAN A2 (12V): -0.002003 CHAN A3 (5V): -0.001424 CHAN B0 (3.3V): 0.000146 CHAN B1 (3.15aV): 0.000423 CHAN B2 (3.15bV): -0.000217 CHAN B3 (GND): 0.000458 OPEN: -0.000414 Full Scale Calc: 4.765 mA, -1.589 mA 2019-08-07T16:33:20.895Z,1565195600.895 [CommandLine](IMPORTANT): got command ! echo i > /dev/loadB2 2019-08-07T16:33:23.340Z,1565195603.340 [CommandLine](IMPORTANT): got command gfscan 2019-08-07T16:33:23.692Z,1565195603.692 [CBIT](IMPORTANT): Beginning ground fault scan 2019-08-07T16:33:32.140Z,1565195612.140 [NAL9602](INFO): SBD MO Status=1, MOMSN=15873, MT Status=0, MTMSN=0 2019-08-07T16:33:32.140Z,1565195612.140 [NAL9602](INFO): No messages in MT queue 2019-08-07T16:33:34.593Z,1565195614.593 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.006392 CHAN A1 (24V): -0.133743 CHAN A2 (12V): -0.002259 CHAN A3 (5V): -0.001447 CHAN B0 (3.3V): 0.000211 CHAN B1 (3.15aV): 0.000190 CHAN B2 (3.15bV): 0.000049 CHAN B3 (GND): 0.000143 OPEN: -0.000338 Full Scale Calc: 4.765 mA, -1.589 mA 2019-08-07T16:34:01.311Z,1565195641.311 [CommandLine](IMPORTANT): got command get CBIT.gf24Offset 2019-08-07T16:34:01.312Z,1565195641.312 [CommandLine](IMPORTANT): CBIT.gf24Offset 107.000000 uA 2019-08-07T16:34:02.835Z,1565195642.835 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-07T16:34:29.086Z,1565195669.086 [CommandLine](IMPORTANT): got command configSet CBIT.gf24Offset -28.000000 microampere persist 2019-08-07T16:34:39.870Z,1565195679.870 [CommandLine](IMPORTANT): got command gfscan 2019-08-07T16:34:40.087Z,1565195680.087 [CBIT](IMPORTANT): Beginning ground fault scan 2019-08-07T16:34:50.993Z,1565195690.993 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.006351 CHAN A1 (24V): 0.001310 CHAN A2 (12V): -0.002088 CHAN A3 (5V): -0.001541 CHAN B0 (3.3V): 0.000169 CHAN B1 (3.15aV): 0.000089 CHAN B2 (3.15bV): -0.000240 CHAN B3 (GND): 0.000352 OPEN: -0.000380 Full Scale Calc: 4.765 mA, -1.589 mA 2019-08-07T16:35:35.185Z,1565195735.185 [CommandLine](IMPORTANT): got command ibit 2019-08-07T16:35:35.421Z,1565195735.421 [IBIT](IMPORTANT): Beginning Initiated BIT 2019-08-07T16:35:35.422Z,1565195735.422 [IBIT](IMPORTANT): Beginning control surface checks. 2019-08-07T16:35:35.425Z,1565195735.425 [CBIT](IMPORTANT): Beginning ground fault scan 2019-08-07T16:35:36.617Z,1565195736.617 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:35:37.012Z,1565195737.012 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163529.00,A,3648.44375,N,12147.33688,W,12.207,242.81,070819,,,D*40 2019-08-07T16:35:37.015Z,1565195737.015 [NAL9602](INFO): GPS fix at 20190807T163529: (36.807396, -121.788948) 2019-08-07T16:35:46.339Z,1565195746.339 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.006361 CHAN A1 (24V): 0.001330 CHAN A2 (12V): -0.002215 CHAN A3 (5V): -0.001619 CHAN B0 (3.3V): -0.000511 CHAN B1 (3.15aV): 0.000017 CHAN B2 (3.15bV): -0.000416 CHAN B3 (GND): -0.000341 OPEN: -0.000348 Full Scale Calc: 4.765 mA, -1.589 mA 2019-08-07T16:35:59.636Z,1565195759.636 [NAL9602](INFO): SBD MO Status=2, MOMSN=15874, MT Status=2, MTMSN=0 2019-08-07T16:35:59.636Z,1565195759.636 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:36:21.891Z,1565195781.891 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 3 Latitude: 36.807396 Longitude: -121.788948 2019-08-07T16:36:22.293Z,1565195782.293 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 0.000000 Voltage: 0.000000 2019-08-07T16:36:22.293Z,1565195782.293 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah 2019-08-07T16:36:22.293Z,1565195782.293 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V 2019-08-07T16:36:22.680Z,1565195782.680 [NAL9602](INFO): SBD MO Status=1, MOMSN=15874, MT Status=0, MTMSN=0 2019-08-07T16:36:22.680Z,1565195782.680 [NAL9602](INFO): No messages in MT queue 2019-08-07T16:36:22.715Z,1565195782.715 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2019-08-07T16:36:22.715Z,1565195782.715 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2019-08-07T16:36:22.715Z,1565195782.715 [IBIT](IMPORTANT): Pressure:8.901306 PSI 2019-08-07T16:36:22.716Z,1565195782.716 [IBIT](IMPORTANT): Humidity:4.260774 % 2019-08-07T16:36:23.096Z,1565195783.096 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m 2019-08-07T16:36:23.097Z,1565195783.097 [IBIT](IMPORTANT): buoyancyNeutral: 200.000000 cc 2019-08-07T16:36:23.097Z,1565195783.097 [IBIT](IMPORTANT): massDefault: -0.400000 cm 2019-08-07T16:36:23.097Z,1565195783.097 [IBIT](IMPORTANT): stopDepth: 205.000000 m 2019-08-07T16:36:23.098Z,1565195783.098 [IBIT](IMPORTANT): abortDepth: 250.000000 m 2019-08-07T16:36:23.098Z,1565195783.098 [IBIT](IMPORTANT): IBIT PASSED 2019-08-07T16:36:53.395Z,1565195813.395 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-07T16:37:26.154Z,1565195846.154 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-07T16:37:26.154Z,1565195846.154 [Default:CheckIn:C.Wait] Stopped 2019-08-07T16:37:26.154Z,1565195846.154 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-07T16:37:26.154Z,1565195846.154 [Default:CheckIn:D] Running Loop=1 2019-08-07T16:37:26.546Z,1565195846.546 [Default:CheckIn:D] Stopped 2019-08-07T16:37:26.546Z,1565195846.546 [Default:CheckIn:E] Running Loop=1 2019-08-07T16:37:26.955Z,1565195846.955 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.599868 min 2019-08-07T16:37:26.955Z,1565195846.955 [Default:CheckIn:E] Stopped 2019-08-07T16:37:26.955Z,1565195846.955 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-07T16:37:26.955Z,1565195846.955 [Default:CheckIn] Stopped 2019-08-07T16:37:26.955Z,1565195846.955 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-07T16:37:26.955Z,1565195846.955 [Default:CheckIn](INFO): Running loop #3 2019-08-07T16:37:26.955Z,1565195846.955 [Default:CheckIn] Running Loop=3 2019-08-07T16:37:26.956Z,1565195846.956 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-07T16:37:26.956Z,1565195846.956 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-07T16:37:28.553Z,1565195848.553 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:37:28.957Z,1565195848.957 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163721.00,A,3648.26621,N,12147.92322,W,16.989,251.82,070819,,,D*4C 2019-08-07T16:37:28.959Z,1565195848.959 [NAL9602](INFO): GPS fix at 20190807T163721: (36.804437, -121.798720) 2019-08-07T16:37:29.006Z,1565195849.006 [Default:CheckIn:Read_GPS] Stopped 2019-08-07T16:37:29.006Z,1565195849.006 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-07T16:37:32.237Z,1565195852.237 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190807T162206/Courier0010.lzma 2019-08-07T16:37:33.043Z,1565195853.043 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Courier0010.lzma.bak 2019-08-07T16:37:33.043Z,1565195853.043 [DataOverHttps](INFO): SBD MOMSN=11535079 2019-08-07T16:37:43.986Z,1565195863.986 [DataOverHttps](INFO): Sending 1007 bytes from file Logs/20190807T162206/Express0011.lzma 2019-08-07T16:37:44.791Z,1565195864.791 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Express0011.lzma.bak 2019-08-07T16:37:44.791Z,1565195864.791 [DataOverHttps](INFO): SBD MOMSN=11535083 2019-08-07T16:37:45.275Z,1565195865.275 [Default:CheckIn:Read_Iridium] Stopped 2019-08-07T16:37:45.275Z,1565195865.275 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-07T16:37:45.275Z,1565195865.275 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-07T16:37:48.072Z,1565195868.072 [NAL9602](INFO): SBD MO Status=2, MOMSN=15875, MT Status=2, MTMSN=0 2019-08-07T16:37:48.072Z,1565195868.072 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:38:03.428Z,1565195883.428 [NAL9602](INFO): SBD MO Status=2, MOMSN=15875, MT Status=2, MTMSN=0 2019-08-07T16:38:03.428Z,1565195883.428 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:38:39.384Z,1565195919.384 [NAL9602](INFO): SBD MO Status=2, MOMSN=15875, MT Status=2, MTMSN=0 2019-08-07T16:38:39.384Z,1565195919.384 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:40:17.148Z,1565196017.148 [NAL9602](INFO): SBD MO Status=1, MOMSN=15875, MT Status=0, MTMSN=0 2019-08-07T16:40:17.148Z,1565196017.148 [NAL9602](INFO): No messages in MT queue 2019-08-07T16:40:47.866Z,1565196047.866 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-07T16:42:45.874Z,1565196165.874 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-07T16:42:45.874Z,1565196165.874 [Default:CheckIn:C.Wait] Stopped 2019-08-07T16:42:45.874Z,1565196165.874 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-07T16:42:45.874Z,1565196165.874 [Default:CheckIn:D] Running Loop=1 2019-08-07T16:42:46.285Z,1565196166.285 [Default:CheckIn:D] Stopped 2019-08-07T16:42:46.285Z,1565196166.285 [Default:CheckIn:E] Running Loop=1 2019-08-07T16:42:46.689Z,1565196166.689 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.928849 min 2019-08-07T16:42:46.689Z,1565196166.689 [Default:CheckIn:E] Stopped 2019-08-07T16:42:46.689Z,1565196166.689 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-07T16:42:46.689Z,1565196166.689 [Default:CheckIn] Stopped 2019-08-07T16:42:46.689Z,1565196166.689 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-07T16:42:46.690Z,1565196166.690 [Default:CheckIn](INFO): Running loop #4 2019-08-07T16:42:46.690Z,1565196166.690 [Default:CheckIn] Running Loop=4 2019-08-07T16:42:46.690Z,1565196166.690 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-07T16:42:46.690Z,1565196166.690 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-07T16:42:48.286Z,1565196168.286 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:42:48.680Z,1565196168.680 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164240.00,A,3647.94422,N,12149.84738,W,17.145,280.65,070819,,,D*44 2019-08-07T16:42:48.682Z,1565196168.682 [NAL9602](INFO): GPS fix at 20190807T164240: (36.799070, -121.830790) 2019-08-07T16:42:48.790Z,1565196168.790 [Default:CheckIn:Read_GPS] Stopped 2019-08-07T16:42:48.790Z,1565196168.790 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-07T16:42:52.317Z,1565196172.317 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190807T162206/Courier0013.lzma 2019-08-07T16:42:53.123Z,1565196173.123 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Courier0013.lzma.bak 2019-08-07T16:42:53.123Z,1565196173.123 [DataOverHttps](INFO): SBD MOMSN=11535124 2019-08-07T16:43:04.313Z,1565196184.313 [DataOverHttps](INFO): Sending 138 bytes from file Logs/20190807T162206/Express0014.lzma 2019-08-07T16:43:05.119Z,1565196185.119 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Express0014.lzma.bak 2019-08-07T16:43:05.119Z,1565196185.119 [DataOverHttps](INFO): SBD MOMSN=11535127 2019-08-07T16:43:05.775Z,1565196185.775 [Default:CheckIn:Read_Iridium] Stopped 2019-08-07T16:43:05.775Z,1565196185.775 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-07T16:43:05.775Z,1565196185.775 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-07T16:43:20.696Z,1565196200.696 [NAL9602](INFO): SBD MO Status=2, MOMSN=15876, MT Status=2, MTMSN=0 2019-08-07T16:43:20.696Z,1565196200.696 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-07T16:43:41.708Z,1565196221.708 [NAL9602](INFO): SBD MO Status=1, MOMSN=15876, MT Status=0, MTMSN=0 2019-08-07T16:43:41.708Z,1565196221.708 [NAL9602](INFO): No messages in MT queue 2019-08-07T16:44:12.401Z,1565196252.401 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-07T16:45:36.474Z,1565196336.474 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-08-07T16:48:06.367Z,1565196486.367 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-07T16:48:06.367Z,1565196486.367 [Default:CheckIn:C.Wait] Stopped 2019-08-07T16:48:06.367Z,1565196486.367 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-07T16:48:06.367Z,1565196486.367 [Default:CheckIn:D] Running Loop=1 2019-08-07T16:48:06.770Z,1565196486.770 [Default:CheckIn:D] Stopped 2019-08-07T16:48:06.770Z,1565196486.770 [Default:CheckIn:E] Running Loop=1 2019-08-07T16:48:07.174Z,1565196487.174 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.270262 min 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn:E] Stopped 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn] Stopped 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn](INFO): Running loop #5 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn] Running Loop=5 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-07T16:48:07.175Z,1565196487.175 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-07T16:48:08.774Z,1565196488.774 [NAL9602](DEBUG): Fix Requested 2019-08-07T16:48:09.168Z,1565196489.168 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164800.00,A,3648.01765,N,12150.10496,W,0.603,28.50,070819,,,D*4E 2019-08-07T16:48:09.171Z,1565196489.171 [NAL9602](INFO): GPS fix at 20190807T164800: (36.800294, -121.835083) 2019-08-07T16:48:09.245Z,1565196489.245 [Default:CheckIn:Read_GPS] Stopped 2019-08-07T16:48:09.245Z,1565196489.245 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-07T16:48:12.809Z,1565196492.809 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190807T162206/Courier0016.lzma 2019-08-07T16:48:13.615Z,1565196493.615 [DataOverHttps](INFO): Moved sent file to Logs/20190807T162206/Courier0016.lzma.bak 2019-08-07T16:48:13.615Z,1565196493.615 [DataOverHttps](IMPORTANT): SBD MOMSN=11535170, MTMSN=20190807T164805