2019-05-30T18:12:38.924Z,1559239958.924 [Supervisor](DEBUG): Initializing supervisor. 2019-05-30T18:12:38.927Z,1559239958.927 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-05-30T18:12:38.928Z,1559239958.928 [SyncHandler](INFO): Protected caller Thread ID is 2170 2019-05-30T18:12:38.928Z,1559239958.928 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-05-30T18:12:38.929Z,1559239958.929 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-05-30T18:12:38.929Z,1559239958.929 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2171 2019-05-30T18:12:38.932Z,1559239958.932 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-05-30T18:12:39.156Z,1559239959.156 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-05-30T18:12:39.157Z,1559239959.157 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-05-30T18:12:39.158Z,1559239959.158 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2172 2019-05-30T18:12:39.158Z,1559239959.158 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-05-30T18:12:39.159Z,1559239959.159 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-05-30T18:12:39.160Z,1559239959.160 [logger ThreadHandler](INFO): Protected caller Thread ID is 2173 2019-05-30T18:12:39.162Z,1559239959.162 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-05-30T18:12:39.162Z,1559239959.162 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-05-30T18:12:39.164Z,1559239959.164 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-05-30T18:12:39.587Z,1559239959.587 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-05-30T18:12:39.588Z,1559239959.588 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-05-30T18:12:39.687Z,1559239959.687 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-05-30T18:12:39.687Z,1559239959.687 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-05-30T18:12:40.030Z,1559239960.030 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-05-30T18:12:40.031Z,1559239960.031 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-05-30T18:12:40.174Z,1559239960.174 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-05-30T18:12:40.175Z,1559239960.175 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-05-30T18:12:40.369Z,1559239960.369 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-05-30T18:12:40.369Z,1559239960.369 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-05-30T18:12:40.826Z,1559239960.826 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-05-30T18:12:40.826Z,1559239960.826 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-05-30T18:12:41.038Z,1559239961.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-05-30T18:12:41.038Z,1559239961.038 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-05-30T18:12:41.186Z,1559239961.186 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-05-30T18:12:41.187Z,1559239961.187 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-05-30T18:12:41.382Z,1559239961.382 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-05-30T18:12:41.382Z,1559239961.382 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-05-30T18:12:41.479Z,1559239961.479 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-05-30T18:12:41.480Z,1559239961.480 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-05-30T18:12:41.803Z,1559239961.803 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-05-30T18:12:41.803Z,1559239961.803 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-05-30T18:12:41.886Z,1559239961.886 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-05-30T18:12:41.993Z,1559239961.993 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-05-30T18:12:41.993Z,1559239961.993 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-05-30T18:12:42.597Z,1559239962.597 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-05-30T18:12:42.598Z,1559239962.598 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-05-30T18:12:42.989Z,1559239962.989 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-05-30T18:12:42.991Z,1559239962.991 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/ 2019-05-30T18:12:42.992Z,1559239962.992 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg 2019-05-30T18:12:43.208Z,1559239963.208 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg 2019-05-30T18:12:43.311Z,1559239963.311 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg 2019-05-30T18:12:43.412Z,1559239963.412 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg 2019-05-30T18:12:43.642Z,1559239963.642 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-05-30T18:12:43.643Z,1559239963.643 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg 2019-05-30T18:12:43.765Z,1559239963.765 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg 2019-05-30T18:12:43.913Z,1559239963.913 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg 2019-05-30T18:12:44.063Z,1559239964.063 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg 2019-05-30T18:12:44.183Z,1559239964.183 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg 2019-05-30T18:12:44.448Z,1559239964.448 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg 2019-05-30T18:12:44.784Z,1559239964.784 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg 2019-05-30T18:12:44.917Z,1559239964.917 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/LOGIN/ 2019-05-30T18:12:44.917Z,1559239964.917 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-05-30T18:12:44.932Z,1559239964.932 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-05-30T18:12:45.317Z,1559239965.317 [AHRS_M2] Loaded 2019-05-30T18:12:45.317Z,1559239965.317 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-05-30T18:12:45.331Z,1559239965.331 [Depth_Keller] Loaded 2019-05-30T18:12:45.331Z,1559239965.331 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-05-30T18:12:45.336Z,1559239965.336 [DropWeight] Loaded 2019-05-30T18:12:45.336Z,1559239965.336 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-05-30T18:12:45.394Z,1559239965.394 [DUSBL_Hydroid] Loaded 2019-05-30T18:12:45.394Z,1559239965.394 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread. 2019-05-30T18:12:45.442Z,1559239965.442 [Micromodem] Loaded 2019-05-30T18:12:45.442Z,1559239965.442 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2019-05-30T18:12:45.541Z,1559239965.541 [NAL9602] Loaded 2019-05-30T18:12:45.541Z,1559239965.541 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-05-30T18:12:45.557Z,1559239965.557 [Onboard] Loaded 2019-05-30T18:12:45.557Z,1559239965.557 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-05-30T18:12:45.563Z,1559239965.563 [PowerOnly] Loaded 2019-05-30T18:12:45.564Z,1559239965.564 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2019-05-30T18:12:45.574Z,1559239965.574 [Radio_Surface] Loaded 2019-05-30T18:12:45.574Z,1559239965.574 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-05-30T18:12:45.575Z,1559239965.575 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407644E0 2019-05-30T18:12:45.576Z,1559239965.576 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2252 2019-05-30T18:12:45.621Z,1559239965.621 [RDI_Pathfinder] Loaded 2019-05-30T18:12:45.621Z,1559239965.621 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2019-05-30T18:12:47.133Z,1559239967.133 [BPC1] Loaded 2019-05-30T18:12:47.133Z,1559239967.133 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-05-30T18:12:47.134Z,1559239967.134 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-05-30T18:12:47.134Z,1559239967.134 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-05-30T18:12:47.147Z,1559239967.147 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-05-30T18:12:47.148Z,1559239967.148 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-05-30T18:12:47.255Z,1559239967.255 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-05-30T18:12:47.255Z,1559239967.255 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-05-30T18:12:47.276Z,1559239967.276 [NavChart] Loaded 2019-05-30T18:12:47.276Z,1559239967.276 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-05-30T18:12:47.280Z,1559239967.280 [UniversalFixResidualReporter] Loaded 2019-05-30T18:12:47.280Z,1559239967.280 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-05-30T18:12:47.281Z,1559239967.281 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-05-30T18:12:47.281Z,1559239967.281 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-05-30T18:12:47.390Z,1559239967.390 [BuoyancyServo] Loaded 2019-05-30T18:12:47.390Z,1559239967.390 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-05-30T18:12:47.405Z,1559239967.405 [ElevatorServo] Loaded 2019-05-30T18:12:47.406Z,1559239967.406 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-05-30T18:12:47.420Z,1559239967.420 [MassServo] Loaded 2019-05-30T18:12:47.421Z,1559239967.421 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-05-30T18:12:47.436Z,1559239967.436 [RudderServo] Loaded 2019-05-30T18:12:47.436Z,1559239967.436 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-05-30T18:12:47.451Z,1559239967.451 [ThrusterServo] Loaded 2019-05-30T18:12:47.451Z,1559239967.451 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-05-30T18:12:47.452Z,1559239967.452 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-05-30T18:12:47.452Z,1559239967.452 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-05-30T18:12:47.704Z,1559239967.704 [CTD_NeilBrown] Loaded 2019-05-30T18:12:47.704Z,1559239967.704 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-05-30T18:12:47.705Z,1559239967.705 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408A64E0 2019-05-30T18:12:47.705Z,1559239967.705 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2253 2019-05-30T18:12:47.750Z,1559239967.750 [WetLabsSeaOWL_UV_A] Loaded 2019-05-30T18:12:47.751Z,1559239967.751 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2019-05-30T18:12:47.752Z,1559239967.752 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408D64E0 2019-05-30T18:12:47.752Z,1559239967.752 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 2254 2019-05-30T18:12:47.753Z,1559239967.753 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-05-30T18:12:47.753Z,1559239967.753 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-05-30T18:12:48.056Z,1559239968.056 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-05-30T18:12:48.056Z,1559239968.056 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-05-30T18:12:48.097Z,1559239968.097 [DepthRateCalculator] Loaded 2019-05-30T18:12:48.097Z,1559239968.097 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-05-30T18:12:48.103Z,1559239968.103 [PitchRateCalculator] Loaded 2019-05-30T18:12:48.103Z,1559239968.103 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-05-30T18:12:48.116Z,1559239968.116 [SpeedCalculator] Loaded 2019-05-30T18:12:48.116Z,1559239968.116 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-05-30T18:12:48.137Z,1559239968.137 [TempGradientCalculator] Loaded 2019-05-30T18:12:48.137Z,1559239968.137 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-05-30T18:12:48.143Z,1559239968.143 [YawRateCalculator] Loaded 2019-05-30T18:12:48.143Z,1559239968.143 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-05-30T18:12:48.184Z,1559239968.184 [ElevatorOffsetCalculator] Loaded 2019-05-30T18:12:48.184Z,1559239968.184 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-05-30T18:12:48.184Z,1559239968.184 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-05-30T18:12:48.185Z,1559239968.185 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-05-30T18:12:48.324Z,1559239968.324 [SBIT](DEBUG): Construct Startup Built In Test. 2019-05-30T18:12:48.346Z,1559239968.346 [SBIT] Loaded 2019-05-30T18:12:48.346Z,1559239968.346 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-05-30T18:12:48.347Z,1559239968.347 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-05-30T18:12:48.358Z,1559239968.358 [IBIT] Loaded 2019-05-30T18:12:48.359Z,1559239968.359 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-05-30T18:12:48.362Z,1559239968.362 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-05-30T18:12:48.501Z,1559239968.501 [CBIT] Loaded 2019-05-30T18:12:48.501Z,1559239968.501 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-05-30T18:12:48.501Z,1559239968.501 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-05-30T18:12:48.502Z,1559239968.502 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-05-30T18:12:48.573Z,1559239968.573 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-05-30T18:12:48.573Z,1559239968.573 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-05-30T18:12:48.675Z,1559239968.675 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-05-30T18:12:48.676Z,1559239968.676 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-05-30T18:12:48.743Z,1559239968.743 [VerticalControl](DEBUG): Construct VerticalControl. 2019-05-30T18:12:48.826Z,1559239968.826 [VerticalControl] Loaded 2019-05-30T18:12:48.827Z,1559239968.827 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-05-30T18:12:48.828Z,1559239968.828 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-05-30T18:12:48.885Z,1559239968.885 [HorizontalControl] Loaded 2019-05-30T18:12:48.885Z,1559239968.885 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-05-30T18:12:48.886Z,1559239968.886 [SpeedControl](DEBUG): Construct SpeedControl. 2019-05-30T18:12:48.888Z,1559239968.888 [SpeedControl] Loaded 2019-05-30T18:12:48.888Z,1559239968.888 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-05-30T18:12:48.889Z,1559239968.889 [LoopControl](DEBUG): Construct LoopControl. 2019-05-30T18:12:48.889Z,1559239968.889 [LoopControl] Loaded 2019-05-30T18:12:48.890Z,1559239968.890 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-05-30T18:12:48.890Z,1559239968.890 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-05-30T18:12:48.891Z,1559239968.891 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-05-30T18:12:48.958Z,1559239968.958 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-05-30T18:12:48.961Z,1559239968.961 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-05-30T18:12:48.962Z,1559239968.962 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-05-30T18:12:48.969Z,1559239968.969 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-05-30T18:12:48.970Z,1559239968.970 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AAD4E0 2019-05-30T18:12:48.971Z,1559239968.971 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2255 2019-05-30T18:12:48.975Z,1559239968.975 [Supervisor](INFO): Main Thread ID is 2169 2019-05-30T18:12:48.975Z,1559239968.975 [Supervisor](DEBUG): Running supervisor. 2019-05-30T18:12:48.976Z,1559239968.976 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2256 2019-05-30T18:12:48.978Z,1559239968.978 [controlThread ThreadHandler](INFO): Handler Thread ID is 2257 2019-05-30T18:12:48.978Z,1559239968.978 [controlThread](DEBUG): Initializing ControlThread 2019-05-30T18:12:48.987Z,1559239968.987 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-05-30T18:12:48.987Z,1559239968.987 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-05-30T18:12:48.988Z,1559239968.988 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-05-30T18:12:48.989Z,1559239968.989 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-05-30T18:12:48.989Z,1559239968.989 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-05-30T18:12:48.989Z,1559239968.989 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-05-30T18:12:48.990Z,1559239968.990 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-05-30T18:12:48.990Z,1559239968.990 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-05-30T18:12:48.991Z,1559239968.991 [SBIT](INFO): Initialize SBIT Component. 2019-05-30T18:12:48.991Z,1559239968.991 [SBIT](IMPORTANT): git: 2019-05-01-19-g6ef4ecc 2019-05-30T18:12:48.991Z,1559239968.991 [SBIT](INFO): git hash: 6ef4ecc926d3cc84e5878e2d73d98fd38ff7dcf7 2019-05-30T18:12:48.992Z,1559239968.992 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-05-30T18:12:48.993Z,1559239968.993 [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-30T18:12:48.994Z,1559239968.994 [SBIT](INFO): Beginning SBIT in 39.000000 seconds. 2019-05-30T18:12:48.995Z,1559239968.995 [IBIT](INFO): Initialize IBIT Component. 2019-05-30T18:12:48.996Z,1559239968.996 [CBIT](DEBUG): Initialize CBIT Component. 2019-05-30T18:12:48.996Z,1559239968.996 [logger ThreadHandler](INFO): Handler Thread ID is 2258 2019-05-30T18:12:49.007Z,1559239969.007 [CBIT](DEBUG): Initialized mux pins. 2019-05-30T18:12:49.007Z,1559239969.007 [CBIT](DEBUG): Initializing the watchdog timer. 2019-05-30T18:12:49.012Z,1559239969.012 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2259 2019-05-30T18:12:49.014Z,1559239969.014 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2260 2019-05-30T18:12:49.015Z,1559239969.015 [CTD_NeilBrown](INFO): Powering down 2019-05-30T18:12:49.036Z,1559239969.036 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 2261 2019-05-30T18:12:49.037Z,1559239969.037 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-05-30T18:12:49.051Z,1559239969.051 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-05-30T18:12:49.051Z,1559239969.051 [CBIT](DEBUG): Initializing heartbeat. 2019-05-30T18:12:49.058Z,1559239969.058 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2262 2019-05-30T18:12:49.061Z,1559239969.061 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-05-30T18:12:49.061Z,1559239969.061 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-05-30T18:12:49.062Z,1559239969.062 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-05-30T18:12:49.062Z,1559239969.062 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-05-30T18:12:49.062Z,1559239969.062 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-05-30T18:12:49.062Z,1559239969.062 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-05-30T18:12:49.062Z,1559239969.062 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-05-30T18:12:49.063Z,1559239969.063 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-05-30T18:12:49.065Z,1559239969.065 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-05-30T18:12:49.065Z,1559239969.065 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-05-30T18:12:49.065Z,1559239969.065 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-05-30T18:12:49.066Z,1559239969.066 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-05-30T18:12:49.066Z,1559239969.066 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-05-30T18:12:49.066Z,1559239969.066 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-05-30T18:12:49.066Z,1559239969.066 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-05-30T18:12:49.066Z,1559239969.066 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-05-30T18:12:49.123Z,1559239969.123 [CBIT](DEBUG): Deactivating GF circuits. 2019-05-30T18:12:49.123Z,1559239969.123 [CBIT](DEBUG): Deactivating emergency mode. 2019-05-30T18:12:49.159Z,1559239969.159 [CBIT](DEBUG): Backplane powered. 2019-05-30T18:12:49.159Z,1559239969.159 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-05-30T18:12:49.161Z,1559239969.161 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-05-30T18:12:49.162Z,1559239969.162 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-05-30T18:12:49.162Z,1559239969.162 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-05-30T18:12:49.163Z,1559239969.163 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-05-30T18:12:49.173Z,1559239969.173 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-30T18:12:49.200Z,1559239969.200 [MissionManager](DEBUG): 2019-05-30T18:12:49.201Z,1559239969.201 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-05-30T18:12:49.271Z,1559239969.271 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-05-30T18:12:49.272Z,1559239969.272 [Default:A.Wait](DEBUG): Construct Wait. 2019-05-30T18:12:49.274Z,1559239969.274 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-30T18:12:49.309Z,1559239969.309 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-05-30T18:12:49.311Z,1559239969.311 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-05-30T18:12:49.321Z,1559239969.321 [Default:E.Execute](DEBUG): Construct Execute. 2019-05-30T18:12:49.340Z,1559239969.340 [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-30T18:12:49.345Z,1559239969.345 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,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-30T18:12:49.363Z,1559239969.363 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-05-30T18:12:49.396Z,1559239969.396 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar 2019-05-30T18:12:49.397Z,1559239969.397 [DUSBL_Hydroid](INFO): Powering up 2019-05-30T18:12:49.397Z,1559239969.397 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid. 2019-05-30T18:12:49.415Z,1559239969.415 [Radio_Surface](INFO): Powering up 2019-05-30T18:12:49.471Z,1559239969.471 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-05-30T18:12:49.489Z,1559239969.489 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-05-30T18:12:49.495Z,1559239969.495 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-05-30T18:12:49.496Z,1559239969.496 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-05-30T18:12:49.503Z,1559239969.503 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-05-30T18:12:49.504Z,1559239969.504 [MassServo](DEBUG): Initializing EZServoServo. 2019-05-30T18:12:49.511Z,1559239969.511 [MassServo](DEBUG): Initializing MassServo. 2019-05-30T18:12:49.512Z,1559239969.512 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-30T18:12:49.519Z,1559239969.519 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-30T18:12:49.520Z,1559239969.520 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-05-30T18:12:49.527Z,1559239969.527 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-05-30T18:12:49.867Z,1559239969.867 [Micromodem](INFO): Powering up 2019-05-30T18:12:49.867Z,1559239969.867 [Micromodem](DEBUG): Initializing Micromodem. 2019-05-30T18:12:54.637Z,1559239974.637 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33 2019-05-30T18:12:55.041Z,1559239975.041 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31 2019-05-30T18:12:55.042Z,1559239975.042 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31 2019-05-30T18:12:55.445Z,1559239975.445 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33 2019-05-30T18:12:55.445Z,1559239975.445 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64 2019-05-30T18:12:55.837Z,1559239975.837 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66 2019-05-30T18:12:55.838Z,1559239975.838 [Micromodem](INFO): Nmea out: $CCCFG,nav.nst,1*4D 2019-05-30T18:12:56.253Z,1559239976.253 [Micromodem](INFO): Nmea in: $CACFG,nav.nst,1*4F 2019-05-30T18:12:56.253Z,1559239976.253 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E 2019-05-30T18:12:56.657Z,1559239976.657 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C 2019-05-30T18:12:56.657Z,1559239976.657 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46 2019-05-30T18:12:57.061Z,1559239977.061 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44 2019-05-30T18:12:57.061Z,1559239977.061 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63 2019-05-30T18:12:57.453Z,1559239977.453 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61 2019-05-30T18:12:57.453Z,1559239977.453 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A 2019-05-30T18:12:57.861Z,1559239977.861 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38 2019-05-30T18:12:57.862Z,1559239977.862 [Micromodem](INFO): Nmea out: $CCCLK,2019,05,30,18,12,58*4F 2019-05-30T18:12:58.253Z,1559239978.253 [Micromodem](INFO): Nmea in: $CACLK,2019,5,30,18,12,58*7D 2019-05-30T18:12:59.058Z,1559239979.058 [Micromodem](INFO): Nmea in: $CATMS,0,2019-05-30T18:12:59Z*7C 2019-05-30T18:12:59.081Z,1559239979.081 [Micromodem](INFO): Nmea in: $CATMG,2019-05-30T18:12:59Z,USER_CMD,RTC*35 2019-05-30T18:13:02.710Z,1559239982.710 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-05-30T18:13:07.533Z,1559239987.533 [DUSBL_Hydroid](INFO): DUSBL Version:O 2019-05-30T18:13:15.625Z,1559239995.625 [NAL9602](INFO): Powering up NAL9602 2019-05-30T18:13:26.529Z,1559240006.529 [NAL9602](INFO): NAL9602 initialized 2019-05-30T18:13:27.339Z,1559240007.339 [NAL9602](DEBUG): Fix Requested 2019-05-30T18:13:28.585Z,1559240008.585 [SBIT](IMPORTANT): Beginning Startup BIT 2019-05-30T18:13:28.621Z,1559240008.621 [CBIT](IMPORTANT): Beginning ground fault scan 2019-05-30T18:13:39.625Z,1559240019.625 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.013293 CHAN A1 (24V): -0.025562 CHAN A2 (12V): -0.005852 CHAN A3 (5V): -0.002284 CHAN B0 (3.3V): 0.000532 CHAN B1 (3.15aV): 0.000080 CHAN B2 (3.15bV): 0.000096 CHAN B3 (GND): 0.001765 OPEN: 0.007112 Full Scale Calc: 4.765 mA, -1.589 mA 2019-05-30T18:13:49.415Z,1559240029.415 [NAL9602](INFO): SBD MO Status=2, MOMSN=5588, MT Status=2, MTMSN=0 2019-05-30T18:13:49.416Z,1559240029.416 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-05-30T18:14:21.958Z,1559240061.958 [SBIT](IMPORTANT): SBIT PASSED 2019-05-30T18:14:22.019Z,1559240062.019 [CommandLine](IMPORTANT): got command configSet list 2019-05-30T18:14:22.020Z,1559240062.020 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=40 count; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude; 2019-05-30T18:14:22.021Z,1559240062.021 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude; 2019-05-30T18:14:22.022Z,1559240062.022 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter; 2019-05-30T18:14:22.022Z,1559240062.022 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_chlorophyll_in_sea_water 5.000000 microgram_per_liter; 2019-05-30T18:14:22.022Z,1559240062.022 [CommandLine](IMPORTANT): Express none mass_concentration_of_oxygen_in_sea_water; 2019-05-30T18:14:22.022Z,1559240062.022 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-05-30T18:14:22.022Z,1559240062.022 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter; 2019-05-30T18:14:22.022Z,1559240062.022 [CommandLine](IMPORTANT): VerticalControl.massDefault=5 millimeter; 2019-05-30T18:14:22.344Z,1559240062.344 [MissionManager](IMPORTANT): Started mission Startup 2019-05-30T18:14:22.344Z,1559240062.344 [Startup] Running Loop=1 2019-05-30T18:14:22.345Z,1559240062.345 [Startup](DEBUG): Aggregate::initialize Startup 2019-05-30T18:14:22.345Z,1559240062.345 [Startup:A.GoToSurface] Running Loop=1 2019-05-30T18:14:22.345Z,1559240062.345 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-30T18:14:22.345Z,1559240062.345 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-30T18:14:22.346Z,1559240062.346 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-30T18:14:22.346Z,1559240062.346 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-30T18:14:22.346Z,1559240062.346 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-30T18:14:22.347Z,1559240062.347 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-30T18:14:22.348Z,1559240062.348 [Startup:StartupSatComms] Running Loop=1 2019-05-30T18:14:22.349Z,1559240062.349 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-05-30T18:14:22.349Z,1559240062.349 [Startup:StartupSatComms:A] Running Loop=1 2019-05-30T18:14:22.770Z,1559240062.770 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-05-30T18:15:22.541Z,1559240122.541 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-30T18:14:22.3Z 2019-05-30T18:15:22.541Z,1559240122.541 [Startup:StartupSatComms:A] Stopped 2019-05-30T18:15:22.541Z,1559240122.541 [Startup:StartupSatComms:B] Running Loop=1 2019-05-30T18:15:22.948Z,1559240122.948 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-30T18:15:23.626Z,1559240123.626 [Micromodem](INFO): Outgoing frame #1: BB13F05C040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567 2019-05-30T18:15:23.627Z,1559240123.627 [Micromodem](INFO): Outgoing frame #2: 266CC0E6F1A517638CB0C0B8BE35994FEABFBDB92FCD92215011E57437C4F5E5F0EC9E14B85A146956ECB75E9F5714D7DBF47C37AF9BB003AE5DC2F70FE304F6 2019-05-30T18:15:23.627Z,1559240123.627 [Micromodem](INFO): Outgoing frame #3: B3E74F2048B14D68F5DE6A13DF4FA06075CAA87D1CF047737B5CBD634C385F34DE5D20CA7A5F635220D90674665503574914BE7D204248BB6588F9B157F197A5 2019-05-30T18:15:23.628Z,1559240123.628 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53 2019-05-30T18:15:24.157Z,1559240124.157 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51 2019-05-30T18:15:24.561Z,1559240124.561 [Micromodem](INFO): Nmea in: $CADRQ,181523,1,9,0,64,1*42 2019-05-30T18:15:24.565Z,1559240124.565 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,BB13F05C040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*0B 2019-05-30T18:15:24.961Z,1559240124.961 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-05-30T18:15:25.365Z,1559240125.365 [Micromodem](INFO): Nmea in: $CADRQ,181524,1,9,0,64,2*46 2019-05-30T18:15:25.366Z,1559240125.366 [Micromodem](INFO): Received CADRQ with unexpected frame#: 2 2019-05-30T18:15:25.366Z,1559240125.366 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,266CC0E6F1A517638CB0C0B8BE35994FEABFBDB92FCD92215011E57437C4F5E5F0EC9E14B85A146956ECB75E9F5714D7DBF47C37AF9BB003AE5DC2F70FE304F6*7D 2019-05-30T18:15:25.773Z,1559240125.773 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-05-30T18:15:26.173Z,1559240126.173 [Micromodem](INFO): Nmea in: $CADRQ,181525,1,9,0,64,3*46 2019-05-30T18:15:26.174Z,1559240126.174 [Micromodem](INFO): Received CADRQ with unexpected frame#: 3 2019-05-30T18:15:26.174Z,1559240126.174 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,B3E74F2048B14D68F5DE6A13DF4FA06075CAA87D1CF047737B5CBD634C385F34DE5D20CA7A5F635220D90674665503574914BE7D204248BB6588F9B157F197A5*7A 2019-05-30T18:15:26.577Z,1559240126.577 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-05-30T18:15:26.985Z,1559240126.985 [Micromodem](INFO): Nmea in: $CATXP,192*48 2019-05-30T18:15:30.634Z,1559240130.634 [Micromodem](INFO): Nmea in: $CATXF,192*5E 2019-05-30T18:15:31.022Z,1559240131.022 [Micromodem](INFO): Nmea in: $CAXST,6,20190530,181526.577628,3,0,200,4000,10000,1,1,9,1,3,3,3,192*4C 2019-05-30T18:15:33.850Z,1559240133.850 [Micromodem](INFO): Nmea in: $CAACK,9,1,1,1*43 2019-05-30T18:15:33.850Z,1559240133.850 [Micromodem](INFO): Received CAACK with unexpected frame#: 1 2019-05-30T18:15:34.257Z,1559240134.257 [Micromodem](INFO): Nmea in: $CAACK,9,1,2,1*40 2019-05-30T18:15:34.258Z,1559240134.258 [Micromodem](INFO): Received CAACK with no data to send 2019-05-30T18:15:34.661Z,1559240134.661 [Micromodem](INFO): Nmea in: $CAACK,9,1,3,1*41 2019-05-30T18:15:34.662Z,1559240134.662 [Micromodem](INFO): Received CAACK with no data to send 2019-05-30T18:15:35.075Z,1559240135.075 [Micromodem](INFO): Nmea in: $CACST,6,0,20190530181532.981232,06,15696,41,0338,0150,07,00,00,00,00,1,009,001,0,4,1,0,150,-21.5,5.00,16,-2.00,-01,-0.02,79,10000,4000*6E 2019-05-30T18:15:45.629Z,1559240145.629 [RDI_Pathfinder](ERROR): Failed to parse: :BE, -19, -27, -10,A 2019-05-30T18:15:48.844Z,1559240148.844 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-05-30T18:15:49.260Z,1559240149.260 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-05-30T18:15:49.260Z,1559240149.260 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-30T18:15:49.270Z,1559240149.270 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-30T18:15:49.802Z,1559240149.802 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-30T18:15:49.802Z,1559240149.802 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-05-30T18:16:22.794Z,1559240182.794 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-30T18:15:22.5Z 2019-05-30T18:16:22.794Z,1559240182.794 [Startup:StartupSatComms:B] Stopped 2019-05-30T18:16:22.794Z,1559240182.794 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-05-30T18:16:22.795Z,1559240182.795 [Startup:StartupSatComms] Stopped 2019-05-30T18:16:22.795Z,1559240182.795 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-05-30T18:16:22.800Z,1559240182.800 [Startup](INFO): Completed Startup 2019-05-30T18:16:22.800Z,1559240182.800 [MissionManager](INFO): Startup is completed. 2019-05-30T18:16:22.800Z,1559240182.800 [MissionManager](INFO): Uninitializing Mission Startup 2019-05-30T18:16:22.800Z,1559240182.800 [Startup] Stopped 2019-05-30T18:16:22.800Z,1559240182.800 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-05-30T18:16:22.800Z,1559240182.800 [Startup:A.GoToSurface] Stopped 2019-05-30T18:16:22.800Z,1559240182.800 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-30T18:16:23.172Z,1559240183.172 [MissionManager](IMPORTANT): Started mission Default 2019-05-30T18:16:23.172Z,1559240183.172 [Default] Running Loop=1 2019-05-30T18:16:23.172Z,1559240183.172 [Default](DEBUG): Aggregate::initialize Default 2019-05-30T18:16:23.172Z,1559240183.172 [Default:B.GoToSurface] Running Loop=1 2019-05-30T18:16:23.172Z,1559240183.172 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-30T18:16:23.173Z,1559240183.173 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-30T18:16:23.173Z,1559240183.173 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-30T18:16:23.173Z,1559240183.173 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-30T18:16:23.174Z,1559240183.174 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-30T18:16:23.174Z,1559240183.174 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-30T18:16:23.174Z,1559240183.174 [Default:A.Wait] Running Loop=1 2019-05-30T18:16:23.174Z,1559240183.174 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-05-30T18:16:36.497Z,1559240196.497 [Default:A.Wait](INFO): Done Waiting. 2019-05-30T18:16:36.497Z,1559240196.497 [Default:A.Wait] Stopped 2019-05-30T18:16:36.497Z,1559240196.497 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-05-30T18:16:36.908Z,1559240196.908 [Default:CheckIn] Running Loop=1 2019-05-30T18:16:36.909Z,1559240196.909 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-30T18:16:36.909Z,1559240196.909 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-30T18:16:37.309Z,1559240197.309 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-05-30T18:17:27.002Z,1559240247.002 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-05-30T18:17:27.002Z,1559240247.002 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 96.92, 94.42, 0.00 2019-05-30T18:18:29.994Z,1559240309.994 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-30T18:18:30.819Z,1559240310.819 [NAL9602](DEBUG): Fix Requested 2019-05-30T18:18:35.667Z,1559240315.667 [NAL9602](DEBUG): Fix Requested 2019-05-30T18:18:36.060Z,1559240316.060 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181829.00,A,3648.17236,N,12147.28452,W,0.719,134.86,300519,,,A*7E 2019-05-30T18:18:36.062Z,1559240316.062 [NAL9602](INFO): GPS fix at 20190530T181829: (36.802873, -121.788075) 2019-05-30T18:18:36.103Z,1559240316.103 [Default:CheckIn:Read_GPS] Stopped 2019-05-30T18:18:36.103Z,1559240316.103 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-30T18:18:36.518Z,1559240316.518 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-30T18:18:36.873Z,1559240316.873 [Micromodem](ERROR): Buffer fill timout failure. 2019-05-30T18:18:37.541Z,1559240317.541 [Micromodem](INFO): Outgoing frame #1: BB13F05C040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567 2019-05-30T18:18:37.541Z,1559240317.541 [Micromodem](INFO): Outgoing frame #2: 266CC0E6F1A517638CB0C0B8BE35994FEABFBDB92FCD92215011E57437C4F5E5F0EC9E14B85A146956ECB75E9F5714D7DBF47C37AF9BB003AE5DC2F70FE304F6 2019-05-30T18:18:37.541Z,1559240317.541 [Micromodem](INFO): Outgoing frame #3: B3E74F2048B14D68F5DE6A13DF4FA06075CAA87D1CF047737B5CBD634C385F34DE5D20CA7A5F635220D90674665503574914BE7D204248BB6588F9B157F197A5 2019-05-30T18:18:37.542Z,1559240317.542 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53 2019-05-30T18:18:37.687Z,1559240317.687 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51 2019-05-30T18:18:38.081Z,1559240318.081 [Micromodem](INFO): Nmea in: $CADRQ,181837,1,9,0,64,1*4A 2019-05-30T18:18:38.081Z,1559240318.081 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,BB13F05C040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*0B 2019-05-30T18:18:38.485Z,1559240318.485 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-05-30T18:18:38.889Z,1559240318.889 [Micromodem](INFO): Nmea in: $CADRQ,181838,1,9,0,64,2*46 2019-05-30T18:18:38.889Z,1559240318.889 [Micromodem](INFO): Received CADRQ with unexpected frame#: 2 2019-05-30T18:18:38.890Z,1559240318.890 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,266CC0E6F1A517638CB0C0B8BE35994FEABFBDB92FCD92215011E57437C4F5E5F0EC9E14B85A146956ECB75E9F5714D7DBF47C37AF9BB003AE5DC2F70FE304F6*7D 2019-05-30T18:18:39.297Z,1559240319.297 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-05-30T18:18:39.697Z,1559240319.697 [Micromodem](INFO): Nmea in: $CADRQ,181839,1,9,0,64,3*46 2019-05-30T18:18:39.697Z,1559240319.697 [Micromodem](INFO): Received CADRQ with unexpected frame#: 3 2019-05-30T18:18:39.698Z,1559240319.698 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,B3E74F2048B14D68F5DE6A13DF4FA06075CAA87D1CF047737B5CBD634C385F34DE5D20CA7A5F635220D90674665503574914BE7D204248BB6588F9B157F197A5*7A 2019-05-30T18:18:40.105Z,1559240320.105 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71 2019-05-30T18:18:40.505Z,1559240320.505 [Micromodem](INFO): Nmea in: $CATXP,192*48 2019-05-30T18:18:44.141Z,1559240324.141 [Micromodem](INFO): Nmea in: $CATXF,192*5E 2019-05-30T18:18:44.550Z,1559240324.550 [Micromodem](INFO): Nmea in: $CAXST,6,20190530,181840.100123,3,0,200,4000,10000,1,1,9,1,3,3,3,192*49 2019-05-30T18:18:47.379Z,1559240327.379 [Micromodem](INFO): Nmea in: $CAACK,9,1,1,1*43 2019-05-30T18:18:47.380Z,1559240327.380 [Micromodem](INFO): Received CAACK with unexpected frame#: 1 2019-05-30T18:18:47.785Z,1559240327.785 [Micromodem](INFO): Nmea in: $CAACK,9,1,2,1*40 2019-05-30T18:18:47.785Z,1559240327.785 [Micromodem](INFO): Received CAACK with no data to send 2019-05-30T18:18:48.181Z,1559240328.181 [Micromodem](INFO): Nmea in: $CAACK,9,1,3,1*41 2019-05-30T18:18:48.181Z,1559240328.181 [Micromodem](INFO): Received CAACK with no data to send 2019-05-30T18:18:48.625Z,1559240328.625 [Micromodem](INFO): Nmea in: $CACST,6,0,20190530181846.504738,06,16138,42,0348,0150,07,00,00,00,00,1,009,001,0,4,1,0,150,-24.5,5.00,16,-2.00,-01,-0.02,79,10000,4000*6F 2019-05-30T18:19:08.782Z,1559240348.782 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-30T18:19:10.539Z,1559240350.539 [CommandLine](IMPORTANT): got command quit 2019-05-30T18:19:11.543Z,1559240351.543 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2019-05-30T18:19:11.543Z,1559240351.543 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-30T18:19:11.544Z,1559240351.544 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:11.683Z,1559240351.683 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-05-30T18:19:11.683Z,1559240351.683 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:11.684Z,1559240351.684 [CommandLine](INFO): Join timeout helper Thread ID is 2285 2019-05-30T18:19:11.684Z,1559240351.684 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-05-30T18:19:11.684Z,1559240351.684 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:11.685Z,1559240351.685 [NavChartDb](INFO): Join timeout helper Thread ID is 2286 2019-05-30T18:19:11.799Z,1559240351.799 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-30T18:19:11.799Z,1559240351.799 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:11.803Z,1559240351.803 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2019-05-30T18:19:11.803Z,1559240351.803 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:11.804Z,1559240351.804 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 2287 2019-05-30T18:19:12.079Z,1559240352.079 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-30T18:19:12.079Z,1559240352.079 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-05-30T18:19:12.080Z,1559240352.080 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.087Z,1559240352.087 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-05-30T18:19:12.087Z,1559240352.087 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.088Z,1559240352.088 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2288 2019-05-30T18:19:12.199Z,1559240352.199 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-30T18:19:12.200Z,1559240352.200 [CTD_NeilBrown](INFO): Powering down 2019-05-30T18:19:12.211Z,1559240352.211 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.219Z,1559240352.219 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-05-30T18:19:12.219Z,1559240352.219 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.219Z,1559240352.219 [Radio_Surface](INFO): Join timeout helper Thread ID is 2289 2019-05-30T18:19:12.487Z,1559240352.487 [Radio_Surface](INFO): Powering down 2019-05-30T18:19:12.488Z,1559240352.488 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-30T18:19:12.488Z,1559240352.488 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.504Z,1559240352.504 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-05-30T18:19:12.504Z,1559240352.504 [logger ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.505Z,1559240352.505 [logger](INFO): Join timeout helper Thread ID is 2290 2019-05-30T18:19:12.511Z,1559240352.511 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-30T18:19:12.511Z,1559240352.511 [logger ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.513Z,1559240352.513 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-05-30T18:19:12.513Z,1559240352.513 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.513Z,1559240352.513 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-05-30T18:19:12.513Z,1559240352.513 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:12.513Z,1559240352.513 [controlThread](INFO): Join timeout helper Thread ID is 2291 2019-05-30T18:19:12.807Z,1559240352.807 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-30T18:19:12.807Z,1559240352.807 [controlThread](DEBUG): Uninitializing ControlThread 2019-05-30T18:19:12.808Z,1559240352.808 [AHRS_M2](INFO): Powering down 2019-05-30T18:19:12.880Z,1559240352.880 [DUSBL_Hydroid](INFO): Powering down 2019-05-30T18:19:12.971Z,1559240352.971 [Micromodem](INFO): Powering down 2019-05-30T18:19:13.067Z,1559240353.067 [NAL9602](INFO): Powering down 2019-05-30T18:19:13.139Z,1559240353.139 [RDI_Pathfinder](INFO): Powering down 2019-05-30T18:19:13.141Z,1559240353.141 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-05-30T18:19:13.142Z,1559240353.142 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-05-30T18:19:13.142Z,1559240353.142 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-05-30T18:19:13.143Z,1559240353.143 [MissionManager](INFO): Uninitializing Mission Default 2019-05-30T18:19:13.143Z,1559240353.143 [Default] Stopped 2019-05-30T18:19:13.143Z,1559240353.143 [Default](DEBUG): Aggregate::uninitialize Default 2019-05-30T18:19:13.143Z,1559240353.143 [Default:B.GoToSurface] Stopped 2019-05-30T18:19:13.143Z,1559240353.143 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-30T18:19:13.143Z,1559240353.143 [Default:CheckIn] Stopped 2019-05-30T18:19:13.143Z,1559240353.143 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-30T18:19:13.143Z,1559240353.143 [Default:CheckIn:Read_Iridium] Stopped 2019-05-30T18:19:13.146Z,1559240353.146 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-05-30T18:19:13.146Z,1559240353.146 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-05-30T18:19:13.146Z,1559240353.146 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-05-30T18:19:13.146Z,1559240353.146 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-05-30T18:19:13.147Z,1559240353.147 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-05-30T18:19:13.147Z,1559240353.147 [BuoyancyServo](INFO): Powering down 2019-05-30T18:19:13.159Z,1559240353.159 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-05-30T18:19:13.159Z,1559240353.159 [ElevatorServo](INFO): Powering down 2019-05-30T18:19:13.160Z,1559240353.160 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-05-30T18:19:13.160Z,1559240353.160 [MassServo](INFO): Powering down 2019-05-30T18:19:13.161Z,1559240353.161 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-05-30T18:19:13.161Z,1559240353.161 [RudderServo](INFO): Powering down 2019-05-30T18:19:13.162Z,1559240353.162 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-05-30T18:19:13.162Z,1559240353.162 [ThrusterServo](INFO): Powering down 2019-05-30T18:19:13.163Z,1559240353.163 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-05-30T18:19:13.163Z,1559240353.163 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-05-30T18:19:13.163Z,1559240353.163 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-05-30T18:19:13.164Z,1559240353.164 [CBIT](DEBUG): Powering off loads. 2019-05-30T18:19:13.175Z,1559240353.175 [CBIT](DEBUG): Disabling WDT. 2019-05-30T18:19:13.187Z,1559240353.187 [CBIT](DEBUG): Opening all GF detection circuits. 2019-05-30T18:19:13.188Z,1559240353.188 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:13.228Z,1559240353.228 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:13.270Z,1559240353.270 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:13.272Z,1559240353.272 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:13.328Z,1559240353.328 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-30T18:19:13.397Z,1559240353.397 [logger ThreadHandler](INFO): Thread cancelled.