2019-04-11T15:24:12.292Z,1554996252.292 [Supervisor](DEBUG): Initializing supervisor. 2019-04-11T15:24:12.295Z,1554996252.295 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-04-11T15:24:12.295Z,1554996252.295 [SyncHandler](INFO): Protected caller Thread ID is 5938 2019-04-11T15:24:12.296Z,1554996252.296 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-04-11T15:24:12.297Z,1554996252.297 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-04-11T15:24:12.297Z,1554996252.297 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5939 2019-04-11T15:24:12.299Z,1554996252.299 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-04-11T15:24:12.311Z,1554996252.311 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-04-11T15:24:12.312Z,1554996252.312 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-04-11T15:24:12.312Z,1554996252.312 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5940 2019-04-11T15:24:12.313Z,1554996252.313 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-04-11T15:24:12.314Z,1554996252.314 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-04-11T15:24:12.314Z,1554996252.314 [logger ThreadHandler](INFO): Protected caller Thread ID is 5941 2019-04-11T15:24:12.316Z,1554996252.316 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-04-11T15:24:12.317Z,1554996252.317 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-04-11T15:24:12.318Z,1554996252.318 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-04-11T15:24:12.749Z,1554996252.749 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-04-11T15:24:12.750Z,1554996252.750 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-04-11T15:24:12.849Z,1554996252.849 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-04-11T15:24:12.850Z,1554996252.850 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-04-11T15:24:13.179Z,1554996253.179 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-04-11T15:24:13.180Z,1554996253.180 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-04-11T15:24:13.325Z,1554996253.325 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-04-11T15:24:13.325Z,1554996253.325 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-04-11T15:24:13.521Z,1554996253.521 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-04-11T15:24:13.521Z,1554996253.521 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-04-11T15:24:13.985Z,1554996253.985 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-04-11T15:24:13.986Z,1554996253.986 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-04-11T15:24:14.200Z,1554996254.200 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-04-11T15:24:14.201Z,1554996254.201 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-04-11T15:24:14.349Z,1554996254.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-04-11T15:24:14.350Z,1554996254.350 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-04-11T15:24:14.546Z,1554996254.546 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-04-11T15:24:14.546Z,1554996254.546 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-04-11T15:24:14.644Z,1554996254.644 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-04-11T15:24:14.645Z,1554996254.645 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-04-11T15:24:14.971Z,1554996254.971 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-04-11T15:24:14.971Z,1554996254.971 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-04-11T15:24:15.053Z,1554996255.053 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-04-11T15:24:15.157Z,1554996255.157 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-04-11T15:24:15.158Z,1554996255.158 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-04-11T15:24:15.669Z,1554996255.669 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-04-11T15:24:15.670Z,1554996255.670 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-04-11T15:24:16.072Z,1554996256.072 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-04-11T15:24:16.075Z,1554996256.075 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/ 2019-04-11T15:24:16.076Z,1554996256.076 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg 2019-04-11T15:24:16.287Z,1554996256.287 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg 2019-04-11T15:24:16.429Z,1554996256.429 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg 2019-04-11T15:24:16.600Z,1554996256.600 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg 2019-04-11T15:24:16.988Z,1554996256.988 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-04-11T15:24:16.988Z,1554996256.988 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg 2019-04-11T15:24:17.236Z,1554996257.236 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg 2019-04-11T15:24:17.384Z,1554996257.384 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg 2019-04-11T15:24:17.487Z,1554996257.487 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg 2019-04-11T15:24:17.571Z,1554996257.571 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg 2019-04-11T15:24:17.684Z,1554996257.684 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg 2019-04-11T15:24:17.863Z,1554996257.863 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg 2019-04-11T15:24:17.000Z,1554996258.000 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-04-11T15:24:18.013Z,1554996258.013 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-04-11T15:24:18.389Z,1554996258.389 [AHRS_M2] Loaded 2019-04-11T15:24:18.390Z,1554996258.390 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-04-11T15:24:18.471Z,1554996258.471 [DataOverHttps] Loaded 2019-04-11T15:24:18.472Z,1554996258.472 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-04-11T15:24:18.473Z,1554996258.473 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0 2019-04-11T15:24:18.473Z,1554996258.473 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 6020 2019-04-11T15:24:18.487Z,1554996258.487 [Depth_Keller] Loaded 2019-04-11T15:24:18.487Z,1554996258.487 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-04-11T15:24:18.492Z,1554996258.492 [DropWeight] Loaded 2019-04-11T15:24:18.492Z,1554996258.492 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-04-11T15:24:18.549Z,1554996258.549 [DUSBL_Hydroid] Loaded 2019-04-11T15:24:18.549Z,1554996258.549 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread. 2019-04-11T15:24:18.590Z,1554996258.590 [Micromodem] Loaded 2019-04-11T15:24:18.590Z,1554996258.590 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2019-04-11T15:24:18.689Z,1554996258.689 [NAL9602] Loaded 2019-04-11T15:24:18.689Z,1554996258.689 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-04-11T15:24:18.705Z,1554996258.705 [Onboard] Loaded 2019-04-11T15:24:18.705Z,1554996258.705 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-04-11T15:24:18.711Z,1554996258.711 [PowerOnly] Loaded 2019-04-11T15:24:18.712Z,1554996258.712 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2019-04-11T15:24:18.718Z,1554996258.718 [Radio_Surface] Loaded 2019-04-11T15:24:18.719Z,1554996258.719 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-04-11T15:24:18.720Z,1554996258.720 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0 2019-04-11T15:24:18.720Z,1554996258.720 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6021 2019-04-11T15:24:18.765Z,1554996258.765 [RDI_Pathfinder] Loaded 2019-04-11T15:24:18.765Z,1554996258.765 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2019-04-11T15:24:20.285Z,1554996260.285 [BPC1] Loaded 2019-04-11T15:24:20.286Z,1554996260.286 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-04-11T15:24:20.286Z,1554996260.286 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-04-11T15:24:20.287Z,1554996260.287 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-04-11T15:24:20.300Z,1554996260.300 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-04-11T15:24:20.300Z,1554996260.300 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-04-11T15:24:20.407Z,1554996260.407 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-04-11T15:24:20.407Z,1554996260.407 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-04-11T15:24:20.428Z,1554996260.428 [NavChart] Loaded 2019-04-11T15:24:20.428Z,1554996260.428 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-04-11T15:24:20.432Z,1554996260.432 [UniversalFixResidualReporter] Loaded 2019-04-11T15:24:20.433Z,1554996260.433 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-04-11T15:24:20.433Z,1554996260.433 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-04-11T15:24:20.434Z,1554996260.434 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-04-11T15:24:20.533Z,1554996260.533 [BuoyancyServo] Loaded 2019-04-11T15:24:20.534Z,1554996260.534 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-04-11T15:24:20.549Z,1554996260.549 [ElevatorServo] Loaded 2019-04-11T15:24:20.549Z,1554996260.549 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-04-11T15:24:20.564Z,1554996260.564 [MassServo] Loaded 2019-04-11T15:24:20.564Z,1554996260.564 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-04-11T15:24:20.579Z,1554996260.579 [RudderServo] Loaded 2019-04-11T15:24:20.579Z,1554996260.579 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-04-11T15:24:20.594Z,1554996260.594 [ThrusterServo] Loaded 2019-04-11T15:24:20.594Z,1554996260.594 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-04-11T15:24:20.595Z,1554996260.595 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-04-11T15:24:20.595Z,1554996260.595 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-04-11T15:24:20.846Z,1554996260.846 [CTD_NeilBrown] Loaded 2019-04-11T15:24:20.846Z,1554996260.846 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-04-11T15:24:20.847Z,1554996260.847 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408C84E0 2019-04-11T15:24:20.848Z,1554996260.848 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 6022 2019-04-11T15:24:20.893Z,1554996260.893 [WetLabsSeaOWL_UV_A] Loaded 2019-04-11T15:24:20.893Z,1554996260.893 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2019-04-11T15:24:20.894Z,1554996260.894 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408F84E0 2019-04-11T15:24:20.894Z,1554996260.894 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 6023 2019-04-11T15:24:20.895Z,1554996260.895 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-04-11T15:24:20.895Z,1554996260.895 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-04-11T15:24:21.168Z,1554996261.168 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-04-11T15:24:21.168Z,1554996261.168 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-04-11T15:24:21.209Z,1554996261.209 [DepthRateCalculator] Loaded 2019-04-11T15:24:21.210Z,1554996261.210 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-04-11T15:24:21.215Z,1554996261.215 [PitchRateCalculator] Loaded 2019-04-11T15:24:21.216Z,1554996261.216 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-04-11T15:24:21.228Z,1554996261.228 [SpeedCalculator] Loaded 2019-04-11T15:24:21.228Z,1554996261.228 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-04-11T15:24:21.249Z,1554996261.249 [TempGradientCalculator] Loaded 2019-04-11T15:24:21.249Z,1554996261.249 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-04-11T15:24:21.255Z,1554996261.255 [YawRateCalculator] Loaded 2019-04-11T15:24:21.255Z,1554996261.255 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-04-11T15:24:21.296Z,1554996261.296 [ElevatorOffsetCalculator] Loaded 2019-04-11T15:24:21.296Z,1554996261.296 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-04-11T15:24:21.297Z,1554996261.297 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-04-11T15:24:21.297Z,1554996261.297 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-04-11T15:24:21.429Z,1554996261.429 [SBIT](DEBUG): Construct Startup Built In Test. 2019-04-11T15:24:21.452Z,1554996261.452 [SBIT] Loaded 2019-04-11T15:24:21.452Z,1554996261.452 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-04-11T15:24:21.453Z,1554996261.453 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-04-11T15:24:21.465Z,1554996261.465 [IBIT] Loaded 2019-04-11T15:24:21.465Z,1554996261.465 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-04-11T15:24:21.468Z,1554996261.468 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-04-11T15:24:21.607Z,1554996261.607 [CBIT] Loaded 2019-04-11T15:24:21.607Z,1554996261.607 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-04-11T15:24:21.607Z,1554996261.607 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-04-11T15:24:21.608Z,1554996261.608 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-04-11T15:24:21.880Z,1554996261.880 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-04-11T15:24:21.880Z,1554996261.880 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-04-11T15:24:22.052Z,1554996262.052 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-04-11T15:24:22.052Z,1554996262.052 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-04-11T15:24:22.281Z,1554996262.281 [VerticalControl](DEBUG): Construct VerticalControl. 2019-04-11T15:24:22.365Z,1554996262.365 [VerticalControl] Loaded 2019-04-11T15:24:22.366Z,1554996262.366 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-04-11T15:24:22.366Z,1554996262.366 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-04-11T15:24:22.424Z,1554996262.424 [HorizontalControl] Loaded 2019-04-11T15:24:22.425Z,1554996262.425 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-04-11T15:24:22.425Z,1554996262.425 [SpeedControl](DEBUG): Construct SpeedControl. 2019-04-11T15:24:22.427Z,1554996262.427 [SpeedControl] Loaded 2019-04-11T15:24:22.427Z,1554996262.427 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-04-11T15:24:22.428Z,1554996262.428 [LoopControl](DEBUG): Construct LoopControl. 2019-04-11T15:24:22.428Z,1554996262.428 [LoopControl] Loaded 2019-04-11T15:24:22.429Z,1554996262.429 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-04-11T15:24:22.429Z,1554996262.429 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-04-11T15:24:22.430Z,1554996262.430 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-04-11T15:24:22.457Z,1554996262.457 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-04-11T15:24:22.461Z,1554996262.461 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-04-11T15:24:22.461Z,1554996262.461 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-04-11T15:24:22.468Z,1554996262.468 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-04-11T15:24:22.469Z,1554996262.469 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AC84E0 2019-04-11T15:24:22.470Z,1554996262.470 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6024 2019-04-11T15:24:22.474Z,1554996262.474 [Supervisor](INFO): Main Thread ID is 2474 2019-04-11T15:24:22.474Z,1554996262.474 [Supervisor](DEBUG): Running supervisor. 2019-04-11T15:24:22.475Z,1554996262.475 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6025 2019-04-11T15:24:22.477Z,1554996262.477 [controlThread ThreadHandler](INFO): Handler Thread ID is 6026 2019-04-11T15:24:22.478Z,1554996262.478 [controlThread](DEBUG): Initializing ControlThread 2019-04-11T15:24:22.483Z,1554996262.483 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-04-11T15:24:22.483Z,1554996262.483 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-04-11T15:24:22.484Z,1554996262.484 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-04-11T15:24:22.484Z,1554996262.484 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-04-11T15:24:22.485Z,1554996262.485 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-04-11T15:24:22.485Z,1554996262.485 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-04-11T15:24:22.485Z,1554996262.485 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-04-11T15:24:22.486Z,1554996262.486 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-04-11T15:24:22.486Z,1554996262.486 [SBIT](INFO): Initialize SBIT Component. 2019-04-11T15:24:22.487Z,1554996262.487 [SBIT](IMPORTANT): git: 2019-04-10 2019-04-11T15:24:22.487Z,1554996262.487 [SBIT](INFO): git hash: c014275aafff9d7805d0dcecdf6cd08611644109 2019-04-11T15:24:22.487Z,1554996262.487 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-04-11T15:24:22.488Z,1554996262.488 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018 2019-04-11T15:24:22.489Z,1554996262.489 [SBIT](INFO): Beginning SBIT in 44.000000 seconds. 2019-04-11T15:24:22.489Z,1554996262.489 [IBIT](INFO): Initialize IBIT Component. 2019-04-11T15:24:22.490Z,1554996262.490 [CBIT](DEBUG): Initialize CBIT Component. 2019-04-11T15:24:22.491Z,1554996262.491 [logger ThreadHandler](INFO): Handler Thread ID is 6027 2019-04-11T15:24:22.503Z,1554996262.503 [CBIT](DEBUG): Initialized mux pins. 2019-04-11T15:24:22.503Z,1554996262.503 [CBIT](DEBUG): Initializing the watchdog timer. 2019-04-11T15:24:22.508Z,1554996262.508 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 6028 2019-04-11T15:24:22.509Z,1554996262.509 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-04-11T15:24:22.516Z,1554996262.516 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6029 2019-04-11T15:24:22.524Z,1554996262.524 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 6030 2019-04-11T15:24:22.525Z,1554996262.525 [CTD_NeilBrown](INFO): Powering down 2019-04-11T15:24:22.527Z,1554996262.527 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-04-11T15:24:22.528Z,1554996262.528 [CBIT](DEBUG): Initializing heartbeat. 2019-04-11T15:24:22.556Z,1554996262.556 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 6031 2019-04-11T15:24:22.557Z,1554996262.557 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-04-11T15:24:22.588Z,1554996262.588 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6032 2019-04-11T15:24:22.594Z,1554996262.594 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-04-11T15:24:22.594Z,1554996262.594 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-04-11T15:24:22.594Z,1554996262.594 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-04-11T15:24:22.594Z,1554996262.594 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-04-11T15:24:22.594Z,1554996262.594 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-04-11T15:24:22.595Z,1554996262.595 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-04-11T15:24:22.595Z,1554996262.595 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-04-11T15:24:22.595Z,1554996262.595 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-04-11T15:24:22.595Z,1554996262.595 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-04-11T15:24:22.595Z,1554996262.595 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-04-11T15:24:22.596Z,1554996262.596 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-04-11T15:24:22.596Z,1554996262.596 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-04-11T15:24:22.596Z,1554996262.596 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-04-11T15:24:22.596Z,1554996262.596 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-04-11T15:24:22.596Z,1554996262.596 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-04-11T15:24:22.597Z,1554996262.597 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-04-11T15:24:22.599Z,1554996262.599 [CBIT](DEBUG): Deactivating GF circuits. 2019-04-11T15:24:22.599Z,1554996262.599 [CBIT](DEBUG): Deactivating emergency mode. 2019-04-11T15:24:22.635Z,1554996262.635 [CBIT](DEBUG): Backplane powered. 2019-04-11T15:24:22.636Z,1554996262.636 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-04-11T15:24:22.637Z,1554996262.637 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-04-11T15:24:22.638Z,1554996262.638 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-04-11T15:24:22.639Z,1554996262.639 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-04-11T15:24:22.639Z,1554996262.639 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-04-11T15:24:22.657Z,1554996262.657 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-04-11T15:24:22.684Z,1554996262.684 [MissionManager](DEBUG): 2019-04-11T15:24:22.684Z,1554996262.684 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-04-11T15:24:22.752Z,1554996262.752 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-04-11T15:24:22.753Z,1554996262.753 [Default:A.Wait](DEBUG): Construct Wait. 2019-04-11T15:24:22.754Z,1554996262.754 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-04-11T15:24:22.774Z,1554996262.774 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-04-11T15:24:22.804Z,1554996262.804 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-04-11T15:24:22.810Z,1554996262.810 [Default:E.Execute](DEBUG): Construct Execute. 2019-04-11T15:24:22.833Z,1554996262.833 [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-04-11T15:24:22.838Z,1554996262.838 [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-04-11T15:24:22.847Z,1554996262.847 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-04-11T15:24:22.919Z,1554996262.919 [Radio_Surface](INFO): Powering up 2019-04-11T15:24:22.921Z,1554996262.921 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar 2019-04-11T15:24:22.922Z,1554996262.922 [DUSBL_Hydroid](INFO): Powering up 2019-04-11T15:24:22.922Z,1554996262.922 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid. 2019-04-11T15:24:22.996Z,1554996262.996 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-04-11T15:24:23.013Z,1554996263.013 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-04-11T15:24:23.028Z,1554996263.028 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-04-11T15:24:23.029Z,1554996263.029 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-04-11T15:24:23.036Z,1554996263.036 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-04-11T15:24:23.037Z,1554996263.037 [MassServo](DEBUG): Initializing EZServoServo. 2019-04-11T15:24:23.044Z,1554996263.044 [MassServo](DEBUG): Initializing MassServo. 2019-04-11T15:24:23.044Z,1554996263.044 [RudderServo](DEBUG): Initializing EZServoServo. 2019-04-11T15:24:23.052Z,1554996263.052 [RudderServo](DEBUG): Initializing RudderServo. 2019-04-11T15:24:23.052Z,1554996263.052 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-04-11T15:24:23.060Z,1554996263.060 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-04-11T15:24:23.261Z,1554996263.261 [Micromodem](INFO): Powering up 2019-04-11T15:24:23.262Z,1554996263.262 [Micromodem](DEBUG): Initializing Micromodem. 2019-04-11T15:24:23.296Z,1554996263.296 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-04-11T15:24:24.011Z,1554996264.011 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-04-11T15:24:24.012Z,1554996264.012 [RudderServo](FAULT): Rudder failed to initialize 2019-04-11T15:24:24.012Z,1554996264.012 [RudderServo] Communications Fault, FailCount= 1 2019-04-11T15:24:24.012Z,1554996264.012 [RudderServo](ERROR): Communications Fault 2019-04-11T15:24:24.124Z,1554996264.124 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-04-11T15:24:24.284Z,1554996264.284 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-04-11T15:24:24.284Z,1554996264.284 [RudderServo](INFO): Powering down 2019-04-11T15:24:24.967Z,1554996264.967 [RudderServo](DEBUG): Initializing EZServoServo. 2019-04-11T15:24:25.088Z,1554996265.088 [RudderServo](DEBUG): Initializing RudderServo. 2019-04-11T15:24:25.093Z,1554996265.093 [CBIT](INFO): Clearing failed state for component RudderServo 2019-04-11T15:24:25.093Z,1554996265.093 [RudderServo] No Fault, FailCount= 1 2019-04-11T15:24:36.280Z,1554996276.280 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-04-11T15:24:41.117Z,1554996281.117 [DUSBL_Hydroid](INFO): DUSBL Version:O 2019-04-11T15:24:48.786Z,1554996288.786 [NAL9602](INFO): Powering up NAL9602 2019-04-11T15:24:53.276Z,1554996293.276 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-04-11T15:24:53.276Z,1554996293.276 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-04-11T15:24:59.686Z,1554996299.686 [NAL9602](INFO): NAL9602 initialized 2019-04-11T15:25:00.507Z,1554996300.507 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:07.001Z,1554996307.001 [SBIT](IMPORTANT): Beginning Startup BIT 2019-04-11T15:25:07.006Z,1554996307.006 [CBIT](IMPORTANT): Beginning ground fault scan 2019-04-11T15:25:11.123Z,1554996311.123 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-04-11T15:25:11.124Z,1554996311.124 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3768,-32768,V 2019-04-11T15:25:12.695Z,1554996312.695 [NAL9602](INFO): SBD MO Status=0, MOMSN=3432, MT Status=0, MTMSN=0 2019-04-11T15:25:12.695Z,1554996312.695 [NAL9602](INFO): No messages in MT queue 2019-04-11T15:25:13.515Z,1554996313.515 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:16.351Z,1554996316.351 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:18.032Z,1554996318.032 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.018749 CHAN A1 (24V): -0.027327 CHAN A2 (12V): -0.007280 CHAN A3 (5V): -0.002095 CHAN B0 (3.3V): 0.000278 CHAN B1 (3.15aV): 0.000034 CHAN B2 (3.15bV): 0.000193 CHAN B3 (GND): 0.002206 OPEN: 0.005059 Full Scale Calc: 4.765 mA, -1.589 mA 2019-04-11T15:25:19.579Z,1554996319.579 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:22.559Z,1554996322.559 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:25.795Z,1554996325.795 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:28.627Z,1554996328.627 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:31.455Z,1554996331.455 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:34.275Z,1554996334.275 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:37.511Z,1554996337.511 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:40.339Z,1554996340.339 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:43.571Z,1554996343.571 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:46.399Z,1554996346.399 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:49.735Z,1554996349.735 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:52.563Z,1554996352.563 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:55.795Z,1554996355.795 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:25:58.623Z,1554996358.623 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:00.258Z,1554996360.258 [SBIT](IMPORTANT): SBIT PASSED 2019-04-11T15:26:00.277Z,1554996360.277 [CommandLine](IMPORTANT): got command configSet list 2019-04-11T15:26:00.278Z,1554996360.278 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-04-11T15:26:00.278Z,1554996360.278 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour; 2019-04-11T15:26:00.279Z,1554996360.279 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool; 2019-04-11T15:26:00.279Z,1554996360.279 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count; 2019-04-11T15:26:00.279Z,1554996360.279 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter; 2019-04-11T15:26:00.279Z,1554996360.279 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree; 2019-04-11T15:26:00.279Z,1554996360.279 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count; 2019-04-11T15:26:00.279Z,1554996360.279 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter; 2019-04-11T15:26:00.279Z,1554996360.279 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude; 2019-04-11T15:26:00.280Z,1554996360.280 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude; 2019-04-11T15:26:00.280Z,1554996360.280 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter; 2019-04-11T15:26:00.280Z,1554996360.280 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-04-11T15:26:00.280Z,1554996360.280 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter; 2019-04-11T15:26:00.280Z,1554996360.280 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter; 2019-04-11T15:26:00.652Z,1554996360.652 [MissionManager](IMPORTANT): Started mission Startup 2019-04-11T15:26:00.653Z,1554996360.653 [Startup] Running Loop=1 2019-04-11T15:26:00.653Z,1554996360.653 [Startup](DEBUG): Aggregate::initialize Startup 2019-04-11T15:26:00.653Z,1554996360.653 [Startup:A.GoToSurface] Running Loop=1 2019-04-11T15:26:00.653Z,1554996360.653 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-04-11T15:26:00.654Z,1554996360.654 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-04-11T15:26:00.654Z,1554996360.654 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-04-11T15:26:00.654Z,1554996360.654 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-04-11T15:26:00.655Z,1554996360.655 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-04-11T15:26:00.655Z,1554996360.655 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-04-11T15:26:00.656Z,1554996360.656 [Startup:StartupSatComms] Running Loop=1 2019-04-11T15:26:00.657Z,1554996360.657 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-04-11T15:26:00.657Z,1554996360.657 [Startup:StartupSatComms:A] Running Loop=1 2019-04-11T15:26:01.064Z,1554996361.064 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-04-11T15:26:01.855Z,1554996361.855 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:04.683Z,1554996364.683 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:07.515Z,1554996367.515 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:10.335Z,1554996370.335 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:13.575Z,1554996373.575 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:16.395Z,1554996376.395 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:19.627Z,1554996379.627 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:22.467Z,1554996382.467 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:25.691Z,1554996385.691 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:28.515Z,1554996388.515 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:31.755Z,1554996391.755 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:34.579Z,1554996394.579 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:37.811Z,1554996397.811 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:40.639Z,1554996400.639 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:43.871Z,1554996403.871 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:46.695Z,1554996406.695 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:49.527Z,1554996409.527 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:52.755Z,1554996412.755 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:55.599Z,1554996415.599 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:26:56.417Z,1554996416.417 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:26:58.419Z,1554996418.419 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:27:00.861Z,1554996420.861 [Startup:StartupSatComms:A](INFO): Timed out from 2019-04-11T15:26:00.7Z 2019-04-11T15:27:00.861Z,1554996420.861 [Startup:StartupSatComms:A] Stopped 2019-04-11T15:27:00.861Z,1554996420.861 [Startup:StartupSatComms:B] Running Loop=1 2019-04-11T15:27:01.262Z,1554996421.262 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-04-11T15:27:01.651Z,1554996421.651 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:27:06.134Z,1554996426.134 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:27:14.167Z,1554996434.167 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:27:16.229Z,1554996436.229 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:27:22.739Z,1554996442.739 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-04-11T15:27:22.739Z,1554996442.739 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-04-11T15:27:22.779Z,1554996442.779 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-04-11T15:27:23.157Z,1554996443.157 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-04-11T15:27:23.157Z,1554996443.157 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-04-11T15:27:26.380Z,1554996446.380 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:27:33.647Z,1554996453.647 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-04-11T15:27:33.647Z,1554996453.647 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3278,V 2019-04-11T15:27:36.073Z,1554996456.073 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:27:36.456Z,1554996456.456 [NAL9602](INFO): SBD MO Status=1, MOMSN=3433, MT Status=0, MTMSN=0 2019-04-11T15:27:36.508Z,1554996456.508 [NAL9602](INFO): Sent 25 bytes from file Logs/20190411T054100/Courier0325.lzma 2019-04-11T15:27:36.508Z,1554996456.508 [NAL9602](INFO): Packets left to send: 0 2019-04-11T15:27:45.849Z,1554996465.849 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:27:53.919Z,1554996473.919 [NAL9602](INFO): SBD MO Status=1, MOMSN=3434, MT Status=0, MTMSN=0 2019-04-11T15:27:53.968Z,1554996473.968 [NAL9602](INFO): Sent 332 bytes from file Logs/20190411T054100/Express0326.lzma 2019-04-11T15:27:53.968Z,1554996473.968 [NAL9602](INFO): Packets left to send: 1 2019-04-11T15:27:57.401Z,1554996477.401 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:27:58.822Z,1554996478.822 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004942 2019-04-11T15:28:01.025Z,1554996481.025 [Startup:StartupSatComms:B](INFO): Timed out from 2019-04-11T15:27:00.9Z 2019-04-11T15:28:01.025Z,1554996481.025 [Startup:StartupSatComms:B] Stopped 2019-04-11T15:28:01.025Z,1554996481.025 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-04-11T15:28:01.025Z,1554996481.025 [Startup:StartupSatComms] Stopped 2019-04-11T15:28:01.025Z,1554996481.025 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-04-11T15:28:01.026Z,1554996481.026 [Startup](INFO): Completed Startup 2019-04-11T15:28:01.026Z,1554996481.026 [MissionManager](INFO): Startup is completed. 2019-04-11T15:28:01.026Z,1554996481.026 [MissionManager](INFO): Uninitializing Mission Startup 2019-04-11T15:28:01.026Z,1554996481.026 [Startup] Stopped 2019-04-11T15:28:01.026Z,1554996481.026 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-04-11T15:28:01.026Z,1554996481.026 [Startup:A.GoToSurface] Stopped 2019-04-11T15:28:01.026Z,1554996481.026 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-04-11T15:28:01.436Z,1554996481.436 [MissionManager](IMPORTANT): Started mission Default 2019-04-11T15:28:01.437Z,1554996481.437 [Default] Running Loop=1 2019-04-11T15:28:01.437Z,1554996481.437 [Default](DEBUG): Aggregate::initialize Default 2019-04-11T15:28:01.437Z,1554996481.437 [Default:B.GoToSurface] Running Loop=1 2019-04-11T15:28:01.437Z,1554996481.437 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-04-11T15:28:01.437Z,1554996481.437 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-04-11T15:28:01.437Z,1554996481.437 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-04-11T15:28:01.438Z,1554996481.438 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-04-11T15:28:01.438Z,1554996481.438 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-04-11T15:28:01.438Z,1554996481.438 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-04-11T15:28:01.439Z,1554996481.439 [Default:A.Wait] Running Loop=1 2019-04-11T15:28:01.439Z,1554996481.439 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-04-11T15:28:05.632Z,1554996485.632 [DataOverHttps](INFO): Sending 604 bytes from file Logs/20190411T054100/Express0326.lzma 2019-04-11T15:28:06.437Z,1554996486.437 [DataOverHttps](INFO): Moved sent file to Logs/20190411T054100/Express0326.lzma.bak 2019-04-11T15:28:06.438Z,1554996486.438 [DataOverHttps](INFO): SBD MOMSN=10552273 2019-04-11T15:28:07.136Z,1554996487.136 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:28:07.880Z,1554996487.880 [NAL9602](INFO): SBD MO Status=1, MOMSN=3435, MT Status=0, MTMSN=0 2019-04-11T15:28:07.928Z,1554996487.928 [NAL9602](INFO): Sent 272 bytes from file Logs/20190411T054100/Express0326.lzma 2019-04-11T15:28:07.928Z,1554996487.928 [NAL9602](INFO): Packets left to send: 0 2019-04-11T15:28:08.699Z,1554996488.699 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:28:09.100Z,1554996489.100 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152807.00,A,3648.43020,N,12148.56041,W,12.965,272.18,110419,,,A*4A 2019-04-11T15:28:09.102Z,1554996489.102 [NAL9602](INFO): GPS fix at 20190411T152807: (36.807170, -121.809340) 2019-04-11T15:28:14.794Z,1554996494.794 [Default:A.Wait](INFO): Done Waiting. 2019-04-11T15:28:14.794Z,1554996494.794 [Default:A.Wait] Stopped 2019-04-11T15:28:14.794Z,1554996494.794 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-04-11T15:28:15.178Z,1554996495.178 [Default:CheckIn] Running Loop=1 2019-04-11T15:28:15.178Z,1554996495.178 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-04-11T15:28:15.178Z,1554996495.178 [Default:CheckIn:Read_GPS] Running Loop=1 2019-04-11T15:28:15.598Z,1554996495.598 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-04-11T15:28:16.787Z,1554996496.787 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:28:16.803Z,1554996496.803 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:28:17.186Z,1554996497.186 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,152815.00,A,3648.43324,N,12148.59752,W,14.190,279.36,110419,,,A*47 2019-04-11T15:28:17.193Z,1554996497.193 [NAL9602](INFO): GPS fix at 20190411T152815: (36.807221, -121.809959) 2019-04-11T15:28:17.266Z,1554996497.266 [Default:CheckIn:Read_GPS] Stopped 2019-04-11T15:28:17.266Z,1554996497.266 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-04-11T15:28:17.657Z,1554996497.657 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-04-11T15:28:26.568Z,1554996506.568 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:28:30.951Z,1554996510.951 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20190411T152412/Courier0004.lzma 2019-04-11T15:28:31.757Z,1554996511.757 [DataOverHttps](INFO): Moved sent file to Logs/20190411T152412/Courier0004.lzma.bak 2019-04-11T15:28:31.757Z,1554996511.757 [DataOverHttps](INFO): SBD MOMSN=10552280 2019-04-11T15:28:36.584Z,1554996516.584 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:28:44.482Z,1554996524.482 [DataOverHttps](INFO): Sending 1268 bytes from file Logs/20190411T152412/Express0001.lzma 2019-04-11T15:28:45.285Z,1554996525.285 [DataOverHttps](INFO): Moved sent file to Logs/20190411T152412/Express0001.lzma.bak 2019-04-11T15:28:45.285Z,1554996525.285 [DataOverHttps](INFO): SBD MOMSN=10552284 2019-04-11T15:28:46.286Z,1554996526.286 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:28:49.493Z,1554996529.493 [NAL9602](INFO): Not Powering down - fast GPS 2019-04-11T15:28:55.976Z,1554996535.976 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:28:57.220Z,1554996537.220 [DataOverHttps](INFO): Sending 361 bytes from file Logs/20190411T152412/Express0005.lzma 2019-04-11T15:28:58.025Z,1554996538.025 [DataOverHttps](INFO): Moved sent file to Logs/20190411T152412/Express0005.lzma.bak 2019-04-11T15:28:58.025Z,1554996538.025 [DataOverHttps](INFO): SBD MOMSN=10552313 2019-04-11T15:28:58.828Z,1554996538.828 [Default:CheckIn:Read_Iridium] Stopped 2019-04-11T15:28:58.828Z,1554996538.828 [Default:CheckIn:C.Wait] Running Loop=1 2019-04-11T15:28:58.828Z,1554996538.828 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-04-11T15:29:05.682Z,1554996545.682 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:29:15.372Z,1554996555.372 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:30:23.280Z,1554996623.280 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-04-11T15:30:23.280Z,1554996623.280 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0.00 +0.00, 0.00,346.99 2019-04-11T15:31:51.716Z,1554996711.716 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:32:01.428Z,1554996721.428 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:32:11.143Z,1554996731.143 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:32:21.229Z,1554996741.229 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:32:31.314Z,1554996751.314 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:32:41.418Z,1554996761.418 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:32:51.505Z,1554996771.505 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:33:01.604Z,1554996781.604 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:33:11.310Z,1554996791.310 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:33:21.418Z,1554996801.418 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:33:27.468Z,1554996807.468 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-04-11T15:33:27.468Z,1554996807.468 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19041108421203,.1, 0.0,1448.9, 0 2019-04-11T15:33:31.504Z,1554996811.504 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:33:41.601Z,1554996821.601 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:33:51.322Z,1554996831.322 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:33:59.476Z,1554996839.476 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-04-11T15:33:59.476Z,1554996839.476 [Default:CheckIn:C.Wait] Stopped 2019-04-11T15:33:59.476Z,1554996839.476 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-04-11T15:33:59.476Z,1554996839.476 [Default:CheckIn:D] Running Loop=1 2019-04-11T15:33:59.794Z,1554996839.794 [Default:CheckIn:D] Stopped 2019-04-11T15:33:59.795Z,1554996839.795 [Default:CheckIn:E] Running Loop=1 2019-04-11T15:34:00.222Z,1554996840.222 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.972630 min 2019-04-11T15:34:00.223Z,1554996840.223 [Default:CheckIn:E] Stopped 2019-04-11T15:34:00.223Z,1554996840.223 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-04-11T15:34:00.223Z,1554996840.223 [Default:CheckIn] Stopped 2019-04-11T15:34:00.223Z,1554996840.223 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-04-11T15:34:00.223Z,1554996840.223 [Default:CheckIn](INFO): Running loop #2 2019-04-11T15:34:00.223Z,1554996840.223 [Default:CheckIn] Running Loop=2 2019-04-11T15:34:00.224Z,1554996840.224 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-04-11T15:34:00.224Z,1554996840.224 [Default:CheckIn:Read_GPS] Running Loop=1 2019-04-11T15:34:01.007Z,1554996841.007 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:34:01.803Z,1554996841.803 [NAL9602](DEBUG): Fix Requested 2019-04-11T15:34:02.195Z,1554996842.195 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,153400.00,A,3648.90061,N,12149.13390,W,0.311,259.32,110419,,,A*7F 2019-04-11T15:34:02.197Z,1554996842.197 [NAL9602](INFO): GPS fix at 20190411T153400: (36.815010, -121.818898) 2019-04-11T15:34:02.285Z,1554996842.285 [Default:CheckIn:Read_GPS] Stopped 2019-04-11T15:34:02.285Z,1554996842.285 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-04-11T15:34:03.848Z,1554996843.848 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-04-11T15:34:09.687Z,1554996849.687 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190411T152412/Courier0007.lzma 2019-04-11T15:34:10.493Z,1554996850.493 [DataOverHttps](INFO): Moved sent file to Logs/20190411T152412/Courier0007.lzma.bak 2019-04-11T15:34:10.493Z,1554996850.493 [DataOverHttps](INFO): SBD MOMSN=10552424 2019-04-11T15:34:11.146Z,1554996851.146 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-04-11T15:34:15.147Z,1554996855.147 [NAL9602](INFO): SBD MO Status=0, MOMSN=3436, MT Status=0, MTMSN=0 2019-04-11T15:34:15.147Z,1554996855.147 [NAL9602](INFO): No messages in MT queue 2019-04-11T15:34:22.512Z,1554996862.512 [DataOverHttps](INFO): Sending 644 bytes from file Logs/20190411T152412/Express0008.lzma 2019-04-11T15:34:23.317Z,1554996863.317 [DataOverHttps](INFO): Moved sent file to Logs/20190411T152412/Express0008.lzma.bak 2019-04-11T15:34:23.317Z,1554996863.317 [DataOverHttps](INFO): SBD MOMSN=10552427 2019-04-11T15:34:24.063Z,1554996864.063 [Default:CheckIn:Read_Iridium] Stopped 2019-04-11T15:34:24.063Z,1554996864.063 [Default:CheckIn:C.Wait] Running Loop=1 2019-04-11T15:34:24.063Z,1554996864.063 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-04-11T15:34:26.121Z,1554996866.121 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-04-11T15:34:30.983Z,1554996870.983 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -22.00 mm (1 active estimators). 2019-04-11T15:34:45.574Z,1554996885.574 [NAL9602](INFO): Not Powering down - fast GPS 2019-04-11T15:35:40.132Z,1554996940.132 [DataOverHttps](IMPORTANT): SBD MTMSN=20190411T153539