2018-09-05T02:16:27.497Z,1536113787.497 [Supervisor](DEBUG): Initializing supervisor. 2018-09-05T02:16:27.499Z,1536113787.499 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2018-09-05T02:16:27.500Z,1536113787.500 [SyncHandler](INFO): Protected caller Thread ID is 5222 2018-09-05T02:16:27.500Z,1536113787.500 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2018-09-05T02:16:27.501Z,1536113787.501 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2018-09-05T02:16:27.502Z,1536113787.502 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5223 2018-09-05T02:16:27.505Z,1536113787.505 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2018-09-05T02:16:27.516Z,1536113787.516 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2018-09-05T02:16:27.517Z,1536113787.517 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2018-09-05T02:16:27.517Z,1536113787.517 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5224 2018-09-05T02:16:27.518Z,1536113787.518 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2018-09-05T02:16:27.519Z,1536113787.519 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2018-09-05T02:16:27.520Z,1536113787.520 [logger ThreadHandler](INFO): Protected caller Thread ID is 5225 2018-09-05T02:16:27.522Z,1536113787.522 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2018-09-05T02:16:27.522Z,1536113787.522 [Supervisor](INFO): Looking for Config files in directory: Config/ 2018-09-05T02:16:27.524Z,1536113787.524 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2018-09-05T02:16:27.882Z,1536113787.882 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2018-09-05T02:16:27.883Z,1536113787.883 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2018-09-05T02:16:28.092Z,1536113788.092 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2018-09-05T02:16:28.092Z,1536113788.092 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2018-09-05T02:16:28.574Z,1536113788.574 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2018-09-05T02:16:28.574Z,1536113788.574 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2018-09-05T02:16:28.680Z,1536113788.680 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2018-09-05T02:16:28.680Z,1536113788.680 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2018-09-05T02:16:28.900Z,1536113788.900 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2018-09-05T02:16:28.901Z,1536113788.901 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2018-09-05T02:16:29.044Z,1536113789.044 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2018-09-05T02:16:29.044Z,1536113789.044 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2018-09-05T02:16:29.401Z,1536113789.401 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2018-09-05T02:16:29.401Z,1536113789.401 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2018-09-05T02:16:29.489Z,1536113789.489 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2018-09-05T02:16:29.592Z,1536113789.592 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2018-09-05T02:16:29.593Z,1536113789.593 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2018-09-05T02:16:29.704Z,1536113789.704 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2018-09-05T02:16:29.705Z,1536113789.705 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2018-09-05T02:16:30.037Z,1536113790.037 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2018-09-05T02:16:30.037Z,1536113790.037 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2018-09-05T02:16:30.258Z,1536113790.258 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2018-09-05T02:16:30.258Z,1536113790.258 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2018-09-05T02:16:30.725Z,1536113790.725 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2018-09-05T02:16:30.725Z,1536113790.725 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2018-09-05T02:16:30.879Z,1536113790.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2018-09-05T02:16:30.879Z,1536113790.879 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2018-09-05T02:16:31.392Z,1536113791.392 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2018-09-05T02:16:31.394Z,1536113791.394 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/ 2018-09-05T02:16:31.395Z,1536113791.395 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Control.cfg 2018-09-05T02:16:31.507Z,1536113791.507 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Navigation.cfg 2018-09-05T02:16:31.604Z,1536113791.604 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg 2018-09-05T02:16:31.699Z,1536113791.699 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/logger.cfg 2018-09-05T02:16:31.824Z,1536113791.824 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Battery.cfg 2018-09-05T02:16:32.064Z,1536113792.064 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2018-09-05T02:16:32.065Z,1536113792.065 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg 2018-09-05T02:16:32.213Z,1536113792.213 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/secure.cfg 2018-09-05T02:16:32.302Z,1536113792.302 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg 2018-09-05T02:16:32.399Z,1536113792.399 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg 2018-09-05T02:16:32.503Z,1536113792.503 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg 2018-09-05T02:16:32.605Z,1536113792.605 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg 2018-09-05T02:16:32.757Z,1536113792.757 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg 2018-09-05T02:16:32.962Z,1536113792.962 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2018-09-05T02:16:32.967Z,1536113792.967 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2018-09-05T02:16:33.095Z,1536113793.095 [SBIT](DEBUG): Construct Startup Built In Test. 2018-09-05T02:16:33.126Z,1536113793.126 [SBIT] Loaded 2018-09-05T02:16:33.126Z,1536113793.126 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2018-09-05T02:16:33.127Z,1536113793.127 [IBIT](DEBUG): Construct Initiated Built In Test. 2018-09-05T02:16:33.154Z,1536113793.154 [IBIT] Loaded 2018-09-05T02:16:33.154Z,1536113793.154 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2018-09-05T02:16:33.158Z,1536113793.158 [CBIT](DEBUG): Construct Continuous Built In Test. 2018-09-05T02:16:33.314Z,1536113793.314 [CBIT] Loaded 2018-09-05T02:16:33.314Z,1536113793.314 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2018-09-05T02:16:33.315Z,1536113793.315 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2018-09-05T02:16:33.315Z,1536113793.315 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2018-09-05T02:16:33.339Z,1536113793.339 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2018-09-05T02:16:33.340Z,1536113793.340 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2018-09-05T02:16:33.530Z,1536113793.530 [CTD_Seabird] Loaded 2018-09-05T02:16:33.530Z,1536113793.530 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2018-09-05T02:16:33.531Z,1536113793.531 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 405B74E0 2018-09-05T02:16:33.532Z,1536113793.532 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 5307 2018-09-05T02:16:33.549Z,1536113793.549 [ESPComponent] Loaded 2018-09-05T02:16:33.550Z,1536113793.550 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2018-09-05T02:16:33.564Z,1536113793.564 [PAR_Licor] Loaded 2018-09-05T02:16:33.564Z,1536113793.564 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2018-09-05T02:16:33.614Z,1536113793.614 [WetLabsBB2FL] Loaded 2018-09-05T02:16:33.614Z,1536113793.614 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2018-09-05T02:16:33.615Z,1536113793.615 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 405E74E0 2018-09-05T02:16:33.615Z,1536113793.615 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5308 2018-09-05T02:16:33.616Z,1536113793.616 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2018-09-05T02:16:33.617Z,1536113793.617 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2018-09-05T02:16:33.723Z,1536113793.723 [BuoyancyServo] Loaded 2018-09-05T02:16:33.723Z,1536113793.723 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2018-09-05T02:16:33.738Z,1536113793.738 [ElevatorServo] Loaded 2018-09-05T02:16:33.738Z,1536113793.738 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2018-09-05T02:16:33.753Z,1536113793.753 [MassServo] Loaded 2018-09-05T02:16:33.753Z,1536113793.753 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2018-09-05T02:16:33.768Z,1536113793.768 [RudderServo] Loaded 2018-09-05T02:16:33.768Z,1536113793.768 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2018-09-05T02:16:33.783Z,1536113793.783 [ThrusterServo] Loaded 2018-09-05T02:16:33.783Z,1536113793.783 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2018-09-05T02:16:33.783Z,1536113793.783 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2018-09-05T02:16:33.784Z,1536113793.784 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2018-09-05T02:16:34.020Z,1536113794.020 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2018-09-05T02:16:34.021Z,1536113794.021 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2018-09-05T02:16:34.312Z,1536113794.312 [AHRS_M2] Loaded 2018-09-05T02:16:34.312Z,1536113794.312 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2018-09-05T02:16:34.382Z,1536113794.382 [DataOverHttps] Loaded 2018-09-05T02:16:34.382Z,1536113794.382 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2018-09-05T02:16:34.395Z,1536113794.395 [Depth_Keller] Loaded 2018-09-05T02:16:34.396Z,1536113794.396 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2018-09-05T02:16:34.401Z,1536113794.401 [DropWeight] Loaded 2018-09-05T02:16:34.401Z,1536113794.401 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2018-09-05T02:16:34.492Z,1536113794.492 [NAL9602] Loaded 2018-09-05T02:16:34.492Z,1536113794.492 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2018-09-05T02:16:34.497Z,1536113794.497 [Onboard] Loaded 2018-09-05T02:16:34.498Z,1536113794.498 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2018-09-05T02:16:34.504Z,1536113794.504 [Radio_Surface] Loaded 2018-09-05T02:16:34.505Z,1536113794.505 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2018-09-05T02:16:34.506Z,1536113794.506 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408CE4E0 2018-09-05T02:16:34.506Z,1536113794.506 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5309 2018-09-05T02:16:34.535Z,1536113794.535 [RDI_Pathfinder] Loaded 2018-09-05T02:16:34.535Z,1536113794.535 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2018-09-05T02:16:34.665Z,1536113794.665 [DAT] Loaded 2018-09-05T02:16:34.665Z,1536113794.665 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2018-09-05T02:16:36.479Z,1536113796.479 [BPC1] Loaded 2018-09-05T02:16:36.479Z,1536113796.479 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2018-09-05T02:16:36.480Z,1536113796.480 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2018-09-05T02:16:36.480Z,1536113796.480 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2018-09-05T02:16:36.495Z,1536113796.495 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2018-09-05T02:16:36.495Z,1536113796.495 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2018-09-05T02:16:36.607Z,1536113796.607 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC 2018-09-05T02:16:36.607Z,1536113796.607 [StratificationFrontDetector](DEBUG): (re)initializing 2018-09-05T02:16:36.607Z,1536113796.607 [StratificationFrontDetector] Loaded 2018-09-05T02:16:36.607Z,1536113796.607 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread. 2018-09-05T02:16:36.608Z,1536113796.608 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2018-09-05T02:16:36.608Z,1536113796.608 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2018-09-05T02:16:36.708Z,1536113796.708 [DeadReckonUsingMultipleVelocitySources] Loaded 2018-09-05T02:16:36.708Z,1536113796.708 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2018-09-05T02:16:36.764Z,1536113796.764 [DeadReckonUsingSpeedCalculator] Loaded 2018-09-05T02:16:36.764Z,1536113796.764 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2018-09-05T02:16:36.780Z,1536113796.780 [NavChart] Loaded 2018-09-05T02:16:36.780Z,1536113796.780 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2018-09-05T02:16:36.784Z,1536113796.784 [UniversalFixResidualReporter] Loaded 2018-09-05T02:16:36.785Z,1536113796.785 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2018-09-05T02:16:36.785Z,1536113796.785 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2018-09-05T02:16:36.786Z,1536113796.786 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2018-09-05T02:16:36.886Z,1536113796.886 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2018-09-05T02:16:36.886Z,1536113796.886 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2018-09-05T02:16:36.954Z,1536113796.954 [VerticalControl](DEBUG): Construct VerticalControl. 2018-09-05T02:16:37.042Z,1536113797.042 [VerticalControl] Loaded 2018-09-05T02:16:37.043Z,1536113797.043 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2018-09-05T02:16:37.043Z,1536113797.043 [HorizontalControl](DEBUG): Construct HorizontalControl. 2018-09-05T02:16:37.102Z,1536113797.102 [HorizontalControl] Loaded 2018-09-05T02:16:37.102Z,1536113797.102 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2018-09-05T02:16:37.103Z,1536113797.103 [SpeedControl](DEBUG): Construct SpeedControl. 2018-09-05T02:16:37.105Z,1536113797.105 [SpeedControl] Loaded 2018-09-05T02:16:37.105Z,1536113797.105 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2018-09-05T02:16:37.106Z,1536113797.106 [LoopControl](DEBUG): Construct LoopControl. 2018-09-05T02:16:37.106Z,1536113797.106 [LoopControl] Loaded 2018-09-05T02:16:37.107Z,1536113797.107 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2018-09-05T02:16:37.107Z,1536113797.107 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2018-09-05T02:16:37.108Z,1536113797.108 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2018-09-05T02:16:37.149Z,1536113797.149 [DepthRateCalculator] Loaded 2018-09-05T02:16:37.149Z,1536113797.149 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2018-09-05T02:16:37.154Z,1536113797.154 [PitchRateCalculator] Loaded 2018-09-05T02:16:37.155Z,1536113797.155 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2018-09-05T02:16:37.167Z,1536113797.167 [SpeedCalculator] Loaded 2018-09-05T02:16:37.167Z,1536113797.167 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2018-09-05T02:16:37.188Z,1536113797.188 [TempGradientCalculator] Loaded 2018-09-05T02:16:37.189Z,1536113797.189 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2018-09-05T02:16:37.201Z,1536113797.201 [VerticalTemperatureHomogeneityIndexCalculator] Loaded 2018-09-05T02:16:37.201Z,1536113797.201 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread. 2018-09-05T02:16:37.206Z,1536113797.206 [YawRateCalculator] Loaded 2018-09-05T02:16:37.206Z,1536113797.206 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2018-09-05T02:16:37.237Z,1536113797.237 [ElevatorOffsetCalculator] Loaded 2018-09-05T02:16:37.237Z,1536113797.237 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2018-09-05T02:16:37.238Z,1536113797.238 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2018-09-05T02:16:37.241Z,1536113797.241 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2018-09-05T02:16:37.242Z,1536113797.242 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2018-09-05T02:16:37.249Z,1536113797.249 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2018-09-05T02:16:37.250Z,1536113797.250 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A064E0 2018-09-05T02:16:37.250Z,1536113797.250 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5310 2018-09-05T02:16:37.255Z,1536113797.255 [Supervisor](INFO): Main Thread ID is 795 2018-09-05T02:16:37.255Z,1536113797.255 [Supervisor](DEBUG): Running supervisor. 2018-09-05T02:16:37.256Z,1536113797.256 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5311 2018-09-05T02:16:37.258Z,1536113797.258 [controlThread ThreadHandler](INFO): Handler Thread ID is 5312 2018-09-05T02:16:37.259Z,1536113797.259 [controlThread](DEBUG): Initializing ControlThread 2018-09-05T02:16:37.259Z,1536113797.259 [SBIT](INFO): Initialize SBIT Component. 2018-09-05T02:16:37.260Z,1536113797.260 [SBIT](IMPORTANT): git: 2018-09-04 2018-09-05T02:16:37.260Z,1536113797.260 [SBIT](INFO): git hash: ec53a78724503e2fb746f629f4029aa8924f623d 2018-09-05T02:16:37.261Z,1536113797.261 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2018-09-05T02:16:37.262Z,1536113797.262 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014 Kernel Reported: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 2018-09-05T02:16:37.263Z,1536113797.263 [SBIT](INFO): Beginning SBIT in 28.000000 seconds. 2018-09-05T02:16:37.264Z,1536113797.264 [IBIT](INFO): Initialize IBIT Component. 2018-09-05T02:16:37.265Z,1536113797.265 [CBIT](DEBUG): Initialize CBIT Component. 2018-09-05T02:16:37.265Z,1536113797.265 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2018-09-05T02:16:37.266Z,1536113797.266 [logger ThreadHandler](INFO): Handler Thread ID is 5313 2018-09-05T02:16:37.291Z,1536113797.291 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 5314 2018-09-05T02:16:37.292Z,1536113797.292 [CTD_Seabird](INFO): Initializing 2018-09-05T02:16:37.292Z,1536113797.292 [CTD_Seabird](INFO): Checking LCM 2018-09-05T02:16:37.301Z,1536113797.301 [CTD_Seabird](INFO): LCM OK 2018-09-05T02:16:37.301Z,1536113797.301 [CTD_Seabird](INFO): Powering up 2018-09-05T02:16:37.308Z,1536113797.308 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5315 2018-09-05T02:16:37.309Z,1536113797.309 [WetLabsBB2FL](INFO): Powering down 2018-09-05T02:16:37.335Z,1536113797.335 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5316 2018-09-05T02:16:37.341Z,1536113797.341 [Radio_Surface](INFO): Powering up 2018-09-05T02:16:37.355Z,1536113797.355 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5317 2018-09-05T02:16:37.361Z,1536113797.361 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2018-09-05T02:16:37.361Z,1536113797.361 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2018-09-05T02:16:37.361Z,1536113797.361 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2018-09-05T02:16:37.362Z,1536113797.362 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2018-09-05T02:16:37.362Z,1536113797.362 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2018-09-05T02:16:37.362Z,1536113797.362 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2018-09-05T02:16:37.362Z,1536113797.362 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2018-09-05T02:16:37.362Z,1536113797.362 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2018-09-05T02:16:37.363Z,1536113797.363 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2018-09-05T02:16:37.363Z,1536113797.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2018-09-05T02:16:37.363Z,1536113797.363 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2018-09-05T02:16:37.363Z,1536113797.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2018-09-05T02:16:37.363Z,1536113797.363 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2018-09-05T02:16:37.364Z,1536113797.364 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2018-09-05T02:16:37.364Z,1536113797.364 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2018-09-05T02:16:37.364Z,1536113797.364 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2018-09-05T02:16:37.386Z,1536113797.386 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-09-05T02:16:37.391Z,1536113797.391 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-09-05T02:16:37.391Z,1536113797.391 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-09-05T02:16:37.392Z,1536113797.392 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-09-05T02:16:37.392Z,1536113797.392 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-09-05T02:16:37.393Z,1536113797.393 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-09-05T02:16:37.393Z,1536113797.393 [NavChart](DEBUG): Initialize NavChart Navigation. 2018-09-05T02:16:37.394Z,1536113797.394 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2018-09-05T02:16:37.394Z,1536113797.394 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2018-09-05T02:16:37.404Z,1536113797.404 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2018-09-05T02:16:37.405Z,1536113797.405 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2018-09-05T02:16:37.405Z,1536113797.405 [LoopControl](DEBUG): Initialize LoopControlComponent. 2018-09-05T02:16:37.406Z,1536113797.406 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-09-05T02:16:37.406Z,1536113797.406 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2018-09-05T02:16:37.407Z,1536113797.407 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2018-09-05T02:16:37.407Z,1536113797.407 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2018-09-05T02:16:37.408Z,1536113797.408 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing 2018-09-05T02:16:37.409Z,1536113797.409 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2018-09-05T02:16:37.409Z,1536113797.409 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2018-09-05T02:16:37.410Z,1536113797.410 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2018-09-05T02:16:37.446Z,1536113797.446 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2018-09-05T02:16:37.481Z,1536113797.481 [MissionManager](DEBUG): 2018-09-05T02:16:37.482Z,1536113797.482 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2018-09-05T02:16:37.577Z,1536113797.577 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2018-09-05T02:16:37.578Z,1536113797.578 [Default:A.Wait](DEBUG): Construct Wait. 2018-09-05T02:16:37.580Z,1536113797.580 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2018-09-05T02:16:37.602Z,1536113797.602 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2018-09-05T02:16:37.625Z,1536113797.625 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2018-09-05T02:16:37.630Z,1536113797.630 [Default:E.Execute](DEBUG): Construct Execute. 2018-09-05T02:16:37.650Z,1536113797.650 [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 2018-09-05T02:16:37.660Z,1536113797.660 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,RDI_Pathfinder,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-09-05T02:16:37.823Z,1536113797.823 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2018-09-05T02:16:37.887Z,1536113797.887 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2018-09-05T02:16:37.920Z,1536113797.920 [Depth_Keller](ERROR): Pressure reading out of range: 2102.507080 decibar 2018-09-05T02:16:38.011Z,1536113798.011 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2018-09-05T02:16:38.011Z,1536113798.011 [DAT](INFO): Powering up 2018-09-05T02:16:38.011Z,1536113798.011 [DAT](DEBUG): Initializing DAT. 2018-09-05T02:16:38.055Z,1536113798.055 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2018-09-05T02:16:38.187Z,1536113798.187 [DepthRateCalculator](ERROR): Depth measurement is not active 2018-09-05T02:16:38.287Z,1536113798.287 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:38.312Z,1536113798.312 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:38.436Z,1536113798.436 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-09-05T02:16:38.443Z,1536113798.443 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-09-05T02:16:38.466Z,1536113798.466 [ElevatorServo](DEBUG): Initializing EZServoServo. 2018-09-05T02:16:38.475Z,1536113798.475 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2018-09-05T02:16:38.489Z,1536113798.489 [MassServo](DEBUG): Initializing EZServoServo. 2018-09-05T02:16:38.495Z,1536113798.495 [MassServo](DEBUG): Initializing MassServo. 2018-09-05T02:16:38.513Z,1536113798.513 [RudderServo](DEBUG): Initializing EZServoServo. 2018-09-05T02:16:38.519Z,1536113798.519 [RudderServo](DEBUG): Initializing RudderServo. 2018-09-05T02:16:38.533Z,1536113798.533 [ThrusterServo](DEBUG): Initializing EZServoServo. 2018-09-05T02:16:38.539Z,1536113798.539 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2018-09-05T02:16:38.855Z,1536113798.855 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:38.856Z,1536113798.856 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:39.079Z,1536113799.079 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:39.081Z,1536113799.081 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:39.559Z,1536113799.559 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:39.560Z,1536113799.560 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:39.943Z,1536113799.943 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:39.944Z,1536113799.944 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:40.343Z,1536113800.343 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:40.344Z,1536113800.344 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:40.743Z,1536113800.743 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:40.744Z,1536113800.744 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:41.179Z,1536113801.179 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:41.180Z,1536113801.180 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:41.583Z,1536113801.583 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:41.584Z,1536113801.584 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:41.951Z,1536113801.951 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:41.952Z,1536113801.952 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-09-05T02:16:42.928Z,1536113802.928 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-09-05T02:16:43.033Z,1536113803.033 [CTD_Seabird](INFO): Started Seabird LCM interface with command:nohup ./lrauv-framework/onboard/bin/gpctd -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyC6 -b 9600 >& /dev/null & 2018-09-05T02:16:43.080Z,1536113803.080 [CTD_Seabird](INFO): LCM subscribed to channel:seabird_gpctd_t.seabird-gpctd 2018-09-05T02:16:43.657Z,1536113803.657 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-09-05T02:16:43.658Z,1536113803.658 [CTD_Seabird](INFO): Powering down 2018-09-05T02:16:51.570Z,1536113811.570 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2018-09-05T02:16:57.138Z,1536113817.138 [DAT](INFO): setting local address to 6 2018-09-05T02:16:57.550Z,1536113817.550 [DAT](INFO): set local address to 6 2018-09-05T02:17:04.737Z,1536113824.737 [NAL9602](INFO): Powering up NAL9602 2018-09-05T02:17:05.995Z,1536113825.995 [SBIT](IMPORTANT): Beginning Startup BIT 2018-09-05T02:17:05.999Z,1536113825.999 [CBIT](IMPORTANT): Beginning ground fault scan 2018-09-05T02:17:15.665Z,1536113835.665 [NAL9602](INFO): NAL9602 initialized 2018-09-05T02:17:16.993Z,1536113836.993 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.009980 CHAN A1 (24V): 0.181374 CHAN A2 (12V): -0.004642 CHAN A3 (5V): -0.003117 CHAN B0 (3.3V): -0.001284 CHAN B1 (3.15aV): -0.000873 CHAN B2 (3.15bV): -0.001494 CHAN B3 (GND): -0.000654 OPEN: 0.005205 Full Scale Calc: 4.765 mA, -1.589 mA 2018-09-05T02:17:30.283Z,1536113850.283 [NAL9602](INFO): SBD MO Status=0, MOMSN=48184, MT Status=0, MTMSN=0 2018-09-05T02:17:30.283Z,1536113850.283 [NAL9602](INFO): No messages in MT queue 2018-09-05T02:18:00.064Z,1536113880.064 [SBIT](IMPORTANT): SBIT PASSED 2018-09-05T02:18:00.107Z,1536113880.107 [CommandLine](IMPORTANT): got command configSet list 2018-09-05T02:18:00.107Z,1536113880.107 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2018-09-05T02:18:00.108Z,1536113880.108 [CommandLine](IMPORTANT): 2018-09-05T02:18:00.108Z,1536113880.108 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool; 2018-09-05T02:18:00.108Z,1536113880.108 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=10 minute; 2018-09-05T02:18:00.108Z,1536113880.108 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool; 2018-09-05T02:18:00.454Z,1536113880.454 [MissionManager](IMPORTANT): Started mission Startup 2018-09-05T02:18:00.454Z,1536113880.454 [Startup] Running Loop=1 2018-09-05T02:18:00.454Z,1536113880.454 [Startup](DEBUG): Aggregate::initialize Startup 2018-09-05T02:18:00.454Z,1536113880.454 [Startup:A.GoToSurface] Running Loop=1 2018-09-05T02:18:00.454Z,1536113880.454 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-09-05T02:18:00.455Z,1536113880.455 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-09-05T02:18:00.456Z,1536113880.456 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-09-05T02:18:00.456Z,1536113880.456 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-09-05T02:18:00.456Z,1536113880.456 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-09-05T02:18:00.457Z,1536113880.457 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-09-05T02:18:00.483Z,1536113880.483 [Startup:StartupSatComms] Running Loop=1 2018-09-05T02:18:00.483Z,1536113880.483 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2018-09-05T02:18:00.483Z,1536113880.483 [Startup:StartupSatComms:A] Running Loop=1 2018-09-05T02:18:00.849Z,1536113880.849 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2018-09-05T02:19:00.865Z,1536113940.865 [Startup:StartupSatComms:A](INFO): Timed out from 2018-09-05T02:18:00.5Z 2018-09-05T02:19:00.865Z,1536113940.865 [Startup:StartupSatComms:A] Stopped 2018-09-05T02:19:00.865Z,1536113940.865 [Startup:StartupSatComms:B] Running Loop=1 2018-09-05T02:19:01.227Z,1536113941.227 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-09-05T02:19:18.538Z,1536113958.538 [NAL9602](INFO): SBD MO Status=1, MOMSN=48185, MT Status=0, MTMSN=0 2018-09-05T02:19:18.595Z,1536113958.595 [NAL9602](INFO): Sent 25 bytes from file Logs/20180904T201556/Courier0084.lzma 2018-09-05T02:19:18.595Z,1536113958.595 [NAL9602](INFO): Packets left to send: 0 2018-09-05T02:19:18.597Z,1536113958.597 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180904T201556/Courier0084.lzma.parts/0000.sbd 2018-09-05T02:19:18.597Z,1536113958.597 [NAL9602](DEBUG): Completed sending Logs/20180904T201556/Courier0084.lzma 2018-09-05T02:19:22.709Z,1536113962.709 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2018-09-05T02:19:30.284Z,1536113970.284 [NAL9602](INFO): SBD MO Status=1, MOMSN=48186, MT Status=0, MTMSN=0 2018-09-05T02:19:30.337Z,1536113970.337 [NAL9602](INFO): Sent 133 bytes from file Logs/20180904T201556/Express0085.lzma 2018-09-05T02:19:30.337Z,1536113970.337 [NAL9602](INFO): Packets left to send: 0 2018-09-05T02:19:30.340Z,1536113970.340 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180904T201556/Express0085.lzma.parts/0000.sbd 2018-09-05T02:19:30.340Z,1536113970.340 [NAL9602](DEBUG): Completed sending Logs/20180904T201556/Express0085.lzma 2018-09-05T02:19:37.673Z,1536113977.673 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-09-05T02:19:37.673Z,1536113977.673 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2018-09-05T02:19:37.673Z,1536113977.673 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2018-09-05T02:19:37.675Z,1536113977.675 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-09-05T02:19:37.675Z,1536113977.675 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1 2018-09-05T02:19:37.675Z,1536113977.675 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault 2018-09-05T02:19:37.698Z,1536113977.698 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2018-09-05T02:19:37.698Z,1536113977.698 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator 2018-09-05T02:19:38.077Z,1536113978.077 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2018-09-05T02:19:38.077Z,1536113978.077 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2018-09-05T02:19:38.078Z,1536113978.078 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator 2018-09-05T02:19:38.078Z,1536113978.078 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1 2018-09-05T02:19:38.463Z,1536113978.463 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-09-05T02:19:38.463Z,1536113978.463 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-09-05T02:19:38.464Z,1536113978.464 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-09-05T02:19:38.464Z,1536113978.464 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-09-05T02:19:38.465Z,1536113978.465 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-09-05T02:19:38.465Z,1536113978.465 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-09-05T02:19:38.873Z,1536113978.873 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.2 s old, using for 20.0 s. 2018-09-05T02:19:39.265Z,1536113979.265 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.6 s old, using for 20.0 s. 2018-09-05T02:19:39.669Z,1536113979.669 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.0 s old, using for 20.0 s. 2018-09-05T02:19:40.078Z,1536113980.078 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.4 s old, using for 20.0 s. 2018-09-05T02:19:40.447Z,1536113980.447 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.8 s old, using for 20.0 s. 2018-09-05T02:19:40.853Z,1536113980.853 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.2 s old, using for 20.0 s. 2018-09-05T02:19:41.222Z,1536113981.222 [NAL9602](INFO): SBD MO Status=1, MOMSN=48187, MT Status=0, MTMSN=0 2018-09-05T02:19:41.272Z,1536113981.272 [NAL9602](INFO): Sent 332 bytes from file Logs/20180905T021627/Express0001.lzma 2018-09-05T02:19:41.272Z,1536113981.272 [NAL9602](INFO): Packets left to send: 2 2018-09-05T02:19:41.275Z,1536113981.275 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T021627/Express0001.lzma.parts/0002.sbd 2018-09-05T02:19:41.306Z,1536113981.306 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.6 s old, using for 20.0 s. 2018-09-05T02:19:41.783Z,1536113981.783 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.1 s old, using for 20.0 s. 2018-09-05T02:19:42.048Z,1536113982.048 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.4 s old, using for 20.0 s. 2018-09-05T02:19:44.495Z,1536113984.495 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.8 s old, using for 20.0 s. 2018-09-05T02:19:44.601Z,1536113984.601 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.9 s old, using for 20.0 s. 2018-09-05T02:19:44.962Z,1536113984.962 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.3 s old, using for 20.0 s. 2018-09-05T02:19:45.366Z,1536113985.366 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.7 s old, using for 20.0 s. 2018-09-05T02:19:45.769Z,1536113985.769 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.1 s old, using for 20.0 s. 2018-09-05T02:19:46.158Z,1536113986.158 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.5 s old, using for 20.0 s. 2018-09-05T02:19:46.574Z,1536113986.574 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.9 s old, using for 20.0 s. 2018-09-05T02:19:46.969Z,1536113986.969 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.3 s old, using for 20.0 s. 2018-09-05T02:19:47.367Z,1536113987.367 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.7 s old, using for 20.0 s. 2018-09-05T02:19:47.772Z,1536113987.772 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.1 s old, using for 20.0 s. 2018-09-05T02:19:48.168Z,1536113988.168 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.5 s old, using for 20.0 s. 2018-09-05T02:19:48.618Z,1536113988.618 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.9 s old, using for 20.0 s. 2018-09-05T02:19:49.014Z,1536113989.014 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.3 s old, using for 20.0 s. 2018-09-05T02:19:49.371Z,1536113989.371 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.7 s old, using for 20.0 s. 2018-09-05T02:19:49.809Z,1536113989.809 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.1 s old, using for 20.0 s. 2018-09-05T02:19:50.170Z,1536113990.170 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.5 s old, using for 20.0 s. 2018-09-05T02:19:50.575Z,1536113990.575 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.9 s old, using for 20.0 s. 2018-09-05T02:19:50.981Z,1536113990.981 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.3 s old, using for 20.0 s. 2018-09-05T02:19:51.378Z,1536113991.378 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.7 s old, using for 20.0 s. 2018-09-05T02:19:51.784Z,1536113991.784 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.1 s old, using for 20.0 s. 2018-09-05T02:19:52.134Z,1536113992.134 [NAL9602](INFO): SBD MO Status=1, MOMSN=48188, MT Status=0, MTMSN=0 2018-09-05T02:19:52.191Z,1536113992.191 [NAL9602](INFO): Sent 332 bytes from file Logs/20180905T021627/Express0001.lzma 2018-09-05T02:19:52.191Z,1536113992.191 [NAL9602](INFO): Packets left to send: 1 2018-09-05T02:19:52.193Z,1536113992.193 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T021627/Express0001.lzma.parts/0001.sbd 2018-09-05T02:19:52.265Z,1536113992.265 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.6 s old, using for 20.0 s. 2018-09-05T02:19:52.702Z,1536113992.702 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.0 s old, using for 20.0 s. 2018-09-05T02:19:55.001Z,1536113995.001 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.3 s old, using for 20.0 s. 2018-09-05T02:19:55.112Z,1536113995.112 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.4 s old, using for 20.0 s. 2018-09-05T02:19:55.517Z,1536113995.517 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.8 s old, using for 20.0 s. 2018-09-05T02:19:55.908Z,1536113995.908 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.2 s old, using for 20.0 s. 2018-09-05T02:19:56.306Z,1536113996.306 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.6 s old, using for 20.0 s. 2018-09-05T02:19:56.728Z,1536113996.728 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.1 s old, using for 20.0 s. 2018-09-05T02:19:57.109Z,1536113997.109 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.4 s old, using for 20.0 s. 2018-09-05T02:19:57.543Z,1536113997.543 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.9 s old, using for 20.0 s. 2018-09-05T02:20:01.132Z,1536114001.132 [Startup:StartupSatComms:B](INFO): Timed out from 2018-09-05T02:19:00.9Z 2018-09-05T02:20:01.132Z,1536114001.132 [Startup:StartupSatComms:B] Stopped 2018-09-05T02:20:01.133Z,1536114001.133 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2018-09-05T02:20:01.133Z,1536114001.133 [Startup:StartupSatComms] Stopped 2018-09-05T02:20:01.133Z,1536114001.133 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2018-09-05T02:20:01.134Z,1536114001.134 [Startup](INFO): Completed Startup 2018-09-05T02:20:01.134Z,1536114001.134 [MissionManager](INFO): Startup is completed. 2018-09-05T02:20:01.134Z,1536114001.134 [MissionManager](INFO): Uninitializing Mission Startup 2018-09-05T02:20:01.134Z,1536114001.134 [Startup] Stopped 2018-09-05T02:20:01.151Z,1536114001.151 [Startup](DEBUG): Aggregate::uninitialize Startup 2018-09-05T02:20:01.151Z,1536114001.151 [Startup:A.GoToSurface] Stopped 2018-09-05T02:20:01.151Z,1536114001.151 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-09-05T02:20:01.528Z,1536114001.528 [MissionManager](IMPORTANT): Started mission Default 2018-09-05T02:20:01.529Z,1536114001.529 [Default] Running Loop=1 2018-09-05T02:20:01.529Z,1536114001.529 [Default](DEBUG): Aggregate::initialize Default 2018-09-05T02:20:01.529Z,1536114001.529 [Default:B.GoToSurface] Running Loop=1 2018-09-05T02:20:01.529Z,1536114001.529 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-09-05T02:20:01.529Z,1536114001.529 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-09-05T02:20:01.530Z,1536114001.530 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-09-05T02:20:01.530Z,1536114001.530 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-09-05T02:20:01.530Z,1536114001.530 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-09-05T02:20:01.531Z,1536114001.531 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-09-05T02:20:01.531Z,1536114001.531 [Default:A.Wait] Running Loop=1 2018-09-05T02:20:01.531Z,1536114001.531 [Default:A.Wait](DEBUG): Initialize Wait Component. 2018-09-05T02:20:02.271Z,1536114002.271 [NAL9602](INFO): SBD MO Status=1, MOMSN=48189, MT Status=0, MTMSN=0 2018-09-05T02:20:02.323Z,1536114002.323 [NAL9602](INFO): Sent 5 bytes from file Logs/20180905T021627/Express0001.lzma 2018-09-05T02:20:02.323Z,1536114002.323 [NAL9602](INFO): Packets left to send: 0 2018-09-05T02:20:02.324Z,1536114002.324 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T021627/Express0001.lzma.parts/0000.sbd 2018-09-05T02:20:02.325Z,1536114002.325 [NAL9602](DEBUG): Completed sending Logs/20180905T021627/Express0001.lzma 2018-09-05T02:20:03.474Z,1536114003.474 [NAL9602](INFO): GPS fix at 20180905T022002: (36.779028, -121.900710) 2018-09-05T02:20:14.729Z,1536114014.729 [Default:A.Wait](INFO): Done Waiting. 2018-09-05T02:20:14.729Z,1536114014.729 [Default:A.Wait] Stopped 2018-09-05T02:20:14.729Z,1536114014.729 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2018-09-05T02:20:15.129Z,1536114015.129 [Default:CheckIn] Running Loop=1 2018-09-05T02:20:15.129Z,1536114015.129 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-09-05T02:20:15.129Z,1536114015.129 [Default:CheckIn:Read_GPS] Running Loop=1 2018-09-05T02:20:15.541Z,1536114015.541 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2018-09-05T02:20:17.614Z,1536114017.614 [NAL9602](INFO): GPS fix at 20180905T022016: (36.778997, -121.900701) 2018-09-05T02:20:17.980Z,1536114017.980 [Default:CheckIn:Read_GPS] Stopped 2018-09-05T02:20:17.981Z,1536114017.981 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-09-05T02:20:18.537Z,1536114018.537 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-09-05T02:20:33.249Z,1536114033.249 [NAL9602](INFO): SBD MO Status=1, MOMSN=48190, MT Status=0, MTMSN=0 2018-09-05T02:20:33.299Z,1536114033.299 [NAL9602](INFO): Sent 212 bytes from file Logs/20180905T021627/Courier0004.lzma 2018-09-05T02:20:33.299Z,1536114033.299 [NAL9602](INFO): Packets left to send: 0 2018-09-05T02:20:33.301Z,1536114033.301 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T021627/Courier0004.lzma.parts/0000.sbd 2018-09-05T02:20:33.301Z,1536114033.301 [NAL9602](DEBUG): Completed sending Logs/20180905T021627/Courier0004.lzma 2018-09-05T02:20:42.009Z,1536114042.009 [NAL9602](INFO): SBD MO Status=1, MOMSN=48191, MT Status=0, MTMSN=0 2018-09-05T02:20:42.063Z,1536114042.063 [NAL9602](INFO): Sent 228 bytes from file Logs/20180905T021627/Express0005.lzma 2018-09-05T02:20:42.063Z,1536114042.063 [NAL9602](INFO): Packets left to send: 0 2018-09-05T02:20:42.065Z,1536114042.065 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180905T021627/Express0005.lzma.parts/0000.sbd 2018-09-05T02:20:42.065Z,1536114042.065 [NAL9602](DEBUG): Completed sending Logs/20180905T021627/Express0005.lzma 2018-09-05T02:20:50.816Z,1536114050.816 [NAL9602](INFO): SBD MO Status=0, MOMSN=48192, MT Status=0, MTMSN=0 2018-09-05T02:20:50.931Z,1536114050.931 [Default:CheckIn:Read_Iridium] Stopped 2018-09-05T02:20:50.931Z,1536114050.931 [Default:CheckIn:C.Wait] Running Loop=1 2018-09-05T02:20:50.931Z,1536114050.931 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-09-05T02:21:21.417Z,1536114081.417 [NAL9602](INFO): Powering down 2018-09-05T02:21:51.838Z,1536114111.838 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T022150 2018-09-05T02:21:51.841Z,1536114111.841 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003696 2018-09-05T02:22:11.274Z,1536114131.274 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2018-09-05T02:22:11.274Z,1536114131.274 [RDI_Pathfinder](ERROR): Failed to parse: :TS,18090502232164,35.0, -0.1, 0.0,1448.9I,-32768,-32768,-32768,-32768,V 2018-09-05T02:22:11.702Z,1536114131.702 [DataOverHttps](INFO): Received command:configSet logExpress none mass_concentration_of_chlorophyll_in_sea_water persist 2018-09-05T02:22:15.322Z,1536114135.322 [CommandLine](IMPORTANT): got command configSet Express none mass_concentration_of_chlorophyll_in_sea_water persist 2018-09-05T02:25:14.962Z,1536114314.962 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T022513 2018-09-05T02:25:27.491Z,1536114327.491 [DataOverHttps](INFO): Received command:configset list 2018-09-05T02:25:27.551Z,1536114327.551 [CommandLine](IMPORTANT): got command configSet list 2018-09-05T02:25:27.551Z,1536114327.551 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2018-09-05T02:25:27.552Z,1536114327.552 [CommandLine](IMPORTANT): 2018-09-05T02:25:27.552Z,1536114327.552 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool; 2018-09-05T02:25:27.552Z,1536114327.552 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=10 minute; 2018-09-05T02:25:27.553Z,1536114327.553 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool; 2018-09-05T02:25:27.553Z,1536114327.553 [CommandLine](IMPORTANT): Express none mass_concentration_of_chlorophyll_in_sea_water; 2018-09-05T02:25:51.621Z,1536114351.621 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-09-05T02:25:51.622Z,1536114351.622 [Default:CheckIn:C.Wait] Stopped 2018-09-05T02:25:51.622Z,1536114351.622 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-09-05T02:25:51.622Z,1536114351.622 [Default:CheckIn:D] Running Loop=1 2018-09-05T02:25:51.974Z,1536114351.974 [Default:CheckIn:D] Stopped 2018-09-05T02:25:51.974Z,1536114351.974 [Default:CheckIn:E] Running Loop=1 2018-09-05T02:25:52.344Z,1536114352.344 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.840723 min 2018-09-05T02:25:52.346Z,1536114352.346 [Default:CheckIn:E] Stopped 2018-09-05T02:25:52.346Z,1536114352.346 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-09-05T02:25:52.346Z,1536114352.346 [Default:CheckIn] Stopped 2018-09-05T02:25:52.347Z,1536114352.347 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-09-05T02:25:52.347Z,1536114352.347 [Default:CheckIn](INFO): Running loop #2 2018-09-05T02:25:52.347Z,1536114352.347 [Default:CheckIn] Running Loop=2 2018-09-05T02:25:52.347Z,1536114352.347 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-09-05T02:25:52.347Z,1536114352.347 [Default:CheckIn:Read_GPS] Running Loop=1 2018-09-05T02:25:53.096Z,1536114353.096 [NAL9602](INFO): Powering up 2018-09-05T02:25:59.360Z,1536114359.360 [BPC1](ERROR): Bank B: No match for stick 0 serial number:1717 in the onboard configuration file. 2018-09-05T02:25:59.360Z,1536114359.360 [BPC1](ERROR): Failed to parse Bank B battery data 2018-09-05T02:26:04.138Z,1536114364.138 [NAL9602](INFO): NAL9602 initialized 2018-09-05T02:26:16.985Z,1536114376.985 [NAL9602](INFO): SBD MO Status=0, MOMSN=48193, MT Status=0, MTMSN=0 2018-09-05T02:26:16.985Z,1536114376.985 [NAL9602](INFO): No messages in MT queue 2018-09-05T02:26:57.923Z,1536114417.923 [RDI_Pathfinder](ERROR): Failed to parse: :B,-32768,-3268,V 2018-09-05T02:28:53.792Z,1536114533.792 [RDI_Pathfinder](ERROR): only read 3 of 5 data items 2018-09-05T02:28:53.792Z,1536114533.792 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768, 2018-09-05T02:30:32.040Z,1536114632.040 [NAL9602](INFO): GPS fix at 20180905T023030: (36.778858, -121.900143) 2018-09-05T02:30:32.121Z,1536114632.121 [Default:CheckIn:Read_GPS] Stopped 2018-09-05T02:30:32.121Z,1536114632.121 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-09-05T02:30:34.826Z,1536114634.826 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180905T021627/Courier0007.lzma 2018-09-05T02:30:37.656Z,1536114637.656 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Courier0007.lzma.bak 2018-09-05T02:30:37.657Z,1536114637.657 [DataOverHttps](INFO): SBD MOMSN=8469309 2018-09-05T02:31:06.439Z,1536114666.439 [NAL9602](INFO): Powering down 2018-09-05T02:31:08.944Z,1536114668.944 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180905T021627/Courier0010.lzma 2018-09-05T02:31:13.742Z,1536114673.742 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Courier0010.lzma.bak 2018-09-05T02:31:13.742Z,1536114673.742 [DataOverHttps](INFO): SBD MOMSN=8469313 2018-09-05T02:31:42.120Z,1536114702.120 [DataOverHttps](INFO): Sending 432 bytes from file Logs/20180905T021627/Express0008.lzma 2018-09-05T02:31:46.114Z,1536114706.114 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Express0008.lzma.bak 2018-09-05T02:31:46.119Z,1536114706.119 [DataOverHttps](INFO): SBD MOMSN=8469315 2018-09-05T02:31:54.376Z,1536114714.376 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2018-09-05T02:31:55.531Z,1536114715.531 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2018-09-05T02:32:16.769Z,1536114736.769 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180905T021627/Express0011.lzma 2018-09-05T02:32:18.689Z,1536114738.689 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Express0011.lzma.bak 2018-09-05T02:32:18.689Z,1536114738.689 [DataOverHttps](INFO): SBD MOMSN=8469328 2018-09-05T02:32:19.196Z,1536114739.196 [Default:CheckIn:Read_Iridium] Stopped 2018-09-05T02:32:19.197Z,1536114739.197 [Default:CheckIn:C.Wait] Running Loop=1 2018-09-05T02:32:19.197Z,1536114739.197 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-09-05T02:34:40.051Z,1536114880.051 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T023437 2018-09-05T02:34:53.857Z,1536114893.857 [DataOverHttps](INFO): Received command:configSet StratificationFrontDetector.loadAtStartup 0 bool persist 2018-09-05T02:34:54.517Z,1536114894.517 [CommandLine](IMPORTANT): got command configSet StratificationFrontDetector.loadAtStartup 0.000000 bool persist 2018-09-05T02:34:54.517Z,1536114894.517 [CommandLine](IMPORTANT): configSet StratificationFrontDetector.loadAtStartup requires a restart to take effect. 2018-09-05T02:34:57.838Z,1536114897.838 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T023456 2018-09-05T02:35:18.025Z,1536114918.025 [DataOverHttps](INFO): Received command:configSet Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index persist 2018-09-05T02:35:21.200Z,1536114921.200 [CommandLine](IMPORTANT): got command configSet Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index persist 2018-09-05T02:36:23.002Z,1536114983.002 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T023622 2018-09-05T02:36:36.629Z,1536114996.629 [DataOverHttps](INFO): Received command:configSet VerticalTemperatureHomogeneityIndexCalculator.loadAtStartup 0 bool persist 2018-09-05T02:36:37.239Z,1536114997.239 [CommandLine](IMPORTANT): got command configSet VerticalTemperatureHomogeneityIndexCalculator.loadAtStartup 0.000000 bool persist 2018-09-05T02:36:37.239Z,1536114997.239 [CommandLine](IMPORTANT): configSet VerticalTemperatureHomogeneityIndexCalculator.loadAtStartup requires a restart to take effect. 2018-09-05T02:37:20.077Z,1536115040.077 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-09-05T02:37:20.077Z,1536115040.077 [Default:CheckIn:C.Wait] Stopped 2018-09-05T02:37:20.077Z,1536115040.077 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-09-05T02:37:20.077Z,1536115040.077 [Default:CheckIn:D] Running Loop=1 2018-09-05T02:37:20.423Z,1536115040.423 [Default:CheckIn:D] Stopped 2018-09-05T02:37:20.423Z,1536115040.423 [Default:CheckIn:E] Running Loop=1 2018-09-05T02:37:20.857Z,1536115040.857 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.314903 min 2018-09-05T02:37:20.857Z,1536115040.857 [Default:CheckIn:E] Stopped 2018-09-05T02:37:20.858Z,1536115040.858 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-09-05T02:37:20.858Z,1536115040.858 [Default:CheckIn] Stopped 2018-09-05T02:37:20.858Z,1536115040.858 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-09-05T02:37:20.858Z,1536115040.858 [Default:CheckIn](INFO): Running loop #3 2018-09-05T02:37:20.858Z,1536115040.858 [Default:CheckIn] Running Loop=3 2018-09-05T02:37:20.858Z,1536115040.858 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-09-05T02:37:20.858Z,1536115040.858 [Default:CheckIn:Read_GPS] Running Loop=1 2018-09-05T02:37:21.576Z,1536115041.576 [NAL9602](INFO): Powering up 2018-09-05T02:37:34.933Z,1536115054.933 [NAL9602](INFO): NAL9602 initialized 2018-09-05T02:37:38.134Z,1536115058.134 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T023737 2018-09-05T02:37:38.561Z,1536115058.561 [BPC1](FAULT): Failed to receive data from all sticks prior to timeout. Missing data from 7 sticks. 2018-09-05T02:37:38.562Z,1536115058.562 [BPC1] Data Fault, FailCount= 1 2018-09-05T02:37:38.562Z,1536115058.562 [BPC1](ERROR): Data Fault 2018-09-05T02:37:38.671Z,1536115058.671 [CBIT](ERROR): Data Fault in component: BPC1 2018-09-05T02:37:39.872Z,1536115059.872 [CBIT](INFO): Clearing failed state for component BPC1 2018-09-05T02:37:39.872Z,1536115059.872 [BPC1] No Fault, FailCount= 1 2018-09-05T02:37:51.593Z,1536115071.593 [NAL9602](INFO): SBD MO Status=0, MOMSN=48194, MT Status=0, MTMSN=0 2018-09-05T02:37:51.593Z,1536115071.593 [NAL9602](INFO): No messages in MT queue 2018-09-05T02:37:52.986Z,1536115072.986 [DataOverHttps](INFO): Received command:configset list 2018-09-05T02:37:53.083Z,1536115073.083 [CommandLine](IMPORTANT): got command configSet list 2018-09-05T02:37:53.084Z,1536115073.084 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2018-09-05T02:37:53.086Z,1536115073.086 [CommandLine](IMPORTANT): 2018-09-05T02:37:53.086Z,1536115073.086 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool; 2018-09-05T02:37:53.089Z,1536115073.089 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=10 minute; 2018-09-05T02:37:53.089Z,1536115073.089 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool; 2018-09-05T02:37:53.089Z,1536115073.089 [CommandLine](IMPORTANT): Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index; 2018-09-05T02:37:53.089Z,1536115073.089 [CommandLine](IMPORTANT): Express none mass_concentration_of_chlorophyll_in_sea_water; 2018-09-05T02:37:53.089Z,1536115073.089 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup=0 bool; 2018-09-05T02:37:53.090Z,1536115073.090 [CommandLine](IMPORTANT): VerticalTemperatureHomogeneityIndexCalculator.loadAtStartup=0 bool; 2018-09-05T02:40:30.652Z,1536115230.652 [NAL9602](INFO): GPS fix at 20180905T024029: (36.778807, -121.899367) 2018-09-05T02:40:30.709Z,1536115230.709 [Default:CheckIn:Read_GPS] Stopped 2018-09-05T02:40:30.709Z,1536115230.709 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-09-05T02:40:51.110Z,1536115251.110 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180905T021627/Courier0013.lzma 2018-09-05T02:40:54.302Z,1536115254.302 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Courier0013.lzma.bak 2018-09-05T02:40:54.303Z,1536115254.303 [DataOverHttps](INFO): SBD MOMSN=8469387 2018-09-05T02:41:03.104Z,1536115263.104 [NAL9602](INFO): Powering down 2018-09-05T02:41:34.564Z,1536115294.564 [RDI_Pathfinder](ERROR): only read 3 of 5 data items 2018-09-05T02:41:34.565Z,1536115294.565 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32762768,-32768,V 2018-09-05T02:41:38.528Z,1536115298.528 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180905T021627/Courier0016.lzma 2018-09-05T02:41:40.526Z,1536115300.526 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Courier0016.lzma.bak 2018-09-05T02:41:40.526Z,1536115300.526 [DataOverHttps](INFO): SBD MOMSN=8469390 2018-09-05T02:42:11.747Z,1536115331.747 [DataOverHttps](INFO): Sending 646 bytes from file Logs/20180905T021627/Express0014.lzma 2018-09-05T02:42:17.250Z,1536115337.250 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Express0014.lzma.bak 2018-09-05T02:42:17.251Z,1536115337.251 [DataOverHttps](INFO): SBD MOMSN=8469392 2018-09-05T02:43:02.584Z,1536115382.584 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180905T021627/Express0017.lzma 2018-09-05T02:43:05.765Z,1536115385.765 [DataOverHttps](INFO): Moved sent file to Logs/20180905T021627/Express0017.lzma.bak 2018-09-05T02:43:05.765Z,1536115385.765 [DataOverHttps](INFO): SBD MOMSN=8469415 2018-09-05T02:43:06.649Z,1536115386.649 [Default:CheckIn:Read_Iridium] Stopped 2018-09-05T02:43:06.649Z,1536115386.649 [Default:CheckIn:C.Wait] Running Loop=1 2018-09-05T02:43:06.649Z,1536115386.649 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-09-05T02:45:37.310Z,1536115537.310 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting. 2018-09-05T02:46:36.453Z,1536115596.453 [RDI_Pathfinder](ERROR): Failed to parse: :HM,G,G,0e88,0e88, 15.182, -0.085, 0.000 2018-09-05T02:47:28.021Z,1536115648.021 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.328186 2018-09-05T02:48:07.003Z,1536115687.003 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-09-05T02:48:07.003Z,1536115687.003 [Default:CheckIn:C.Wait] Stopped 2018-09-05T02:48:07.003Z,1536115687.003 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-09-05T02:48:07.003Z,1536115687.003 [Default:CheckIn:D] Running Loop=1 2018-09-05T02:48:07.407Z,1536115687.407 [Default:CheckIn:D] Stopped 2018-09-05T02:48:07.407Z,1536115687.407 [Default:CheckIn:E] Running Loop=1 2018-09-05T02:48:07.829Z,1536115687.829 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.097972 min 2018-09-05T02:48:07.829Z,1536115687.829 [Default:CheckIn:E] Stopped 2018-09-05T02:48:07.829Z,1536115687.829 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-09-05T02:48:07.829Z,1536115687.829 [Default:CheckIn] Stopped 2018-09-05T02:48:07.829Z,1536115687.829 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-09-05T02:48:07.829Z,1536115687.829 [Default:CheckIn](INFO): Running loop #4 2018-09-05T02:48:07.830Z,1536115687.830 [Default:CheckIn] Running Loop=4 2018-09-05T02:48:07.830Z,1536115687.830 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-09-05T02:48:07.830Z,1536115687.830 [Default:CheckIn:Read_GPS] Running Loop=1 2018-09-05T02:48:08.576Z,1536115688.576 [NAL9602](INFO): Powering up 2018-09-05T02:48:19.549Z,1536115699.549 [NAL9602](INFO): NAL9602 initialized 2018-09-05T02:48:37.597Z,1536115717.597 [DataOverHttps](IMPORTANT): SBD MTMSN=20180905T024836 2018-09-05T02:48:37.601Z,1536115717.601 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003604 2018-09-05T02:48:42.430Z,1536115722.430 [NAL9602](INFO): SBD MO Status=0, MOMSN=48195, MT Status=0, MTMSN=0 2018-09-05T02:48:42.431Z,1536115722.431 [NAL9602](INFO): No messages in MT queue 2018-09-05T02:48:56.028Z,1536115736.028 [DataOverHttps](INFO): Received command:restart app 2018-09-05T02:48:56.065Z,1536115736.065 [CommandLine](IMPORTANT): got command restart application 2018-09-05T02:48:57.067Z,1536115737.067 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2018-09-05T02:48:57.070Z,1536115737.070 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-05T02:48:57.071Z,1536115737.071 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:57.139Z,1536115737.139 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-09-05T02:48:57.139Z,1536115737.139 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:57.140Z,1536115737.140 [CommandLine](INFO): Join timeout helper Thread ID is 6390 2018-09-05T02:48:57.140Z,1536115737.140 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-09-05T02:48:57.140Z,1536115737.140 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:57.141Z,1536115737.141 [NavChartDb](INFO): Join timeout helper Thread ID is 6391 2018-09-05T02:48:57.439Z,1536115737.439 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-05T02:48:57.439Z,1536115737.439 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:57.455Z,1536115737.455 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-09-05T02:48:57.456Z,1536115737.456 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:57.457Z,1536115737.457 [Radio_Surface](INFO): Join timeout helper Thread ID is 6392 2018-09-05T02:48:57.848Z,1536115737.848 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-05T02:48:57.848Z,1536115737.848 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:57.867Z,1536115737.867 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-09-05T02:48:57.867Z,1536115737.867 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:57.867Z,1536115737.867 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 6393 2018-09-05T02:48:58.107Z,1536115738.107 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-05T02:48:58.107Z,1536115738.107 [WetLabsBB2FL](INFO): Powering down 2018-09-05T02:48:58.108Z,1536115738.108 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.109Z,1536115738.109 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2018-09-05T02:48:58.109Z,1536115738.109 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.109Z,1536115738.109 [CTD_Seabird](INFO): Join timeout helper Thread ID is 6394 2018-09-05T02:48:58.251Z,1536115738.251 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-05T02:48:58.460Z,1536115738.460 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-09-05T02:48:58.461Z,1536115738.461 [CTD_Seabird](INFO): Powering down 2018-09-05T02:48:58.462Z,1536115738.462 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.472Z,1536115738.472 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-09-05T02:48:58.472Z,1536115738.472 [logger ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.473Z,1536115738.473 [logger](INFO): Join timeout helper Thread ID is 6396 2018-09-05T02:48:58.483Z,1536115738.483 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-05T02:48:58.483Z,1536115738.483 [logger ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.496Z,1536115738.496 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-09-05T02:48:58.496Z,1536115738.496 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.496Z,1536115738.496 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-09-05T02:48:58.497Z,1536115738.497 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.497Z,1536115738.497 [controlThread](INFO): Join timeout helper Thread ID is 6397 2018-09-05T02:48:58.553Z,1536115738.553 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-09-05T02:48:58.553Z,1536115738.553 [controlThread](DEBUG): Uninitializing ControlThread 2018-09-05T02:48:58.554Z,1536115738.554 [AHRS_M2](INFO): Powering down 2018-09-05T02:48:58.638Z,1536115738.638 [NAL9602](INFO): Powering down 2018-09-05T02:48:58.711Z,1536115738.711 [RDI_Pathfinder](INFO): Powering down 2018-09-05T02:48:58.712Z,1536115738.712 [DAT](INFO): Powering down 2018-09-05T02:48:58.832Z,1536115738.832 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-09-05T02:48:58.833Z,1536115738.833 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-09-05T02:48:58.834Z,1536115738.834 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2018-09-05T02:48:58.835Z,1536115738.835 [MissionManager](INFO): Uninitializing Mission Default 2018-09-05T02:48:58.835Z,1536115738.835 [Default] Stopped 2018-09-05T02:48:58.835Z,1536115738.835 [Default](DEBUG): Aggregate::uninitialize Default 2018-09-05T02:48:58.835Z,1536115738.835 [Default:B.GoToSurface] Stopped 2018-09-05T02:48:58.835Z,1536115738.835 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-09-05T02:48:58.835Z,1536115738.835 [Default:CheckIn] Stopped 2018-09-05T02:48:58.836Z,1536115738.836 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-09-05T02:48:58.836Z,1536115738.836 [Default:CheckIn:Read_GPS] Stopped 2018-09-05T02:48:58.840Z,1536115738.840 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-09-05T02:48:58.840Z,1536115738.840 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-09-05T02:48:58.840Z,1536115738.840 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-09-05T02:48:58.841Z,1536115738.841 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-09-05T02:48:58.841Z,1536115738.841 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-09-05T02:48:58.841Z,1536115738.841 [BuoyancyServo](INFO): Powering down 2018-09-05T02:48:58.855Z,1536115738.855 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-09-05T02:48:58.855Z,1536115738.855 [ElevatorServo](INFO): Powering down 2018-09-05T02:48:58.856Z,1536115738.856 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-09-05T02:48:58.856Z,1536115738.856 [MassServo](INFO): Powering down 2018-09-05T02:48:58.857Z,1536115738.857 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-09-05T02:48:58.857Z,1536115738.857 [RudderServo](INFO): Powering down 2018-09-05T02:48:58.858Z,1536115738.858 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-09-05T02:48:58.858Z,1536115738.858 [ThrusterServo](INFO): Powering down 2018-09-05T02:48:58.860Z,1536115738.860 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-09-05T02:48:58.860Z,1536115738.860 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-09-05T02:48:58.860Z,1536115738.860 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-09-05T02:48:58.861Z,1536115738.861 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.914Z,1536115738.914 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:58.934Z,1536115738.934 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:59.017Z,1536115739.017 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:59.085Z,1536115739.085 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-09-05T02:48:59.154Z,1536115739.154 [logger ThreadHandler](INFO): Thread cancelled.