2019-07-26T23:09:08.490Z,1564182548.490 [Supervisor](DEBUG): Initializing supervisor. 2019-07-26T23:09:08.493Z,1564182548.493 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-07-26T23:09:08.493Z,1564182548.493 [SyncHandler](INFO): Protected caller Thread ID is 6082 2019-07-26T23:09:08.494Z,1564182548.494 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-07-26T23:09:08.495Z,1564182548.495 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-07-26T23:09:08.495Z,1564182548.495 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 6083 2019-07-26T23:09:08.498Z,1564182548.498 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-07-26T23:09:08.510Z,1564182548.510 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-07-26T23:09:08.511Z,1564182548.511 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-07-26T23:09:08.511Z,1564182548.511 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 6084 2019-07-26T23:09:08.512Z,1564182548.512 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-07-26T23:09:08.513Z,1564182548.513 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-07-26T23:09:08.513Z,1564182548.513 [logger ThreadHandler](INFO): Protected caller Thread ID is 6085 2019-07-26T23:09:08.515Z,1564182548.515 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-07-26T23:09:08.516Z,1564182548.516 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-07-26T23:09:08.517Z,1564182548.517 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-07-26T23:09:08.618Z,1564182548.618 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-07-26T23:09:08.618Z,1564182548.618 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-07-26T23:09:08.830Z,1564182548.830 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-07-26T23:09:08.831Z,1564182548.831 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-07-26T23:09:08.975Z,1564182548.975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-07-26T23:09:08.976Z,1564182548.976 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-07-26T23:09:09.563Z,1564182549.563 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-07-26T23:09:09.564Z,1564182549.564 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-07-26T23:09:10.028Z,1564182550.028 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-07-26T23:09:10.029Z,1564182550.029 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-07-26T23:09:10.526Z,1564182550.526 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-07-26T23:09:10.526Z,1564182550.526 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-07-26T23:09:10.846Z,1564182550.846 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-07-26T23:09:10.847Z,1564182550.847 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-07-26T23:09:11.199Z,1564182551.199 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-07-26T23:09:11.199Z,1564182551.199 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-07-26T23:09:11.611Z,1564182551.611 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-07-26T23:09:11.612Z,1564182551.612 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-07-26T23:09:11.768Z,1564182551.768 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-07-26T23:09:11.769Z,1564182551.769 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-07-26T23:09:11.879Z,1564182551.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-07-26T23:09:11.880Z,1564182551.880 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-07-26T23:09:11.966Z,1564182551.966 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-07-26T23:09:12.076Z,1564182552.076 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-07-26T23:09:12.077Z,1564182552.077 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-07-26T23:09:12.286Z,1564182552.286 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-07-26T23:09:12.287Z,1564182552.287 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-07-26T23:09:12.504Z,1564182552.504 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-07-26T23:09:12.506Z,1564182552.506 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/ 2019-07-26T23:09:12.507Z,1564182552.507 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg 2019-07-26T23:09:12.595Z,1564182552.595 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg 2019-07-26T23:09:12.847Z,1564182552.847 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-07-26T23:09:12.848Z,1564182552.848 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg 2019-07-26T23:09:13.201Z,1564182553.201 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg 2019-07-26T23:09:13.768Z,1564182553.768 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg 2019-07-26T23:09:14.039Z,1564182554.039 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg 2019-07-26T23:09:14.131Z,1564182554.131 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg 2019-07-26T23:09:14.240Z,1564182554.240 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg 2019-07-26T23:09:14.341Z,1564182554.341 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg 2019-07-26T23:09:14.510Z,1564182554.510 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg 2019-07-26T23:09:14.624Z,1564182554.624 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg 2019-07-26T23:09:14.730Z,1564182554.730 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/ 2019-07-26T23:09:14.730Z,1564182554.730 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-07-26T23:09:14.738Z,1564182554.738 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-07-26T23:09:14.837Z,1564182554.837 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-07-26T23:09:14.838Z,1564182554.838 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-07-26T23:09:14.968Z,1564182554.968 [BuoyancyServo] Loaded 2019-07-26T23:09:14.968Z,1564182554.968 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-07-26T23:09:14.983Z,1564182554.983 [ElevatorServo] Loaded 2019-07-26T23:09:14.983Z,1564182554.983 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-07-26T23:09:14.999Z,1564182554.999 [MassServo] Loaded 2019-07-26T23:09:14.999Z,1564182554.999 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-07-26T23:09:15.014Z,1564182555.014 [RudderServo] Loaded 2019-07-26T23:09:15.014Z,1564182555.014 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-07-26T23:09:15.029Z,1564182555.029 [ThrusterServo] Loaded 2019-07-26T23:09:15.029Z,1564182555.029 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-07-26T23:09:15.030Z,1564182555.030 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-07-26T23:09:15.030Z,1564182555.030 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-07-26T23:09:15.166Z,1564182555.166 [SBIT](DEBUG): Construct Startup Built In Test. 2019-07-26T23:09:15.196Z,1564182555.196 [SBIT] Loaded 2019-07-26T23:09:15.196Z,1564182555.196 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-07-26T23:09:15.197Z,1564182555.197 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-07-26T23:09:15.225Z,1564182555.225 [IBIT] Loaded 2019-07-26T23:09:15.225Z,1564182555.225 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-07-26T23:09:15.228Z,1564182555.228 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-07-26T23:09:15.622Z,1564182555.622 [CBIT] Loaded 2019-07-26T23:09:15.622Z,1564182555.622 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-07-26T23:09:15.623Z,1564182555.623 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-07-26T23:09:15.623Z,1564182555.623 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-07-26T23:09:15.808Z,1564182555.808 [Aanderaa_O2] Loaded 2019-07-26T23:09:15.808Z,1564182555.808 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2019-07-26T23:09:15.818Z,1564182555.818 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2019-07-26T23:09:15.823Z,1564182555.823 [CTD_Seabird](INFO): created writer for : sea_water_density 2019-07-26T23:09:15.825Z,1564182555.825 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2019-07-26T23:09:15.830Z,1564182555.830 [CTD_Seabird](INFO): created writer for : depth 2019-07-26T23:09:15.830Z,1564182555.830 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2019-07-26T23:09:15.836Z,1564182555.836 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2019-07-26T23:09:15.836Z,1564182555.836 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2019-07-26T23:09:15.841Z,1564182555.841 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2019-07-26T23:09:15.842Z,1564182555.842 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2019-07-26T23:09:15.847Z,1564182555.847 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2019-07-26T23:09:15.848Z,1564182555.848 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2019-07-26T23:09:15.853Z,1564182555.853 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2019-07-26T23:09:15.854Z,1564182555.854 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2019-07-26T23:09:15.859Z,1564182555.859 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2019-07-26T23:09:15.886Z,1564182555.886 [CTD_Seabird] Loaded 2019-07-26T23:09:15.886Z,1564182555.886 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2019-07-26T23:09:15.887Z,1564182555.887 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066B4E0 2019-07-26T23:09:15.888Z,1564182555.888 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 6164 2019-07-26T23:09:15.919Z,1564182555.919 [ESPComponent] Loaded 2019-07-26T23:09:15.919Z,1564182555.919 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2019-07-26T23:09:15.934Z,1564182555.934 [PAR_Licor] Loaded 2019-07-26T23:09:15.934Z,1564182555.934 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-07-26T23:09:15.983Z,1564182555.983 [WetLabsBB2FL] Loaded 2019-07-26T23:09:15.983Z,1564182555.983 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2019-07-26T23:09:15.984Z,1564182555.984 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069B4E0 2019-07-26T23:09:15.985Z,1564182555.985 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 6165 2019-07-26T23:09:15.985Z,1564182555.985 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-07-26T23:09:15.986Z,1564182555.986 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-07-26T23:09:16.028Z,1564182556.028 [DepthRateCalculator] Loaded 2019-07-26T23:09:16.029Z,1564182556.029 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-07-26T23:09:16.035Z,1564182556.035 [PitchRateCalculator] Loaded 2019-07-26T23:09:16.035Z,1564182556.035 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-07-26T23:09:16.051Z,1564182556.051 [SpeedCalculator] Loaded 2019-07-26T23:09:16.051Z,1564182556.051 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-07-26T23:09:16.072Z,1564182556.072 [TempGradientCalculator] Loaded 2019-07-26T23:09:16.072Z,1564182556.072 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-07-26T23:09:16.078Z,1564182556.078 [YawRateCalculator] Loaded 2019-07-26T23:09:16.079Z,1564182556.079 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-07-26T23:09:16.112Z,1564182556.112 [ElevatorOffsetCalculator] Loaded 2019-07-26T23:09:16.112Z,1564182556.112 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-07-26T23:09:16.113Z,1564182556.113 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-07-26T23:09:16.113Z,1564182556.113 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-07-26T23:09:16.146Z,1564182556.146 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-07-26T23:09:16.146Z,1564182556.146 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-07-26T23:09:16.251Z,1564182556.251 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-07-26T23:09:16.252Z,1564182556.252 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-07-26T23:09:16.273Z,1564182556.273 [NavChart] Loaded 2019-07-26T23:09:16.274Z,1564182556.274 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-07-26T23:09:16.278Z,1564182556.278 [UniversalFixResidualReporter] Loaded 2019-07-26T23:09:16.278Z,1564182556.278 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-07-26T23:09:16.278Z,1564182556.278 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-07-26T23:09:16.279Z,1564182556.279 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-07-26T23:09:16.632Z,1564182556.632 [AHRS_M2] Loaded 2019-07-26T23:09:16.633Z,1564182556.633 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-07-26T23:09:16.709Z,1564182556.709 [DataOverHttps] Loaded 2019-07-26T23:09:16.710Z,1564182556.710 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-07-26T23:09:16.711Z,1564182556.711 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409744E0 2019-07-26T23:09:16.711Z,1564182556.711 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 6166 2019-07-26T23:09:16.724Z,1564182556.724 [Depth_Keller] Loaded 2019-07-26T23:09:16.724Z,1564182556.724 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-07-26T23:09:16.858Z,1564182556.858 [DVL_micro] Loaded 2019-07-26T23:09:16.859Z,1564182556.859 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2019-07-26T23:09:16.951Z,1564182556.951 [NAL9602] Loaded 2019-07-26T23:09:16.951Z,1564182556.951 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-07-26T23:09:16.956Z,1564182556.956 [Onboard] Loaded 2019-07-26T23:09:16.956Z,1564182556.956 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-07-26T23:09:16.960Z,1564182556.960 [Radio_Surface] Loaded 2019-07-26T23:09:16.960Z,1564182556.960 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-07-26T23:09:16.961Z,1564182556.961 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A44E0 2019-07-26T23:09:16.962Z,1564182556.962 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6167 2019-07-26T23:09:17.093Z,1564182557.093 [DAT] Loaded 2019-07-26T23:09:17.093Z,1564182557.093 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2019-07-26T23:09:18.396Z,1564182558.396 [BPC1] Loaded 2019-07-26T23:09:18.397Z,1564182558.397 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-07-26T23:09:18.397Z,1564182558.397 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-07-26T23:09:18.398Z,1564182558.398 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-07-26T23:09:18.635Z,1564182558.635 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-07-26T23:09:18.636Z,1564182558.636 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-07-26T23:09:18.956Z,1564182558.956 [VerticalControl](DEBUG): Construct VerticalControl. 2019-07-26T23:09:19.110Z,1564182559.110 [VerticalControl] Loaded 2019-07-26T23:09:19.111Z,1564182559.111 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-07-26T23:09:19.111Z,1564182559.111 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-07-26T23:09:19.169Z,1564182559.169 [HorizontalControl] Loaded 2019-07-26T23:09:19.170Z,1564182559.170 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-07-26T23:09:19.170Z,1564182559.170 [SpeedControl](DEBUG): Construct SpeedControl. 2019-07-26T23:09:19.172Z,1564182559.172 [SpeedControl] Loaded 2019-07-26T23:09:19.172Z,1564182559.172 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-07-26T23:09:19.173Z,1564182559.173 [LoopControl](DEBUG): Construct LoopControl. 2019-07-26T23:09:19.174Z,1564182559.174 [LoopControl] Loaded 2019-07-26T23:09:19.174Z,1564182559.174 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-07-26T23:09:19.174Z,1564182559.174 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-07-26T23:09:19.175Z,1564182559.175 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-07-26T23:09:19.188Z,1564182559.188 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-07-26T23:09:19.188Z,1564182559.188 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-07-26T23:09:19.482Z,1564182559.482 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-07-26T23:09:19.485Z,1564182559.485 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-07-26T23:09:19.486Z,1564182559.486 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-07-26T23:09:19.493Z,1564182559.493 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-07-26T23:09:19.494Z,1564182559.494 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADF4E0 2019-07-26T23:09:19.495Z,1564182559.495 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6168 2019-07-26T23:09:19.499Z,1564182559.499 [Supervisor](INFO): Main Thread ID is 5737 2019-07-26T23:09:19.499Z,1564182559.499 [Supervisor](DEBUG): Running supervisor. 2019-07-26T23:09:19.500Z,1564182559.500 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6169 2019-07-26T23:09:19.503Z,1564182559.503 [controlThread ThreadHandler](INFO): Handler Thread ID is 6170 2019-07-26T23:09:19.504Z,1564182559.504 [controlThread](DEBUG): Initializing ControlThread 2019-07-26T23:09:19.506Z,1564182559.506 [SBIT](INFO): Initialize SBIT Component. 2019-07-26T23:09:19.506Z,1564182559.506 [SBIT](IMPORTANT): git: 2019-07-26 2019-07-26T23:09:19.506Z,1564182559.506 [SBIT](INFO): git hash: f88ffa24b8ecf5258b33f27687ba0d8562856deb 2019-07-26T23:09:19.507Z,1564182559.507 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-07-26T23:09:19.508Z,1564182559.508 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 2019-07-26T23:09:19.509Z,1564182559.509 [SBIT](INFO): Beginning SBIT in 72.000000 seconds. 2019-07-26T23:09:19.510Z,1564182559.510 [IBIT](INFO): Initialize IBIT Component. 2019-07-26T23:09:19.511Z,1564182559.511 [CBIT](DEBUG): Initialize CBIT Component. 2019-07-26T23:09:19.512Z,1564182559.512 [logger ThreadHandler](INFO): Handler Thread ID is 6171 2019-07-26T23:09:19.521Z,1564182559.521 [CBIT](DEBUG): Initialized mux pins. 2019-07-26T23:09:19.521Z,1564182559.521 [CBIT](DEBUG): Initializing the watchdog timer. 2019-07-26T23:09:19.530Z,1564182559.530 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 6172 2019-07-26T23:09:19.530Z,1564182559.530 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2019-07-26T23:09:19.534Z,1564182559.534 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20 2019-07-26T23:09:19.535Z,1564182559.535 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 6174 2019-07-26T23:09:19.536Z,1564182559.536 [WetLabsBB2FL](INFO): Powering down 2019-07-26T23:09:19.546Z,1564182559.546 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-07-26T23:09:19.546Z,1564182559.546 [CBIT](DEBUG): Initializing heartbeat. 2019-07-26T23:09:19.566Z,1564182559.566 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 6175 2019-07-26T23:09:19.567Z,1564182559.567 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-07-26T23:09:19.578Z,1564182559.578 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6176 2019-07-26T23:09:19.594Z,1564182559.594 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6177 2019-07-26T23:09:19.597Z,1564182559.597 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-07-26T23:09:19.597Z,1564182559.597 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-07-26T23:09:19.597Z,1564182559.597 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-07-26T23:09:19.597Z,1564182559.597 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-07-26T23:09:19.598Z,1564182559.598 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-07-26T23:09:19.598Z,1564182559.598 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-07-26T23:09:19.598Z,1564182559.598 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-07-26T23:09:19.598Z,1564182559.598 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-07-26T23:09:19.598Z,1564182559.598 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-07-26T23:09:19.599Z,1564182559.599 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-07-26T23:09:19.599Z,1564182559.599 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-07-26T23:09:19.599Z,1564182559.599 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-07-26T23:09:19.599Z,1564182559.599 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-07-26T23:09:19.599Z,1564182559.599 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-07-26T23:09:19.600Z,1564182559.600 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-07-26T23:09:19.600Z,1564182559.600 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-07-26T23:09:19.617Z,1564182559.617 [CBIT](DEBUG): Deactivating GF circuits. 2019-07-26T23:09:19.617Z,1564182559.617 [CBIT](DEBUG): Deactivating emergency mode. 2019-07-26T23:09:19.653Z,1564182559.653 [CBIT](DEBUG): Backplane powered. 2019-07-26T23:09:19.658Z,1564182559.658 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-07-26T23:09:19.658Z,1564182559.658 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-07-26T23:09:19.658Z,1564182559.658 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-07-26T23:09:19.659Z,1564182559.659 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-07-26T23:09:19.659Z,1564182559.659 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-07-26T23:09:19.659Z,1564182559.659 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-07-26T23:09:19.661Z,1564182559.661 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-07-26T23:09:19.661Z,1564182559.661 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-07-26T23:09:19.671Z,1564182559.671 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-07-26T23:09:19.673Z,1564182559.673 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-07-26T23:09:19.673Z,1564182559.673 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-07-26T23:09:19.674Z,1564182559.674 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-07-26T23:09:19.675Z,1564182559.675 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-07-26T23:09:19.701Z,1564182559.701 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-07-26T23:09:19.736Z,1564182559.736 [MissionManager](DEBUG): 2019-07-26T23:09:19.745Z,1564182559.745 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-07-26T23:09:19.822Z,1564182559.822 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-07-26T23:09:19.823Z,1564182559.823 [Default:A.Wait](DEBUG): Construct Wait. 2019-07-26T23:09:19.825Z,1564182559.825 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-07-26T23:09:19.868Z,1564182559.868 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-07-26T23:09:19.870Z,1564182559.870 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-07-26T23:09:19.888Z,1564182559.888 [Default:E.Execute](DEBUG): Construct Execute. 2019-07-26T23:09:19.891Z,1564182559.891 [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-07-26T23:09:19.925Z,1564182559.925 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-07-26T23:09:19.981Z,1564182559.981 [Radio_Surface](INFO): Powering up 2019-07-26T23:09:19.989Z,1564182559.989 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-07-26T23:09:20.145Z,1564182560.145 [DVL_micro](INFO): Initializing 2019-07-26T23:09:20.171Z,1564182560.171 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2019-07-26T23:09:20.171Z,1564182560.171 [DAT](INFO): Powering up 2019-07-26T23:09:20.171Z,1564182560.171 [DAT](DEBUG): Initializing DAT. 2019-07-26T23:09:20.217Z,1564182560.217 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2019-07-26T23:09:20.288Z,1564182560.288 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-07-26T23:09:20.294Z,1564182560.294 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-07-26T23:09:20.295Z,1564182560.295 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-07-26T23:09:20.306Z,1564182560.306 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-07-26T23:09:20.307Z,1564182560.307 [MassServo](DEBUG): Initializing EZServoServo. 2019-07-26T23:09:20.318Z,1564182560.318 [MassServo](DEBUG): Initializing MassServo. 2019-07-26T23:09:20.319Z,1564182560.319 [RudderServo](DEBUG): Initializing EZServoServo. 2019-07-26T23:09:20.330Z,1564182560.330 [RudderServo](DEBUG): Initializing RudderServo. 2019-07-26T23:09:20.331Z,1564182560.331 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-07-26T23:09:20.342Z,1564182560.342 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-07-26T23:09:23.301Z,1564182563.301 [Aanderaa_O2](INFO): Powering down 2019-07-26T23:09:26.562Z,1564182566.562 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit. 2019-07-26T23:09:35.509Z,1564182575.509 [DAT](INFO): setting local address to 3 2019-07-26T23:09:35.919Z,1564182575.919 [DAT](INFO): set local address to 3 2019-07-26T23:09:47.195Z,1564182587.195 [NAL9602](INFO): Powering up NAL9602 2019-07-26T23:09:58.103Z,1564182598.103 [NAL9602](INFO): NAL9602 initialized 2019-07-26T23:09:58.929Z,1564182598.929 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:13.461Z,1564182613.461 [NAL9602](INFO): SBD MO Status=0, MOMSN=30216, MT Status=0, MTMSN=0 2019-07-26T23:10:13.461Z,1564182613.461 [NAL9602](INFO): No messages in MT queue 2019-07-26T23:10:14.285Z,1564182614.285 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:14.689Z,1564182614.689 [DVL_micro](ERROR): only read 45 of 46 data items 2019-07-26T23:10:14.690Z,1564182614.690 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 -43 -29 3 3 3 3 146.8 60.1 2.9 2 -60.1 146.8 2.9 2 146 60 2 2 -60 146 2 2 0.76 2.07 90.0 -3.0 22.4 0.005 35.0 1489 124 2019-07-26T23:10:16.709Z,1564182616.709 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:19.533Z,1564182619.533 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:22.765Z,1564182622.765 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:25.593Z,1564182625.593 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:28.829Z,1564182628.829 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:31.657Z,1564182631.657 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:32.096Z,1564182632.096 [SBIT](IMPORTANT): Beginning Startup BIT 2019-07-26T23:10:32.100Z,1564182632.100 [CBIT](IMPORTANT): Beginning ground fault scan 2019-07-26T23:10:34.581Z,1564182634.581 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:37.801Z,1564182637.801 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:40.645Z,1564182640.645 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:43.126Z,1564182643.126 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): 0.008589 CHAN A1 (24V): 0.004160 CHAN A2 (12V): 0.002049 CHAN A3 (5V): -0.004861 CHAN B0 (3.3V): -0.004515 CHAN B1 (3.15aV): -0.003977 CHAN B2 (3.15bV): -0.003269 CHAN B3 (GND): -0.006960 OPEN: 0.007545 Full Scale Calc: 4.765 mA, -1.589 mA 2019-07-26T23:10:43.881Z,1564182643.881 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:46.689Z,1564182646.689 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:49.705Z,1564182649.705 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:52.937Z,1564182652.937 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:55.765Z,1564182655.765 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:10:58.993Z,1564182658.993 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:11:01.825Z,1564182661.825 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:11:04.653Z,1564182664.653 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:11:07.885Z,1564182667.885 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:11:08.277Z,1564182668.277 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231101.00,A,3648.17966,N,12147.18656,W,6.181,37.82,260719,,,A*4C 2019-07-26T23:11:08.280Z,1564182668.280 [NAL9602](INFO): GPS fix at 20190726T231101: (36.802994, -121.786443) 2019-07-26T23:11:25.406Z,1564182685.406 [SBIT](IMPORTANT): SBIT PASSED 2019-07-26T23:11:25.471Z,1564182685.471 [CommandLine](IMPORTANT): got command configSet list 2019-07-26T23:11:25.472Z,1564182685.472 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-07-26T23:11:25.472Z,1564182685.472 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count; 2019-07-26T23:11:25.473Z,1564182685.473 [CommandLine](IMPORTANT): BuoyancyServo.fastPumpDepth=5 meter; 2019-07-26T23:11:25.473Z,1564182685.473 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=1 bool; 2019-07-26T23:11:25.473Z,1564182685.473 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2019-07-26T23:11:25.473Z,1564182685.473 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=210 cubic_centimeter; 2019-07-26T23:11:25.473Z,1564182685.473 [CommandLine](IMPORTANT): VerticalControl.kiDepthBuoy=0.3 reciprocal_second; 2019-07-26T23:11:25.473Z,1564182685.473 [CommandLine](IMPORTANT): VerticalControl.massDefault=13 millimeter; 2019-07-26T23:11:25.822Z,1564182685.822 [MissionManager](IMPORTANT): Started mission Startup 2019-07-26T23:11:25.822Z,1564182685.822 [Startup] Running Loop=1 2019-07-26T23:11:25.822Z,1564182685.822 [Startup](DEBUG): Aggregate::initialize Startup 2019-07-26T23:11:25.822Z,1564182685.822 [Startup:A.GoToSurface] Running Loop=1 2019-07-26T23:11:25.822Z,1564182685.822 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-07-26T23:11:25.823Z,1564182685.823 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-07-26T23:11:25.823Z,1564182685.823 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-07-26T23:11:25.824Z,1564182685.824 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-07-26T23:11:25.824Z,1564182685.824 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-07-26T23:11:25.824Z,1564182685.824 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-07-26T23:11:25.830Z,1564182685.830 [Startup:StartupSatComms] Running Loop=1 2019-07-26T23:11:25.830Z,1564182685.830 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-07-26T23:11:25.830Z,1564182685.830 [Startup:StartupSatComms:A] Running Loop=1 2019-07-26T23:11:26.199Z,1564182686.199 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-07-26T23:11:27.393Z,1564182687.393 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:11:27.770Z,1564182687.770 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231120.00,A,3648.20496,N,12147.16231,W,6.006,36.02,260719,,,A*45 2019-07-26T23:11:27.772Z,1564182687.772 [NAL9602](INFO): GPS fix at 20190726T231120: (36.803416, -121.786039) 2019-07-26T23:11:27.821Z,1564182687.821 [Startup:StartupSatComms:A] Stopped 2019-07-26T23:11:27.821Z,1564182687.821 [Startup:StartupSatComms:B] Running Loop=1 2019-07-26T23:11:28.225Z,1564182688.225 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-07-26T23:11:44.139Z,1564182704.139 [NAL9602](INFO): SBD MO Status=1, MOMSN=30217, MT Status=0, MTMSN=0 2019-07-26T23:11:44.186Z,1564182704.186 [NAL9602](INFO): Sent 214 bytes from file Logs/20190726T223320/Courier0021.lzma 2019-07-26T23:11:44.186Z,1564182704.186 [NAL9602](INFO): Packets left to send: 0 2019-07-26T23:11:57.522Z,1564182717.522 [NAL9602](INFO): SBD MO Status=1, MOMSN=30218, MT Status=0, MTMSN=0 2019-07-26T23:11:57.566Z,1564182717.566 [NAL9602](INFO): Sent 213 bytes from file Logs/20190726T230908/Courier0000.lzma 2019-07-26T23:11:57.566Z,1564182717.566 [NAL9602](INFO): Packets left to send: 0 2019-07-26T23:12:15.426Z,1564182735.426 [NAL9602](INFO): SBD MO Status=2, MOMSN=30219, MT Status=2, MTMSN=0 2019-07-26T23:12:15.426Z,1564182735.426 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-26T23:12:24.376Z,1564182744.376 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-07-26T23:12:24.376Z,1564182744.376 [DVL_micro] Data Fault, FailCount= 1 2019-07-26T23:12:24.376Z,1564182744.376 [DVL_micro](ERROR): Data Fault 2019-07-26T23:12:24.410Z,1564182744.410 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-07-26T23:12:24.858Z,1564182744.858 [DVL_micro](INFO): uninitialize:Powering down 2019-07-26T23:12:25.623Z,1564182745.623 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-07-26T23:12:25.624Z,1564182745.624 [DVL_micro] No Fault, FailCount= 1 2019-07-26T23:12:25.994Z,1564182745.994 [DVL_micro](INFO): Initializing 2019-07-26T23:12:28.052Z,1564182748.052 [Startup:StartupSatComms:B](INFO): Timed out from 2019-07-26T23:11:27.8Z 2019-07-26T23:12:28.052Z,1564182748.052 [Startup:StartupSatComms:B] Stopped 2019-07-26T23:12:28.053Z,1564182748.053 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-07-26T23:12:28.053Z,1564182748.053 [Startup:StartupSatComms] Stopped 2019-07-26T23:12:28.053Z,1564182748.053 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-07-26T23:12:28.054Z,1564182748.054 [Startup](INFO): Completed Startup 2019-07-26T23:12:28.054Z,1564182748.054 [MissionManager](INFO): Startup is completed. 2019-07-26T23:12:28.054Z,1564182748.054 [MissionManager](INFO): Uninitializing Mission Startup 2019-07-26T23:12:28.054Z,1564182748.054 [Startup] Stopped 2019-07-26T23:12:28.054Z,1564182748.054 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-07-26T23:12:28.054Z,1564182748.054 [Startup:A.GoToSurface] Stopped 2019-07-26T23:12:28.054Z,1564182748.054 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-07-26T23:12:28.465Z,1564182748.465 [MissionManager](IMPORTANT): Started mission Default 2019-07-26T23:12:28.465Z,1564182748.465 [Default] Running Loop=1 2019-07-26T23:12:28.465Z,1564182748.465 [Default](DEBUG): Aggregate::initialize Default 2019-07-26T23:12:28.465Z,1564182748.465 [Default:B.GoToSurface] Running Loop=1 2019-07-26T23:12:28.465Z,1564182748.465 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-07-26T23:12:28.466Z,1564182748.466 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-07-26T23:12:28.466Z,1564182748.466 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-07-26T23:12:28.466Z,1564182748.466 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-07-26T23:12:28.467Z,1564182748.467 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-07-26T23:12:28.467Z,1564182748.467 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-07-26T23:12:28.467Z,1564182748.467 [Default:A.Wait] Running Loop=1 2019-07-26T23:12:28.467Z,1564182748.467 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-07-26T23:12:34.886Z,1564182754.886 [NAL9602](INFO): SBD MO Status=1, MOMSN=30219, MT Status=0, MTMSN=0 2019-07-26T23:12:34.933Z,1564182754.933 [NAL9602](INFO): Sent 25 bytes from file Logs/20190726T223320/Express0022.lzma 2019-07-26T23:12:34.934Z,1564182754.934 [NAL9602](INFO): Packets left to send: 0 2019-07-26T23:12:41.789Z,1564182761.789 [Default:A.Wait](INFO): Done Waiting. 2019-07-26T23:12:41.789Z,1564182761.789 [Default:A.Wait] Stopped 2019-07-26T23:12:41.790Z,1564182761.790 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-07-26T23:12:42.226Z,1564182762.226 [Default:CheckIn] Running Loop=1 2019-07-26T23:12:42.226Z,1564182762.226 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-26T23:12:42.226Z,1564182762.226 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-26T23:12:42.593Z,1564182762.593 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-07-26T23:12:43.777Z,1564182763.777 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:12:44.177Z,1564182764.177 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231237.00,A,3648.31707,N,12147.12806,W,5.210,2.09,260719,,,D*7E 2019-07-26T23:12:44.179Z,1564182764.179 [NAL9602](INFO): GPS fix at 20190726T231237: (36.805284, -121.785468) 2019-07-26T23:12:44.203Z,1564182764.203 [Default:CheckIn:Read_GPS] Stopped 2019-07-26T23:12:44.203Z,1564182764.203 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-26T23:12:44.621Z,1564182764.621 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-07-26T23:13:00.039Z,1564182780.039 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004841 2019-07-26T23:13:02.462Z,1564182782.462 [NAL9602](INFO): SBD MO Status=1, MOMSN=30220, MT Status=0, MTMSN=0 2019-07-26T23:13:02.510Z,1564182782.510 [NAL9602](INFO): Sent 63 bytes from file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:13:02.510Z,1564182782.510 [NAL9602](INFO): Packets left to send: 0 2019-07-26T23:13:02.588Z,1564182782.588 [Default:CheckIn:Read_Iridium] Stopped 2019-07-26T23:13:02.588Z,1564182782.588 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-26T23:13:02.589Z,1564182782.589 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-26T23:13:05.527Z,1564182785.527 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:13:05.528Z,1564182785.528 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:13:05.736Z,1564182785.736 [CommandLine](FAULT): Scheduling is paused 2019-07-26T23:13:05.736Z,1564182785.736 [CBIT](INFO): Critical error at 20190726T231305 2019-07-26T23:13:05.737Z,1564182785.737 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2019-07-26T23:13:11.595Z,1564182791.595 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:13:11.596Z,1564182791.596 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:13:11.782Z,1564182791.782 [CBIT](INFO): Critical error at 20190726T231311 2019-07-26T23:13:33.165Z,1564182813.165 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-26T23:13:42.335Z,1564182822.335 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:13:42.336Z,1564182822.336 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:13:42.515Z,1564182822.515 [CBIT](INFO): Critical error at 20190726T231342 2019-07-26T23:14:12.471Z,1564182852.471 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:14:12.472Z,1564182852.472 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:14:12.791Z,1564182852.791 [CBIT](INFO): Critical error at 20190726T231412 2019-07-26T23:14:42.551Z,1564182882.551 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:14:42.552Z,1564182882.552 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:14:42.703Z,1564182882.703 [CBIT](INFO): Critical error at 20190726T231442 2019-07-26T23:15:12.455Z,1564182912.455 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:15:12.456Z,1564182912.456 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:15:12.635Z,1564182912.635 [CBIT](INFO): Critical error at 20190726T231512 2019-07-26T23:15:30.322Z,1564182930.322 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-07-26T23:15:30.322Z,1564182930.322 [DVL_micro] Data Fault, FailCount= 1 2019-07-26T23:15:30.322Z,1564182930.322 [DVL_micro](ERROR): Data Fault 2019-07-26T23:15:30.355Z,1564182930.355 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-07-26T23:15:30.802Z,1564182930.802 [DVL_micro](INFO): uninitialize:Powering down 2019-07-26T23:15:31.574Z,1564182931.574 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-07-26T23:15:31.574Z,1564182931.574 [DVL_micro] No Fault, FailCount= 1 2019-07-26T23:15:31.987Z,1564182931.987 [DVL_micro](INFO): Initializing 2019-07-26T23:15:42.668Z,1564182942.668 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:15:42.668Z,1564182942.668 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:15:42.885Z,1564182942.885 [CBIT](INFO): Critical error at 20190726T231542 2019-07-26T23:16:12.959Z,1564182972.959 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:16:12.960Z,1564182972.960 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:16:13.184Z,1564182973.184 [CBIT](INFO): Critical error at 20190726T231612 2019-07-26T23:16:43.480Z,1564183003.480 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:16:43.480Z,1564183003.480 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:16:43.519Z,1564183003.519 [CBIT](INFO): Critical error at 20190726T231643 2019-07-26T23:16:55.240Z,1564183015.240 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-07-26T23:16:55.241Z,1564183015.241 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-07-26T23:16:55.246Z,1564183015.246 [BPC1](INFO): Calculating totals. Valid battery stick count: 53. Valid reserve battery stick count: 5. 2019-07-26T23:16:55.249Z,1564183015.249 [BPC1](INFO): Received data from all battery sticks. 2019-07-26T23:17:14.675Z,1564183034.675 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:17:14.676Z,1564183034.676 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:17:14.995Z,1564183034.995 [CBIT](INFO): Critical error at 20190726T231714 2019-07-26T23:17:43.607Z,1564183063.607 [DataOverHttps](IMPORTANT): Could not stat file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:17:43.608Z,1564183063.608 [DataOverHttps](CRITICAL): Could not open file Logs/20190726T230908/Courier0004.lzma 2019-07-26T23:17:43.672Z,1564183063.672 [CBIT](INFO): Critical error at 20190726T231743 2019-07-26T23:17:44.470Z,1564183064.470 [DVL_micro](ERROR): only read 45 of 46 data items 2019-07-26T23:17:44.470Z,1564183064.470 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 2 -22 -77 -26 3 3 3 3 -20.0 5.3 -58.5 2 18.1 -10.1 -58.5 2 -20 5 -58 2 18 -10 -58 2 -2.48 0.02 165.6 -3.0 22.4 0.005 35.0 1489 98 2019-07-26T23:18:03.059Z,1564183083.059 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-26T23:18:03.059Z,1564183083.059 [Default:CheckIn:C.Wait] Stopped 2019-07-26T23:18:03.059Z,1564183083.059 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-26T23:18:03.059Z,1564183083.059 [Default:CheckIn:D] Running Loop=1 2019-07-26T23:18:03.469Z,1564183083.469 [Default:CheckIn:D] Stopped 2019-07-26T23:18:03.469Z,1564183083.469 [Default:CheckIn:E] Running Loop=1 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.583398 min 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn:E] Stopped 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn] Stopped 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn](INFO): Running loop #2 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn] Running Loop=2 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-26T23:18:03.898Z,1564183083.898 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-26T23:18:05.477Z,1564183085.477 [NAL9602](DEBUG): Fix Requested 2019-07-26T23:18:05.899Z,1564183085.899 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231759.00,A,3648.36610,N,12148.00532,W,20.760,273.56,260719,,,D*4E 2019-07-26T23:18:05.901Z,1564183085.901 [NAL9602](INFO): GPS fix at 20190726T231759: (36.806102, -121.800089) 2019-07-26T23:18:05.945Z,1564183085.945 [Default:CheckIn:Read_GPS] Stopped 2019-07-26T23:18:05.945Z,1564183085.945 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-26T23:18:11.525Z,1564183091.525 [DataOverHttps](INFO): Sending 354 bytes from file Logs/20190726T230908/Courier0007.lzma 2019-07-26T23:18:12.331Z,1564183092.331 [DataOverHttps](INFO): Moved sent file to Logs/20190726T230908/Courier0007.lzma.bak 2019-07-26T23:18:12.331Z,1564183092.331 [DataOverHttps](INFO): SBD MOMSN=11478810 2019-07-26T23:18:18.796Z,1564183098.796 [NAL9602](INFO): SBD MO Status=0, MOMSN=30221, MT Status=0, MTMSN=0 2019-07-26T23:18:18.796Z,1564183098.796 [NAL9602](INFO): No messages in MT queue 2019-07-26T23:18:24.334Z,1564183104.334 [DataOverHttps](INFO): Sending 882 bytes from file Logs/20190726T230908/Express0001.lzma 2019-07-26T23:18:25.139Z,1564183105.139 [DataOverHttps](INFO): Moved sent file to Logs/20190726T230908/Express0001.lzma.bak 2019-07-26T23:18:25.139Z,1564183105.139 [DataOverHttps](INFO): SBD MOMSN=11478824 2019-07-26T23:18:36.162Z,1564183116.162 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-07-26T23:18:36.162Z,1564183116.162 [DVL_micro] Data Fault, FailCount= 1 2019-07-26T23:18:36.162Z,1564183116.162 [DVL_micro](ERROR): Data Fault 2019-07-26T23:18:36.202Z,1564183116.202 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-07-26T23:18:36.389Z,1564183116.389 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20190726T230908/Express0005.lzma 2019-07-26T23:18:36.641Z,1564183116.641 [DVL_micro](INFO): uninitialize:Powering down 2019-07-26T23:18:37.195Z,1564183117.195 [DataOverHttps](INFO): Moved sent file to Logs/20190726T230908/Express0005.lzma.bak 2019-07-26T23:18:37.195Z,1564183117.195 [DataOverHttps](INFO): SBD MOMSN=11478844 2019-07-26T23:18:37.418Z,1564183117.418 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-07-26T23:18:37.418Z,1564183117.418 [DVL_micro] No Fault, FailCount= 1 2019-07-26T23:18:37.784Z,1564183117.784 [DVL_micro](INFO): Initializing 2019-07-26T23:18:49.069Z,1564183129.069 [DataOverHttps](INFO): Sending 356 bytes from file Logs/20190726T230908/Express0008.lzma 2019-07-26T23:18:49.506Z,1564183129.506 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-26T23:18:49.875Z,1564183129.875 [DataOverHttps](INFO): Moved sent file to Logs/20190726T230908/Express0008.lzma.bak 2019-07-26T23:18:49.875Z,1564183129.875 [DataOverHttps](INFO): SBD MOMSN=11478848 2019-07-26T23:18:50.768Z,1564183130.768 [Default:CheckIn:Read_Iridium] Stopped 2019-07-26T23:18:50.769Z,1564183130.769 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-26T23:18:50.769Z,1564183130.769 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-26T23:21:38.382Z,1564183298.382 [DVL_micro](ERROR): checksum mismatch: reported94 , calculated:76 2019-07-26T23:21:38.382Z,1564183298.382 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -28 -84 -125 123 3 3 3 -276.3 -30.8 2 210.1 -221.3 -30.8 2 129 -276 -30 2 210 -221 -30 2 0.02 1.46 18.4 -3.0 22.4 0.005 35.0 1489 94 2019-07-26T23:21:42.414Z,1564183302.414 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-07-26T23:21:42.414Z,1564183302.414 [DVL_micro] Data Fault, FailCount= 1 2019-07-26T23:21:42.414Z,1564183302.414 [DVL_micro](ERROR): Data Fault 2019-07-26T23:21:42.446Z,1564183302.446 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-07-26T23:21:42.890Z,1564183302.890 [DVL_micro](INFO): uninitialize:Powering down 2019-07-26T23:21:43.660Z,1564183303.660 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-07-26T23:21:43.661Z,1564183303.661 [DVL_micro] No Fault, FailCount= 1 2019-07-26T23:21:44.040Z,1564183304.040 [DVL_micro](INFO): Initializing 2019-07-26T23:22:33.354Z,1564183353.354 [DataOverHttps](IMPORTANT): SBD MTMSN=20190726T232226 2019-07-26T23:22:38.490Z,1564183358.490 [DataOverHttps](INFO): Received command:restart logs