2019-05-28T17:03:23.558Z,1559063003.558 [Supervisor](DEBUG): Initializing supervisor. 2019-05-28T17:03:23.561Z,1559063003.561 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-05-28T17:03:23.561Z,1559063003.561 [SyncHandler](INFO): Protected caller Thread ID is 2086 2019-05-28T17:03:23.561Z,1559063003.561 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-05-28T17:03:23.562Z,1559063003.562 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-05-28T17:03:23.563Z,1559063003.563 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2087 2019-05-28T17:03:23.566Z,1559063003.566 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-05-28T17:03:23.578Z,1559063003.578 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-05-28T17:03:23.579Z,1559063003.579 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-05-28T17:03:23.579Z,1559063003.579 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2088 2019-05-28T17:03:23.580Z,1559063003.580 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-05-28T17:03:23.581Z,1559063003.581 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-05-28T17:03:23.581Z,1559063003.581 [logger ThreadHandler](INFO): Protected caller Thread ID is 2089 2019-05-28T17:03:23.583Z,1559063003.583 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-05-28T17:03:23.584Z,1559063003.584 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-05-28T17:03:23.586Z,1559063003.586 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-05-28T17:03:23.744Z,1559063003.744 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-05-28T17:03:23.745Z,1559063003.745 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-05-28T17:03:23.947Z,1559063003.947 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-05-28T17:03:23.948Z,1559063003.948 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-05-28T17:03:24.085Z,1559063004.085 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-05-28T17:03:24.086Z,1559063004.086 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-05-28T17:03:24.626Z,1559063004.626 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-05-28T17:03:24.627Z,1559063004.627 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-05-28T17:03:25.082Z,1559063005.082 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-05-28T17:03:25.083Z,1559063005.083 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-05-28T17:03:25.550Z,1559063005.550 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-05-28T17:03:25.551Z,1559063005.551 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-05-28T17:03:25.857Z,1559063005.857 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-05-28T17:03:25.857Z,1559063005.857 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-05-28T17:03:26.208Z,1559063006.208 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-05-28T17:03:26.209Z,1559063006.209 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-05-28T17:03:26.605Z,1559063006.605 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-05-28T17:03:26.606Z,1559063006.606 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-05-28T17:03:26.758Z,1559063006.758 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-05-28T17:03:26.758Z,1559063006.758 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-05-28T17:03:26.866Z,1559063006.866 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-05-28T17:03:26.867Z,1559063006.867 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-05-28T17:03:26.948Z,1559063006.948 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-05-28T17:03:27.050Z,1559063007.050 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-05-28T17:03:27.050Z,1559063007.050 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-05-28T17:03:27.247Z,1559063007.247 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-05-28T17:03:27.247Z,1559063007.247 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-05-28T17:03:27.455Z,1559063007.455 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-05-28T17:03:27.457Z,1559063007.457 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/ 2019-05-28T17:03:27.458Z,1559063007.458 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg 2019-05-28T17:03:27.541Z,1559063007.541 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg 2019-05-28T17:03:27.771Z,1559063007.771 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-05-28T17:03:27.772Z,1559063007.772 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg 2019-05-28T17:03:28.289Z,1559063008.289 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg 2019-05-28T17:03:29.106Z,1559063009.106 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg 2019-05-28T17:03:29.321Z,1559063009.321 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg 2019-05-28T17:03:29.408Z,1559063009.408 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg 2019-05-28T17:03:29.509Z,1559063009.509 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg 2019-05-28T17:03:29.604Z,1559063009.604 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg 2019-05-28T17:03:29.764Z,1559063009.764 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg 2019-05-28T17:03:29.872Z,1559063009.872 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg 2019-05-28T17:03:29.971Z,1559063009.971 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-05-28T17:03:29.989Z,1559063009.989 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-05-28T17:03:30.087Z,1559063010.087 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-05-28T17:03:30.087Z,1559063010.087 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-05-28T17:03:30.223Z,1559063010.223 [BuoyancyServo] Loaded 2019-05-28T17:03:30.224Z,1559063010.224 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-05-28T17:03:30.239Z,1559063010.239 [ElevatorServo] Loaded 2019-05-28T17:03:30.239Z,1559063010.239 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-05-28T17:03:30.253Z,1559063010.253 [MassServo] Loaded 2019-05-28T17:03:30.254Z,1559063010.254 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-05-28T17:03:30.268Z,1559063010.268 [RudderServo] Loaded 2019-05-28T17:03:30.269Z,1559063010.269 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-05-28T17:03:30.283Z,1559063010.283 [ThrusterServo] Loaded 2019-05-28T17:03:30.283Z,1559063010.283 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-05-28T17:03:30.284Z,1559063010.284 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-05-28T17:03:30.284Z,1559063010.284 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-05-28T17:03:30.418Z,1559063010.418 [SBIT](DEBUG): Construct Startup Built In Test. 2019-05-28T17:03:30.447Z,1559063010.447 [SBIT] Loaded 2019-05-28T17:03:30.448Z,1559063010.448 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-05-28T17:03:30.448Z,1559063010.448 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-05-28T17:03:30.477Z,1559063010.477 [IBIT] Loaded 2019-05-28T17:03:30.477Z,1559063010.477 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-05-28T17:03:30.480Z,1559063010.480 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-05-28T17:03:30.865Z,1559063010.865 [CBIT] Loaded 2019-05-28T17:03:30.865Z,1559063010.865 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-05-28T17:03:30.866Z,1559063010.866 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-05-28T17:03:30.866Z,1559063010.866 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-05-28T17:03:31.053Z,1559063011.053 [Aanderaa_O2] Loaded 2019-05-28T17:03:31.054Z,1559063011.054 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2019-05-28T17:03:31.063Z,1559063011.063 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2019-05-28T17:03:31.068Z,1559063011.068 [CTD_Seabird](INFO): created writer for : sea_water_density 2019-05-28T17:03:31.073Z,1559063011.073 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2019-05-28T17:03:31.077Z,1559063011.077 [CTD_Seabird](INFO): created writer for : depth 2019-05-28T17:03:31.078Z,1559063011.078 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2019-05-28T17:03:31.083Z,1559063011.083 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2019-05-28T17:03:31.084Z,1559063011.084 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2019-05-28T17:03:31.089Z,1559063011.089 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2019-05-28T17:03:31.090Z,1559063011.090 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2019-05-28T17:03:31.095Z,1559063011.095 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2019-05-28T17:03:31.096Z,1559063011.096 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2019-05-28T17:03:31.101Z,1559063011.101 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2019-05-28T17:03:31.101Z,1559063011.101 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2019-05-28T17:03:31.106Z,1559063011.106 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2019-05-28T17:03:31.132Z,1559063011.132 [CTD_Seabird] Loaded 2019-05-28T17:03:31.133Z,1559063011.133 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2019-05-28T17:03:31.134Z,1559063011.134 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066A4E0 2019-05-28T17:03:31.134Z,1559063011.134 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 2168 2019-05-28T17:03:31.164Z,1559063011.164 [ESPComponent] Loaded 2019-05-28T17:03:31.164Z,1559063011.164 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2019-05-28T17:03:31.178Z,1559063011.178 [PAR_Licor] Loaded 2019-05-28T17:03:31.178Z,1559063011.178 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-05-28T17:03:31.225Z,1559063011.225 [WetLabsBB2FL] Loaded 2019-05-28T17:03:31.226Z,1559063011.226 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2019-05-28T17:03:31.227Z,1559063011.227 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069A4E0 2019-05-28T17:03:31.227Z,1559063011.227 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2169 2019-05-28T17:03:31.228Z,1559063011.228 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-05-28T17:03:31.228Z,1559063011.228 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-05-28T17:03:31.269Z,1559063011.269 [DepthRateCalculator] Loaded 2019-05-28T17:03:31.270Z,1559063011.270 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-05-28T17:03:31.275Z,1559063011.275 [PitchRateCalculator] Loaded 2019-05-28T17:03:31.276Z,1559063011.276 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-05-28T17:03:31.292Z,1559063011.292 [SpeedCalculator] Loaded 2019-05-28T17:03:31.292Z,1559063011.292 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-05-28T17:03:31.313Z,1559063011.313 [TempGradientCalculator] Loaded 2019-05-28T17:03:31.313Z,1559063011.313 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-05-28T17:03:31.319Z,1559063011.319 [YawRateCalculator] Loaded 2019-05-28T17:03:31.319Z,1559063011.319 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-05-28T17:03:31.352Z,1559063011.352 [ElevatorOffsetCalculator] Loaded 2019-05-28T17:03:31.352Z,1559063011.352 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-05-28T17:03:31.353Z,1559063011.353 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-05-28T17:03:31.353Z,1559063011.353 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-05-28T17:03:31.386Z,1559063011.386 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-05-28T17:03:31.386Z,1559063011.386 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-05-28T17:03:31.489Z,1559063011.489 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-05-28T17:03:31.489Z,1559063011.489 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-05-28T17:03:31.510Z,1559063011.510 [NavChart] Loaded 2019-05-28T17:03:31.510Z,1559063011.510 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-05-28T17:03:31.514Z,1559063011.514 [UniversalFixResidualReporter] Loaded 2019-05-28T17:03:31.515Z,1559063011.515 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-05-28T17:03:31.515Z,1559063011.515 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-05-28T17:03:31.516Z,1559063011.516 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-05-28T17:03:31.874Z,1559063011.874 [AHRS_M2] Loaded 2019-05-28T17:03:31.874Z,1559063011.874 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-05-28T17:03:31.949Z,1559063011.949 [DataOverHttps] Loaded 2019-05-28T17:03:31.949Z,1559063011.949 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-05-28T17:03:31.950Z,1559063011.950 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409734E0 2019-05-28T17:03:31.950Z,1559063011.950 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2170 2019-05-28T17:03:31.963Z,1559063011.963 [Depth_Keller] Loaded 2019-05-28T17:03:31.963Z,1559063011.963 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-05-28T17:03:31.968Z,1559063011.968 [DropWeight] Loaded 2019-05-28T17:03:31.968Z,1559063011.968 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-05-28T17:03:32.096Z,1559063012.096 [DVL_micro] Loaded 2019-05-28T17:03:32.096Z,1559063012.096 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2019-05-28T17:03:32.186Z,1559063012.186 [NAL9602] Loaded 2019-05-28T17:03:32.186Z,1559063012.186 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-05-28T17:03:32.191Z,1559063012.191 [Onboard] Loaded 2019-05-28T17:03:32.191Z,1559063012.191 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-05-28T17:03:32.195Z,1559063012.195 [Radio_Surface] Loaded 2019-05-28T17:03:32.195Z,1559063012.195 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-05-28T17:03:32.196Z,1559063012.196 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A34E0 2019-05-28T17:03:32.196Z,1559063012.196 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2171 2019-05-28T17:03:32.322Z,1559063012.322 [DAT] Loaded 2019-05-28T17:03:32.323Z,1559063012.323 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2019-05-28T17:03:33.887Z,1559063013.887 [BPC1] Loaded 2019-05-28T17:03:33.888Z,1559063013.888 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-05-28T17:03:33.888Z,1559063013.888 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-05-28T17:03:33.889Z,1559063013.889 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-05-28T17:03:33.963Z,1559063013.963 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-05-28T17:03:33.964Z,1559063013.964 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-05-28T17:03:34.034Z,1559063014.034 [VerticalControl](DEBUG): Construct VerticalControl. 2019-05-28T17:03:34.158Z,1559063014.158 [VerticalControl] Loaded 2019-05-28T17:03:34.158Z,1559063014.158 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-05-28T17:03:34.159Z,1559063014.159 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-05-28T17:03:34.215Z,1559063014.215 [HorizontalControl] Loaded 2019-05-28T17:03:34.215Z,1559063014.215 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-05-28T17:03:34.216Z,1559063014.216 [SpeedControl](DEBUG): Construct SpeedControl. 2019-05-28T17:03:34.218Z,1559063014.218 [SpeedControl] Loaded 2019-05-28T17:03:34.218Z,1559063014.218 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-05-28T17:03:34.219Z,1559063014.219 [LoopControl](DEBUG): Construct LoopControl. 2019-05-28T17:03:34.219Z,1559063014.219 [LoopControl] Loaded 2019-05-28T17:03:34.220Z,1559063014.220 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-05-28T17:03:34.220Z,1559063014.220 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-05-28T17:03:34.221Z,1559063014.221 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-05-28T17:03:34.234Z,1559063014.234 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-05-28T17:03:34.235Z,1559063014.235 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-05-28T17:03:34.528Z,1559063014.528 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-05-28T17:03:34.532Z,1559063014.532 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-05-28T17:03:34.533Z,1559063014.533 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-05-28T17:03:34.540Z,1559063014.540 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-05-28T17:03:34.541Z,1559063014.541 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADE4E0 2019-05-28T17:03:34.541Z,1559063014.541 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2172 2019-05-28T17:03:34.546Z,1559063014.546 [Supervisor](INFO): Main Thread ID is 803 2019-05-28T17:03:34.546Z,1559063014.546 [Supervisor](DEBUG): Running supervisor. 2019-05-28T17:03:34.547Z,1559063014.547 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2173 2019-05-28T17:03:34.549Z,1559063014.549 [controlThread ThreadHandler](INFO): Handler Thread ID is 2174 2019-05-28T17:03:34.549Z,1559063014.549 [controlThread](DEBUG): Initializing ControlThread 2019-05-28T17:03:34.551Z,1559063014.551 [SBIT](INFO): Initialize SBIT Component. 2019-05-28T17:03:34.552Z,1559063014.552 [SBIT](IMPORTANT): git: 2019-05-21 2019-05-28T17:03:34.552Z,1559063014.552 [SBIT](INFO): git hash: d33b11e57afc4926c4e35bc3081773f5ba5b446b 2019-05-28T17:03:34.552Z,1559063014.552 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-05-28T17:03:34.554Z,1559063014.554 [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-05-28T17:03:34.555Z,1559063014.555 [SBIT](INFO): Beginning SBIT in 48.000000 seconds. 2019-05-28T17:03:34.555Z,1559063014.555 [IBIT](INFO): Initialize IBIT Component. 2019-05-28T17:03:34.556Z,1559063014.556 [CBIT](DEBUG): Initialize CBIT Component. 2019-05-28T17:03:34.557Z,1559063014.557 [logger ThreadHandler](INFO): Handler Thread ID is 2175 2019-05-28T17:03:34.569Z,1559063014.569 [CBIT](DEBUG): Initialized mux pins. 2019-05-28T17:03:34.569Z,1559063014.569 [CBIT](DEBUG): Initializing the watchdog timer. 2019-05-28T17:03:34.577Z,1559063014.577 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 2176 2019-05-28T17:03:34.578Z,1559063014.578 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2019-05-28T17:03:34.581Z,1559063014.581 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20 2019-05-28T17:03:34.583Z,1559063014.583 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2178 2019-05-28T17:03:34.584Z,1559063014.584 [WetLabsBB2FL](INFO): Powering down 2019-05-28T17:03:34.593Z,1559063014.593 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-05-28T17:03:34.593Z,1559063014.593 [CBIT](DEBUG): Initializing heartbeat. 2019-05-28T17:03:34.613Z,1559063014.613 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2179 2019-05-28T17:03:34.614Z,1559063014.614 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-05-28T17:03:34.625Z,1559063014.625 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2180 2019-05-28T17:03:34.641Z,1559063014.641 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2181 2019-05-28T17:03:34.647Z,1559063014.647 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-05-28T17:03:34.647Z,1559063014.647 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-05-28T17:03:34.647Z,1559063014.647 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-05-28T17:03:34.648Z,1559063014.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-05-28T17:03:34.648Z,1559063014.648 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-05-28T17:03:34.648Z,1559063014.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-05-28T17:03:34.648Z,1559063014.648 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-05-28T17:03:34.648Z,1559063014.648 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-05-28T17:03:34.649Z,1559063014.649 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-05-28T17:03:34.649Z,1559063014.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-05-28T17:03:34.649Z,1559063014.649 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-05-28T17:03:34.649Z,1559063014.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-05-28T17:03:34.649Z,1559063014.649 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-05-28T17:03:34.649Z,1559063014.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-05-28T17:03:34.650Z,1559063014.650 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-05-28T17:03:34.650Z,1559063014.650 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-05-28T17:03:34.665Z,1559063014.665 [CBIT](DEBUG): Deactivating GF circuits. 2019-05-28T17:03:34.665Z,1559063014.665 [CBIT](DEBUG): Deactivating emergency mode. 2019-05-28T17:03:34.701Z,1559063014.701 [CBIT](DEBUG): Backplane powered. 2019-05-28T17:03:34.705Z,1559063014.705 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-05-28T17:03:34.705Z,1559063014.705 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-05-28T17:03:34.706Z,1559063014.706 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-05-28T17:03:34.706Z,1559063014.706 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-05-28T17:03:34.707Z,1559063014.707 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-05-28T17:03:34.707Z,1559063014.707 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-05-28T17:03:34.708Z,1559063014.708 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-05-28T17:03:34.709Z,1559063014.709 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-05-28T17:03:34.720Z,1559063014.720 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-05-28T17:03:34.725Z,1559063014.725 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-05-28T17:03:34.726Z,1559063014.726 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-05-28T17:03:34.727Z,1559063014.727 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-05-28T17:03:34.727Z,1559063014.727 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-05-28T17:03:34.756Z,1559063014.756 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-28T17:03:34.792Z,1559063014.792 [MissionManager](DEBUG): 2019-05-28T17:03:34.792Z,1559063014.792 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-05-28T17:03:34.859Z,1559063014.859 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-05-28T17:03:34.877Z,1559063014.877 [Default:A.Wait](DEBUG): Construct Wait. 2019-05-28T17:03:34.878Z,1559063014.878 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-28T17:03:34.905Z,1559063014.905 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-05-28T17:03:34.908Z,1559063014.908 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-05-28T17:03:34.929Z,1559063014.929 [Default:E.Execute](DEBUG): Construct Execute. 2019-05-28T17:03:34.942Z,1559063014.942 [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-05-28T17:03:34.957Z,1559063014.957 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,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-05-28T17:03:35.009Z,1559063015.009 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-05-28T17:03:35.029Z,1559063015.029 [Radio_Surface](INFO): Powering up 2019-05-28T17:03:35.058Z,1559063015.058 [DVL_micro](INFO): Initializing 2019-05-28T17:03:35.087Z,1559063015.087 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2019-05-28T17:03:35.087Z,1559063015.087 [DAT](INFO): Powering up 2019-05-28T17:03:35.087Z,1559063015.087 [DAT](DEBUG): Initializing DAT. 2019-05-28T17:03:35.145Z,1559063015.145 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2019-05-28T17:03:35.203Z,1559063015.203 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-05-28T17:03:35.213Z,1559063015.213 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-05-28T17:03:35.215Z,1559063015.215 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-05-28T17:03:35.225Z,1559063015.225 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-05-28T17:03:35.226Z,1559063015.226 [MassServo](DEBUG): Initializing EZServoServo. 2019-05-28T17:03:35.237Z,1559063015.237 [MassServo](DEBUG): Initializing MassServo. 2019-05-28T17:03:35.238Z,1559063015.238 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-28T17:03:35.249Z,1559063015.249 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-28T17:03:35.250Z,1559063015.250 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-05-28T17:03:35.257Z,1559063015.257 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-05-28T17:03:36.149Z,1559063016.149 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-05-28T17:03:36.149Z,1559063016.149 [RudderServo](FAULT): Rudder failed to initialize 2019-05-28T17:03:36.149Z,1559063016.149 [RudderServo] Communications Fault, FailCount= 1 2019-05-28T17:03:36.149Z,1559063016.149 [RudderServo](ERROR): Communications Fault 2019-05-28T17:03:36.262Z,1559063016.262 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-05-28T17:03:36.487Z,1559063016.487 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-05-28T17:03:36.488Z,1559063016.488 [RudderServo](INFO): Powering down 2019-05-28T17:03:37.128Z,1559063017.128 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-28T17:03:37.262Z,1559063017.262 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-28T17:03:37.266Z,1559063017.266 [CBIT](INFO): Clearing failed state for component RudderServo 2019-05-28T17:03:37.266Z,1559063017.266 [RudderServo] No Fault, FailCount= 1 2019-05-28T17:03:38.405Z,1559063018.405 [Aanderaa_O2](INFO): Powering down 2019-05-28T17:03:50.497Z,1559063030.497 [DAT](INFO): setting local address to 3 2019-05-28T17:03:50.905Z,1559063030.905 [DAT](INFO): set local address to 3 2019-05-28T17:04:02.195Z,1559063042.195 [NAL9602](INFO): Powering up NAL9602 2019-05-28T17:04:13.103Z,1559063053.103 [NAL9602](INFO): NAL9602 initialized 2019-05-28T17:04:13.953Z,1559063053.953 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:04:23.263Z,1559063063.263 [SBIT](IMPORTANT): Beginning Startup BIT 2019-05-28T17:04:23.271Z,1559063063.271 [CBIT](IMPORTANT): Beginning ground fault scan 2019-05-28T17:04:34.002Z,1559063074.002 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.011363 CHAN A1 (24V): -0.024005 CHAN A2 (12V): -0.005402 CHAN A3 (5V): -0.002340 CHAN B0 (3.3V): -0.001437 CHAN B1 (3.15aV): -0.001003 CHAN B2 (3.15bV): -0.001514 CHAN B3 (GND): 0.000386 OPEN: 0.006853 Full Scale Calc: 4.765 mA, -1.589 mA 2019-05-28T17:04:45.719Z,1559063085.719 [NAL9602](INFO): SBD MO Status=0, MOMSN=26133, MT Status=0, MTMSN=0 2019-05-28T17:04:45.720Z,1559063085.720 [NAL9602](INFO): No messages in MT queue 2019-05-28T17:04:46.533Z,1559063086.533 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:04:46.921Z,1559063086.921 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170338.00,A,3648.16341,N,12147.21506,W,0.311,0.00,280519,,,A*7F 2019-05-28T17:04:46.924Z,1559063086.924 [NAL9602](INFO): GPS fix at 20190528T170338: (36.802723, -121.786918) 2019-05-28T17:05:17.044Z,1559063117.044 [SBIT](IMPORTANT): SBIT PASSED 2019-05-28T17:05:17.106Z,1559063117.106 [CommandLine](IMPORTANT): got command configSet list 2019-05-28T17:05:17.106Z,1559063117.106 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-05-28T17:05:17.107Z,1559063117.107 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=1 bool; 2019-05-28T17:05:17.107Z,1559063117.107 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup=0 bool; 2019-05-28T17:05:17.107Z,1559063117.107 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count; 2019-05-28T17:05:17.107Z,1559063117.107 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour; 2019-05-28T17:05:17.107Z,1559063117.107 [CommandLine](IMPORTANT): BR_Ping1D.verbosity=1 count; 2019-05-28T17:05:17.107Z,1559063117.107 [CommandLine](IMPORTANT): CBIT.abortDepth=300 meter; 2019-05-28T17:05:17.107Z,1559063117.107 [CommandLine](IMPORTANT): CBIT.stopDepth=295 meter; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle=1 bool; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=1 bool; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=1 bool; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): Express linearApproximation DAT.range 20.000000 meter; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): PAR_Licor.adcCal=8.765e-06 microampere_per_count; 2019-05-28T17:05:17.108Z,1559063117.108 [CommandLine](IMPORTANT): PAR_Licor.darkCount=0 count; 2019-05-28T17:05:17.109Z,1559063117.109 [CommandLine](IMPORTANT): PAR_Licor.multiplier=190.3 micromole_per_second_per_square_meter_per_microampere; 2019-05-28T17:05:17.109Z,1559063117.109 [CommandLine](IMPORTANT): PNI_TCM.loadAtStartup=0 bool; 2019-05-28T17:05:17.109Z,1559063117.109 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool; 2019-05-28T17:05:17.109Z,1559063117.109 [CommandLine](IMPORTANT): VerticalControl.massDefault=-7 millimeter; 2019-05-28T17:05:17.430Z,1559063117.430 [MissionManager](IMPORTANT): Started mission Startup 2019-05-28T17:05:17.430Z,1559063117.430 [Startup] Running Loop=1 2019-05-28T17:05:17.430Z,1559063117.430 [Startup](DEBUG): Aggregate::initialize Startup 2019-05-28T17:05:17.430Z,1559063117.430 [Startup:A.GoToSurface] Running Loop=1 2019-05-28T17:05:17.430Z,1559063117.430 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-28T17:05:17.431Z,1559063117.431 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-28T17:05:17.432Z,1559063117.432 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-28T17:05:17.432Z,1559063117.432 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-28T17:05:17.432Z,1559063117.432 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-28T17:05:17.433Z,1559063117.433 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-28T17:05:17.434Z,1559063117.434 [Startup:StartupSatComms] Running Loop=1 2019-05-28T17:05:17.434Z,1559063117.434 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-05-28T17:05:17.435Z,1559063117.435 [Startup:StartupSatComms:A] Running Loop=1 2019-05-28T17:05:17.845Z,1559063117.845 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-05-28T17:05:19.041Z,1559063119.041 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:05:19.432Z,1559063119.432 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170410.00,A,3648.16211,N,12147.21773,W,0.039,0.00,280519,,,A*7F 2019-05-28T17:05:19.435Z,1559063119.435 [NAL9602](INFO): GPS fix at 20190528T170410: (36.802702, -121.786962) 2019-05-28T17:05:19.459Z,1559063119.459 [Startup:StartupSatComms:A] Stopped 2019-05-28T17:05:19.459Z,1559063119.459 [Startup:StartupSatComms:B] Running Loop=1 2019-05-28T17:05:19.886Z,1559063119.886 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-28T17:05:37.790Z,1559063137.790 [NAL9602](INFO): SBD MO Status=1, MOMSN=26134, MT Status=0, MTMSN=0 2019-05-28T17:05:37.841Z,1559063137.841 [NAL9602](INFO): Sent 25 bytes from file Logs/20190528T045030/Courier0234.lzma 2019-05-28T17:05:37.841Z,1559063137.841 [NAL9602](INFO): Packets left to send: 0 2019-05-28T17:05:57.319Z,1559063157.319 [NAL9602](INFO): SBD MO Status=1, MOMSN=26135, MT Status=0, MTMSN=0 2019-05-28T17:05:57.373Z,1559063157.373 [NAL9602](INFO): Sent 25 bytes from file Logs/20190528T045030/Courier0238.lzma 2019-05-28T17:05:57.373Z,1559063157.373 [NAL9602](INFO): Packets left to send: 0 2019-05-28T17:06:19.769Z,1559063179.769 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-28T17:05:19.5Z 2019-05-28T17:06:19.769Z,1559063179.769 [Startup:StartupSatComms:B] Stopped 2019-05-28T17:06:19.769Z,1559063179.769 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-05-28T17:06:19.769Z,1559063179.769 [Startup:StartupSatComms] Stopped 2019-05-28T17:06:19.769Z,1559063179.769 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-05-28T17:06:19.770Z,1559063179.770 [Startup](INFO): Completed Startup 2019-05-28T17:06:19.770Z,1559063179.770 [MissionManager](INFO): Startup is completed. 2019-05-28T17:06:19.770Z,1559063179.770 [MissionManager](INFO): Uninitializing Mission Startup 2019-05-28T17:06:19.770Z,1559063179.770 [Startup] Stopped 2019-05-28T17:06:19.771Z,1559063179.771 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-05-28T17:06:19.771Z,1559063179.771 [Startup:A.GoToSurface] Stopped 2019-05-28T17:06:19.771Z,1559063179.771 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-28T17:06:20.174Z,1559063180.174 [MissionManager](IMPORTANT): Started mission Default 2019-05-28T17:06:20.174Z,1559063180.174 [Default] Running Loop=1 2019-05-28T17:06:20.174Z,1559063180.174 [Default](DEBUG): Aggregate::initialize Default 2019-05-28T17:06:20.174Z,1559063180.174 [Default:B.GoToSurface] Running Loop=1 2019-05-28T17:06:20.174Z,1559063180.174 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-28T17:06:20.175Z,1559063180.175 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-28T17:06:20.175Z,1559063180.175 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-28T17:06:20.175Z,1559063180.175 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-28T17:06:20.176Z,1559063180.176 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-28T17:06:20.176Z,1559063180.176 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-28T17:06:20.176Z,1559063180.176 [Default:A.Wait] Running Loop=1 2019-05-28T17:06:20.176Z,1559063180.176 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-05-28T17:06:33.506Z,1559063193.506 [Default:A.Wait](INFO): Done Waiting. 2019-05-28T17:06:33.506Z,1559063193.506 [Default:A.Wait] Stopped 2019-05-28T17:06:33.506Z,1559063193.506 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-05-28T17:06:33.906Z,1559063193.906 [Default:CheckIn] Running Loop=1 2019-05-28T17:06:33.906Z,1559063193.906 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-28T17:06:33.906Z,1559063193.906 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-28T17:06:34.344Z,1559063194.344 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-05-28T17:06:39.536Z,1559063199.536 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-28T17:06:39.536Z,1559063199.536 [DVL_micro] Data Fault, FailCount= 1 2019-05-28T17:06:39.536Z,1559063199.536 [DVL_micro](ERROR): Data Fault 2019-05-28T17:06:39.571Z,1559063199.571 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-28T17:06:40.014Z,1559063200.014 [DVL_micro](INFO): uninitialize:Powering down 2019-05-28T17:06:40.782Z,1559063200.782 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-28T17:06:40.782Z,1559063200.782 [DVL_micro] No Fault, FailCount= 1 2019-05-28T17:06:41.166Z,1559063201.166 [DVL_micro](INFO): Initializing 2019-05-28T17:07:07.034Z,1559063227.034 [NAL9602](FAULT): Verify xmit timeout failure. 2019-05-28T17:07:07.035Z,1559063227.035 [NAL9602] Data Fault, FailCount= 1 2019-05-28T17:07:07.035Z,1559063227.035 [NAL9602](ERROR): Data Fault 2019-05-28T17:07:07.068Z,1559063227.068 [CBIT](ERROR): Data Fault in component: NAL9602 2019-05-28T17:07:07.425Z,1559063227.425 [NAL9602](INFO): Powering down 2019-05-28T17:07:08.278Z,1559063228.278 [CBIT](INFO): Clearing failed state for component NAL9602 2019-05-28T17:07:08.278Z,1559063228.278 [NAL9602] No Fault, FailCount= 1 2019-05-28T17:07:17.059Z,1559063237.059 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005006 2019-05-28T17:07:37.721Z,1559063257.721 [NAL9602](INFO): Powering up NAL9602 2019-05-28T17:07:48.631Z,1559063268.631 [NAL9602](INFO): NAL9602 initialized 2019-05-28T17:07:49.453Z,1559063269.453 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:07:52.685Z,1559063272.685 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:07:55.537Z,1559063275.537 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:07:58.777Z,1559063278.777 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:01.565Z,1559063281.565 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:04.801Z,1559063284.801 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:07.633Z,1559063287.633 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:10.873Z,1559063290.873 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:13.689Z,1559063293.689 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:16.921Z,1559063296.921 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:16.943Z,1559063296.943 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file). 2019-05-28T17:08:19.749Z,1559063299.749 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:22.977Z,1559063302.977 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:25.805Z,1559063305.805 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:28.641Z,1559063308.641 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:31.865Z,1559063311.865 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:34.705Z,1559063314.705 [NAL9602](DEBUG): Fix Requested 2019-05-28T17:08:35.086Z,1559063315.086 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170726.00,A,3648.16507,N,12147.21593,W,0.078,324.31,280519,,,A*77 2019-05-28T17:08:35.088Z,1559063315.088 [NAL9602](INFO): GPS fix at 20190528T170726: (36.802751, -121.786932) 2019-05-28T17:08:35.136Z,1559063315.136 [Default:CheckIn:Read_GPS] Stopped 2019-05-28T17:08:35.136Z,1559063315.136 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-28T17:08:35.543Z,1559063315.543 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-28T17:08:43.722Z,1559063323.722 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190528T170323/Courier0000.lzma 2019-05-28T17:08:44.526Z,1559063324.526 [DataOverHttps](INFO): Moved sent file to Logs/20190528T170323/Courier0000.lzma.bak 2019-05-28T17:08:44.526Z,1559063324.526 [DataOverHttps](INFO): SBD MOMSN=11205840 2019-05-28T17:08:57.572Z,1559063337.572 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190528T170323/Courier0004.lzma 2019-05-28T17:08:58.378Z,1559063338.378 [DataOverHttps](INFO): Moved sent file to Logs/20190528T170323/Courier0004.lzma.bak 2019-05-28T17:08:58.378Z,1559063338.378 [DataOverHttps](INFO): SBD MOMSN=11205845 2019-05-28T17:09:03.380Z,1559063343.380 [DVL_micro](ERROR): only read 45 of 46 data items 2019-05-28T17:09:03.381Z,1559063343.381 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 2148 156 59 -37 2 3 2 2 2788.1 257.6 627. 2799.7 627.2 2 2788 257 627 2 25 2799 627 2 -3.75 1.78 84.2 -3.0 24.2 00 1489 75 2019-05-28T17:09:07.812Z,1559063347.812 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-28T17:09:14.177Z,1559063354.177 [DataOverHttps](INFO): Sending 409 bytes from file Logs/20190528T045030/Express0230.lzma 2019-05-28T17:09:14.983Z,1559063354.983 [DataOverHttps](INFO): Moved sent file to Logs/20190528T045030/Express0230.lzma.bak 2019-05-28T17:09:14.983Z,1559063354.983 [DataOverHttps](INFO): SBD MOMSN=11205848 2019-05-28T17:09:36.060Z,1559063376.060 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190528T045030/Express0231.lzma 2019-05-28T17:09:36.867Z,1559063376.867 [DataOverHttps](INFO): Moved sent file to Logs/20190528T045030/Express0231.lzma.bak 2019-05-28T17:09:36.867Z,1559063376.867 [DataOverHttps](INFO): SBD MOMSN=11205860 2019-05-28T17:09:45.468Z,1559063385.468 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-28T17:09:45.468Z,1559063385.468 [DVL_micro] Data Fault, FailCount= 1 2019-05-28T17:09:45.468Z,1559063385.468 [DVL_micro](ERROR): Data Fault 2019-05-28T17:09:45.574Z,1559063385.574 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-28T17:09:45.949Z,1559063385.949 [DVL_micro](INFO): uninitialize:Powering down 2019-05-28T17:09:46.733Z,1559063386.733 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-28T17:09:46.733Z,1559063386.733 [DVL_micro] No Fault, FailCount= 1 2019-05-28T17:09:47.105Z,1559063387.105 [DVL_micro](INFO): Initializing 2019-05-28T17:09:52.751Z,1559063392.751 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 0.000000 meter 2019-05-28T17:09:52.753Z,1559063392.753 [ComponentRegistry](DEBUG): SyncComponen