2015-06-01T21:19:04.614Z,1433193544.614 [Supervisor](DEBUG): Initializing supervisor. 2015-06-01T21:19:04.618Z,1433193544.618 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0 2015-06-01T21:19:04.618Z,1433193544.618 [SyncHandler](INFO): Protected caller Thread ID is 764 2015-06-01T21:19:04.619Z,1433193544.619 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2015-06-01T21:19:04.620Z,1433193544.620 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0 2015-06-01T21:19:04.621Z,1433193544.621 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 765 2015-06-01T21:19:04.623Z,1433193544.623 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2015-06-01T21:19:04.636Z,1433193544.636 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2015-06-01T21:19:04.640Z,1433193544.640 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0 2015-06-01T21:19:04.641Z,1433193544.641 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 766 2015-06-01T21:19:04.641Z,1433193544.641 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2015-06-01T21:19:04.644Z,1433193544.644 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0 2015-06-01T21:19:04.645Z,1433193544.645 [logger ThreadHandler](INFO): Protected caller Thread ID is 767 2015-06-01T21:19:04.647Z,1433193544.647 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2015-06-01T21:19:04.647Z,1433193544.647 [Supervisor](INFO): Looking for Config files in directory: Config/ 2015-06-01T21:19:04.650Z,1433193544.650 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2015-06-01T21:19:05.080Z,1433193545.080 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2015-06-01T21:19:05.082Z,1433193545.082 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2015-06-01T21:19:05.270Z,1433193545.270 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2015-06-01T21:19:05.272Z,1433193545.272 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2015-06-01T21:19:05.394Z,1433193545.394 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2015-06-01T21:19:05.396Z,1433193545.396 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2015-06-01T21:19:05.533Z,1433193545.533 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2015-06-01T21:19:05.534Z,1433193545.534 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2015-06-01T21:19:05.631Z,1433193545.631 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2015-06-01T21:19:05.847Z,1433193545.847 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2015-06-01T21:19:05.849Z,1433193545.849 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2015-06-01T21:19:05.946Z,1433193545.946 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2015-06-01T21:19:05.948Z,1433193545.948 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2015-06-01T21:19:06.194Z,1433193546.194 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2015-06-01T21:19:06.195Z,1433193546.195 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2015-06-01T21:19:06.610Z,1433193546.610 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2015-06-01T21:19:06.611Z,1433193546.611 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2015-06-01T21:19:06.965Z,1433193546.965 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2015-06-01T21:19:06.967Z,1433193546.967 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2015-06-01T21:19:07.523Z,1433193547.523 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2015-06-01T21:19:07.524Z,1433193547.524 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2015-06-01T21:19:07.747Z,1433193547.747 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2015-06-01T21:19:07.747Z,1433193547.747 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2015-06-01T21:19:07.862Z,1433193547.862 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2015-06-01T21:19:07.863Z,1433193547.863 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2015-06-01T21:19:08.348Z,1433193548.348 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2015-06-01T21:19:08.348Z,1433193548.348 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2015-06-01T21:19:08.470Z,1433193548.470 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2015-06-01T21:19:08.472Z,1433193548.472 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2015-06-01T21:19:08.475Z,1433193548.475 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2015-06-01T21:19:08.740Z,1433193548.740 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2015-06-01T21:19:08.740Z,1433193548.740 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2015-06-01T21:19:08.876Z,1433193548.876 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg 2015-06-01T21:19:08.999Z,1433193548.999 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2015-06-01T21:19:09.113Z,1433193549.113 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2015-06-01T21:19:09.225Z,1433193549.225 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2015-06-01T21:19:09.329Z,1433193549.329 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2015-06-01T21:19:09.478Z,1433193549.478 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2015-06-01T21:19:09.651Z,1433193549.651 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2015-06-01T21:19:09.754Z,1433193549.754 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2015-06-01T21:19:09.862Z,1433193549.862 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2015-06-01T21:19:09.970Z,1433193549.970 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2015-06-01T21:19:10.102Z,1433193550.102 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2015-06-01T21:19:10.192Z,1433193550.192 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2015-06-01T21:19:10.197Z,1433193550.197 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2015-06-01T21:19:10.267Z,1433193550.267 [VerticalControl](DEBUG): Construct VerticalControl. 2015-06-01T21:19:10.393Z,1433193550.393 [VerticalControl] Loaded 2015-06-01T21:19:10.393Z,1433193550.393 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2015-06-01T21:19:10.394Z,1433193550.394 [HorizontalControl](DEBUG): Construct HorizontalControl. 2015-06-01T21:19:10.471Z,1433193550.471 [HorizontalControl] Loaded 2015-06-01T21:19:10.471Z,1433193550.471 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2015-06-01T21:19:10.472Z,1433193550.472 [SpeedControl](DEBUG): Construct SpeedControl. 2015-06-01T21:19:10.477Z,1433193550.477 [SpeedControl] Loaded 2015-06-01T21:19:10.478Z,1433193550.478 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2015-06-01T21:19:10.478Z,1433193550.478 [LoopControl](DEBUG): Construct LoopControl. 2015-06-01T21:19:10.479Z,1433193550.479 [LoopControl] Loaded 2015-06-01T21:19:10.479Z,1433193550.479 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2015-06-01T21:19:10.480Z,1433193550.480 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2015-06-01T21:19:10.480Z,1433193550.480 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2015-06-01T21:19:10.629Z,1433193550.629 [SBIT](DEBUG): Construct Startup Built In Test. 2015-06-01T21:19:10.644Z,1433193550.644 [SBIT] Loaded 2015-06-01T21:19:10.644Z,1433193550.644 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2015-06-01T21:19:10.645Z,1433193550.645 [IBIT](DEBUG): Construct Initiated Built In Test. 2015-06-01T21:19:10.673Z,1433193550.673 [IBIT] Loaded 2015-06-01T21:19:10.673Z,1433193550.673 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2015-06-01T21:19:10.676Z,1433193550.676 [CBIT](DEBUG): Construct Continuous Built In Test. 2015-06-01T21:19:10.823Z,1433193550.823 [CBIT] Loaded 2015-06-01T21:19:10.823Z,1433193550.823 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2015-06-01T21:19:10.823Z,1433193550.823 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2015-06-01T21:19:10.824Z,1433193550.824 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2015-06-01T21:19:10.855Z,1433193550.855 [DepthRateCalculator] Loaded 2015-06-01T21:19:10.855Z,1433193550.855 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2015-06-01T21:19:10.860Z,1433193550.860 [PitchRateCalculator] Loaded 2015-06-01T21:19:10.860Z,1433193550.860 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2015-06-01T21:19:10.871Z,1433193550.871 [SpeedCalculator] Loaded 2015-06-01T21:19:10.871Z,1433193550.871 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2015-06-01T21:19:10.887Z,1433193550.887 [TempGradientCalculator] Loaded 2015-06-01T21:19:10.887Z,1433193550.887 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2015-06-01T21:19:10.892Z,1433193550.892 [YawRateCalculator] Loaded 2015-06-01T21:19:10.892Z,1433193550.892 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2015-06-01T21:19:10.893Z,1433193550.893 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2015-06-01T21:19:10.893Z,1433193550.893 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2015-06-01T21:19:14.809Z,1433193554.809 [HFRadarCompactModelForecaster] Loaded 2015-06-01T21:19:14.809Z,1433193554.809 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread. 2015-06-01T21:19:15.741Z,1433193555.741 [HFRCMSpaceInterpolator] Loaded 2015-06-01T21:19:15.742Z,1433193555.742 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread. 2015-06-01T21:19:15.744Z,1433193555.744 [HFRCMTimeInterpolator] Loaded 2015-06-01T21:19:15.744Z,1433193555.744 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread. 2015-06-01T21:19:16.680Z,1433193556.680 [HFRCMReconstructedInterpolator] Loaded 2015-06-01T21:19:16.680Z,1433193556.680 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread. 2015-06-01T21:19:16.692Z,1433193556.692 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded 2015-06-01T21:19:16.692Z,1433193556.692 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread. 2015-06-01T21:19:16.717Z,1433193556.717 [HFRCMVirtualSurfaceDrifter] Loaded 2015-06-01T21:19:16.717Z,1433193556.717 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread. 2015-06-01T21:19:16.718Z,1433193556.718 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2015-06-01T21:19:16.718Z,1433193556.718 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2015-06-01T21:19:16.969Z,1433193556.969 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2015-06-01T21:19:16.970Z,1433193556.970 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2015-06-01T21:19:17.082Z,1433193557.082 [DeadReckonUsingMultipleVelocitySources] Loaded 2015-06-01T21:19:17.082Z,1433193557.082 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2015-06-01T21:19:17.135Z,1433193557.135 [DeadReckonUsingSpeedCalculator] Loaded 2015-06-01T21:19:17.135Z,1433193557.135 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2015-06-01T21:19:17.151Z,1433193557.151 [NavChart] Loaded 2015-06-01T21:19:17.152Z,1433193557.152 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2015-06-01T21:19:17.156Z,1433193557.156 [UniversalFixResidualReporter] Loaded 2015-06-01T21:19:17.156Z,1433193557.156 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2015-06-01T21:19:17.157Z,1433193557.157 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2015-06-01T21:19:17.158Z,1433193557.158 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2015-06-01T21:19:17.166Z,1433193557.166 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2015-06-01T21:19:17.167Z,1433193557.167 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2015-06-01T21:19:17.371Z,1433193557.371 [Aanderaa_O2] Loaded 2015-06-01T21:19:17.371Z,1433193557.371 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2015-06-01T21:19:17.382Z,1433193557.382 [CANONSampler] Loaded 2015-06-01T21:19:17.382Z,1433193557.382 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread. 2015-06-01T21:19:17.454Z,1433193557.454 [CTD_NeilBrown] Loaded 2015-06-01T21:19:17.455Z,1433193557.455 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2015-06-01T21:19:17.456Z,1433193557.456 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406EF4E0 2015-06-01T21:19:17.456Z,1433193557.456 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 853 2015-06-01T21:19:17.469Z,1433193557.469 [ISUS] Loaded 2015-06-01T21:19:17.469Z,1433193557.469 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread. 2015-06-01T21:19:17.483Z,1433193557.483 [PAR_Licor] Loaded 2015-06-01T21:19:17.483Z,1433193557.483 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2015-06-01T21:19:17.529Z,1433193557.529 [WetLabsBB2FL] Loaded 2015-06-01T21:19:17.530Z,1433193557.530 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2015-06-01T21:19:17.531Z,1433193557.531 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4071F4E0 2015-06-01T21:19:17.531Z,1433193557.531 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 854 2015-06-01T21:19:17.532Z,1433193557.532 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2015-06-01T21:19:17.532Z,1433193557.532 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2015-06-01T21:19:18.164Z,1433193558.164 [AHRS_sp3003D] Loaded 2015-06-01T21:19:18.164Z,1433193558.164 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2015-06-01T21:19:18.327Z,1433193558.327 [DataOverHttps] Loaded 2015-06-01T21:19:18.327Z,1433193558.327 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2015-06-01T21:19:18.340Z,1433193558.340 [Depth_Keller] Loaded 2015-06-01T21:19:18.341Z,1433193558.341 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2015-06-01T21:19:18.345Z,1433193558.345 [DropWeight] Loaded 2015-06-01T21:19:18.346Z,1433193558.346 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2015-06-01T21:19:18.474Z,1433193558.474 [DVL_micro] Loaded 2015-06-01T21:19:18.474Z,1433193558.474 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2015-06-01T21:19:18.564Z,1433193558.564 [NAL9602] Loaded 2015-06-01T21:19:18.564Z,1433193558.564 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2015-06-01T21:19:18.604Z,1433193558.604 [Onboard] Loaded 2015-06-01T21:19:18.604Z,1433193558.604 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2015-06-01T21:19:18.611Z,1433193558.611 [Radio_Surface] Loaded 2015-06-01T21:19:18.611Z,1433193558.611 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2015-06-01T21:19:18.612Z,1433193558.612 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409634E0 2015-06-01T21:19:18.612Z,1433193558.612 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 855 2015-06-01T21:19:18.741Z,1433193558.741 [DAT] Loaded 2015-06-01T21:19:18.742Z,1433193558.742 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2015-06-01T21:19:20.528Z,1433193560.528 [BPC1] Loaded 2015-06-01T21:19:20.528Z,1433193560.528 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2015-06-01T21:19:20.528Z,1433193560.528 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2015-06-01T21:19:20.529Z,1433193560.529 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2015-06-01T21:19:20.645Z,1433193560.645 [BuoyancyServo] Loaded 2015-06-01T21:19:20.645Z,1433193560.645 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2015-06-01T21:19:20.657Z,1433193560.657 [ElevatorServo] Loaded 2015-06-01T21:19:20.657Z,1433193560.657 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2015-06-01T21:19:20.669Z,1433193560.669 [MassServo] Loaded 2015-06-01T21:19:20.669Z,1433193560.669 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2015-06-01T21:19:20.681Z,1433193560.681 [RudderServo] Loaded 2015-06-01T21:19:20.681Z,1433193560.681 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2015-06-01T21:19:20.693Z,1433193560.693 [ThrusterServo] Loaded 2015-06-01T21:19:20.693Z,1433193560.693 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2015-06-01T21:19:20.694Z,1433193560.694 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2015-06-01T21:19:20.694Z,1433193560.694 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2015-06-01T21:19:20.820Z,1433193560.820 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2015-06-01T21:19:20.821Z,1433193560.821 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2015-06-01T21:19:20.858Z,1433193560.858 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2015-06-01T21:19:20.862Z,1433193560.862 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2015-06-01T21:19:20.863Z,1433193560.863 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2015-06-01T21:19:20.870Z,1433193560.870 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2015-06-01T21:19:20.871Z,1433193560.871 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A114E0 2015-06-01T21:19:20.871Z,1433193560.871 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 856 2015-06-01T21:19:20.876Z,1433193560.876 [Supervisor](INFO): Main Thread ID is 760 2015-06-01T21:19:20.876Z,1433193560.876 [Supervisor](DEBUG): Running supervisor. 2015-06-01T21:19:20.877Z,1433193560.877 [CommandLine ThreadHandler](INFO): Handler Thread ID is 857 2015-06-01T21:19:20.880Z,1433193560.880 [controlThread ThreadHandler](INFO): Handler Thread ID is 858 2015-06-01T21:19:20.880Z,1433193560.880 [controlThread](DEBUG): Initializing ControlThread 2015-06-01T21:19:20.881Z,1433193560.881 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2015-06-01T21:19:20.883Z,1433193560.883 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2015-06-01T21:19:20.884Z,1433193560.884 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2015-06-01T21:19:20.884Z,1433193560.884 [LoopControl](DEBUG): Initialize LoopControlComponent. 2015-06-01T21:19:20.884Z,1433193560.884 [SBIT](INFO): Initialize SBIT Component. 2015-06-01T21:19:20.885Z,1433193560.885 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:12274 2015-06-01T21:19:20.885Z,1433193560.885 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2015-06-01T21:19:20.886Z,1433193560.886 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014 2015-06-01T21:19:20.886Z,1433193560.886 [IBIT](INFO): Initialize IBIT Component. 2015-06-01T21:19:20.887Z,1433193560.887 [CBIT](DEBUG): Initialize CBIT Component. 2015-06-01T21:19:20.887Z,1433193560.887 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2015-06-01T21:19:20.888Z,1433193560.888 [logger ThreadHandler](INFO): Handler Thread ID is 859 2015-06-01T21:19:20.914Z,1433193560.914 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2015-06-01T21:19:20.914Z,1433193560.914 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2015-06-01T21:19:20.914Z,1433193560.914 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2015-06-01T21:19:20.915Z,1433193560.915 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2015-06-01T21:19:20.915Z,1433193560.915 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2015-06-01T21:19:20.918Z,1433193560.918 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 860 2015-06-01T21:19:20.924Z,1433193560.924 [HFRadarCompactModelForecaster](DEBUG): Found new ECs! 2015-06-01T21:19:20.924Z,1433193560.924 [HFRadarCompactModelForecaster](ERROR): Most recent ECs are more than six hours old. 2015-06-01T21:19:20.925Z,1433193560.925 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2015-06-01T21:19:20.928Z,1433193560.928 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4 2015-06-01T21:19:20.960Z,1433193560.960 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 862 2015-06-01T21:19:20.962Z,1433193560.962 [WetLabsBB2FL](INFO): Powering down 2015-06-01T21:19:21.002Z,1433193561.002 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 863 2015-06-01T21:19:21.008Z,1433193561.008 [Radio_Surface](INFO): Powering up 2015-06-01T21:19:21.020Z,1433193561.020 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 864 2015-06-01T21:19:21.028Z,1433193561.028 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2015-06-01T21:19:21.029Z,1433193561.029 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2015-06-01T21:19:21.029Z,1433193561.029 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2015-06-01T21:19:21.029Z,1433193561.029 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2015-06-01T21:19:21.029Z,1433193561.029 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2015-06-01T21:19:21.030Z,1433193561.030 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2015-06-01T21:19:21.030Z,1433193561.030 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2015-06-01T21:19:21.030Z,1433193561.030 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2015-06-01T21:19:21.031Z,1433193561.031 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2015-06-01T21:19:21.082Z,1433193561.082 [CTD_NeilBrown](DEBUG): CTD uart timeout: serial timeout 2015-06-01T21:19:21.082Z,1433193561.082 [CTD_NeilBrown](ERROR): Could not get real or simulated CTD data. startTime.elapsed() = 0.153742 2015-06-01T21:19:30.022Z,1433193570.022 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201505192300 published 2015-06-01T21:19:30.034Z,1433193570.034 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0. 2015-06-01T21:19:30.044Z,1433193570.044 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component. 2015-06-01T21:19:30.045Z,1433193570.045 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s. 2015-06-01T21:19:30.046Z,1433193570.046 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component. 2015-06-01T21:19:30.047Z,1433193570.047 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component. 2015-06-01T21:19:30.047Z,1433193570.047 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2015-06-01T21:19:30.056Z,1433193570.056 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after this many seconds: 120.000000 2015-06-01T21:19:30.056Z,1433193570.056 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after this many seconds: 20.000000 2015-06-01T21:19:30.057Z,1433193570.057 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2015-06-01T21:19:30.057Z,1433193570.057 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after this many seconds: 120.000000 2015-06-01T21:19:30.057Z,1433193570.057 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after this many seconds: 20.000000 2015-06-01T21:19:30.058Z,1433193570.058 [NavChart](DEBUG): Initialize NavChart Navigation. 2015-06-01T21:19:30.058Z,1433193570.058 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2015-06-01T21:19:30.083Z,1433193570.083 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2015-06-01T21:19:30.128Z,1433193570.128 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2015-06-01T21:19:30.146Z,1433193570.146 [MissionManager](DEBUG): 2015-06-01T21:19:30.147Z,1433193570.147 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2015-06-01T21:19:30.227Z,1433193570.227 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2015-06-01T21:19:30.228Z,1433193570.228 [Default:A.GoToSurface](DEBUG): Construct GoToSurface. 2015-06-01T21:19:30.245Z,1433193570.245 [Default:CheckIn:A.SetSpeed](DEBUG): Construct. 2015-06-01T21:19:30.302Z,1433193570.302 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2015-06-01T21:19:30.313Z,1433193570.313 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct. 2015-06-01T21:19:30.327Z,1433193570.327 [MissionManager](DEBUG): 0 5.0 1.0 400 10 500 Default mission has been running for Burn 300 Dropped weight due to communications timeout. 5 2015-06-01T21:19:30.333Z,1433193570.333 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,CANONSampler,ISUS,PAR_Licor,AHRS_sp3003D,DataOverHttps,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMReconstructedInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2015-06-01T21:19:30.387Z,1433193570.387 [CANONSampler](INFO): Powering down 2015-06-01T21:19:30.493Z,1433193570.493 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2015-06-01T21:19:30.806Z,1433193570.806 [DVL_micro](INFO): Initializing 2015-06-01T21:19:30.835Z,1433193570.835 [NAL9602](INFO): Powering up NAL9602 2015-06-01T21:19:30.877Z,1433193570.877 [DAT](INFO): Powering up 2015-06-01T21:19:30.877Z,1433193570.877 [DAT](DEBUG): Initializing DAT. 2015-06-01T21:19:40.488Z,1433193580.488 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2015-06-01T21:19:40.500Z,1433193580.500 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2015-06-01T21:19:40.613Z,1433193580.613 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2015-06-01T21:19:40.620Z,1433193580.620 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2015-06-01T21:19:40.643Z,1433193580.643 [ElevatorServo](DEBUG): Initializing EZServoServo. 2015-06-01T21:19:40.648Z,1433193580.648 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2015-06-01T21:19:40.658Z,1433193580.658 [MassServo](DEBUG): Initializing EZServoServo. 2015-06-01T21:19:40.664Z,1433193580.664 [MassServo](DEBUG): Initializing MassServo. 2015-06-01T21:19:40.686Z,1433193580.686 [RudderServo](DEBUG): Initializing EZServoServo. 2015-06-01T21:19:40.692Z,1433193580.692 [RudderServo](DEBUG): Initializing RudderServo. 2015-06-01T21:19:40.714Z,1433193580.714 [ThrusterServo](DEBUG): Initializing EZServoServo. 2015-06-01T21:19:40.720Z,1433193580.720 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2015-06-01T21:19:40.843Z,1433193580.843 [Aanderaa_O2](FAULT): Timed out starting 2015-06-01T21:19:40.843Z,1433193580.843 [Aanderaa_O2] Communications Fault, FailCount= 1 2015-06-01T21:19:40.843Z,1433193580.843 [Aanderaa_O2](ERROR): Communications Fault 2015-06-01T21:19:40.953Z,1433193580.953 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar 2015-06-01T21:19:41.015Z,1433193581.015 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2015-06-01T21:19:41.016Z,1433193581.016 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2015-06-01T21:19:41.040Z,1433193581.040 [SBIT](IMPORTANT): Beginning Startup BIT 2015-06-01T21:19:41.050Z,1433193581.050 [CBIT](ERROR): Communications Fault in component: Aanderaa_O2 2015-06-01T21:19:41.051Z,1433193581.051 [CBIT](IMPORTANT): Beginning GF scan 2015-06-01T21:19:41.321Z,1433193581.321 [Aanderaa_O2](INFO): Powering down 2015-06-01T21:19:42.527Z,1433193582.527 [NAL9602](INFO): NAL9602 initialized 2015-06-01T21:19:43.071Z,1433193583.071 [CBIT](INFO): Clearing failed state for component Aanderaa_O2 2015-06-01T21:19:43.072Z,1433193583.072 [Aanderaa_O2] No Fault, FailCount= 1 2015-06-01T21:19:46.285Z,1433193586.285 [Aanderaa_O2](INFO): Powering down 2015-06-01T21:19:47.291Z,1433193587.291 [DAT](DEBUG): 2015-06-01T21:19:47.831Z,1433193587.831 [DAT](DEBUG): Teledyne Benthos ATM-900 Series 2015-06-01T21:19:47.840Z,1433193587.840 [DAT](DEBUG): MF Frequency Band 2015-06-01T21:19:47.841Z,1433193587.841 [DAT](DEBUG): Directional Acoustic Transponder version 8.3.1 2015-06-01T21:19:48.395Z,1433193588.395 [DAT](DEBUG): Jun 1 2015 22:19:06 2015-06-01T21:19:49.531Z,1433193589.531 [DAT](INFO): entering command mode 2015-06-01T21:19:49.987Z,1433193589.987 [DAT](DEBUG): checking for command mode acknowledgment 2015-06-01T21:19:49.988Z,1433193589.988 [DAT](DEBUG): read user prompt 1: user:1> 2015-06-01T21:19:49.988Z,1433193589.988 [DAT](INFO): command mode acknowledged 2015-06-01T21:19:50.513Z,1433193590.513 [DAT](INFO): setting local address to 2 2015-06-01T21:19:50.964Z,1433193590.964 [DAT](DEBUG): checking for local address setting acknowledgment 2015-06-01T21:19:50.965Z,1433193590.965 [DAT](INFO): set local address to 2 2015-06-01T21:19:51.416Z,1433193591.416 [DAT](DEBUG): read user prompt 2: user:2> 2015-06-01T21:19:54.420Z,1433193594.420 [SBIT](ERROR): Could not read massPosReader_. 2015-06-01T21:20:01.021Z,1433193601.021 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 24 of 46 2015-06-01T21:20:01.022Z,1433193601.022 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 1387 1136 1358 539 2 3 2 2 38.7 796.8 11 2015-06-01T21:20:08.196Z,1433193608.196 [CBIT](IMPORTANT): No ground fault detected 2015-06-01T21:20:35.439Z,1433193635.439 [SBIT](CRITICAL): SBIT FAILED 2015-06-01T21:20:35.440Z,1433193635.440 [CommandLine](FAULT): Scheduling is paused 2015-06-01T21:20:35.892Z,1433193635.892 [MissionManager](IMPORTANT): Started mission Startup 2015-06-01T21:20:35.893Z,1433193635.893 [Startup] Running Loop=1 2015-06-01T21:20:35.893Z,1433193635.893 [Startup](INFO): Aggregate::initialize Startup 2015-06-01T21:20:35.893Z,1433193635.893 [Startup:A.GoToSurface] Running Loop=1 2015-06-01T21:20:35.893Z,1433193635.893 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2015-06-01T21:20:35.898Z,1433193635.898 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2015-06-01T21:20:35.898Z,1433193635.898 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2015-06-01T21:20:35.899Z,1433193635.899 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s. 2015-06-01T21:20:35.909Z,1433193635.909 [Startup:StartupSatComms] Running Loop=1 2015-06-01T21:20:35.909Z,1433193635.909 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2015-06-01T21:20:35.909Z,1433193635.909 [Startup:StartupSatComms:A] Running Loop=1 2015-06-01T21:20:36.306Z,1433193636.306 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2015-06-01T21:20:58.095Z,1433193658.095 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003806 2015-06-01T21:21:36.260Z,1433193696.260 [Startup:StartupSatComms:A](INFO): Timed out from 2015-06-01T21:20:35.9Z 2015-06-01T21:21:36.260Z,1433193696.260 [Startup:StartupSatComms:A] Stopped 2015-06-01T21:21:36.260Z,1433193696.260 [Startup:StartupSatComms:B] Running Loop=1 2015-06-01T21:21:36.710Z,1433193696.710 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2015-06-01T21:21:41.513Z,1433193701.513 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150601T211904/Courier0000.lzma 2015-06-01T21:21:42.448Z,1433193702.448 [DataOverHttps](INFO): Moved sent file to Logs/20150601T211904/Courier0000.lzma.bak 2015-06-01T21:21:42.448Z,1433193702.448 [DataOverHttps](INFO): SBD MOMSN=3530298 2015-06-01T21:21:52.608Z,1433193712.608 [DataOverHttps](INFO): Sending 672 bytes from file Logs/20150601T211904/Express0001.lzma 2015-06-01T21:21:53.489Z,1433193713.489 [DataOverHttps](INFO): Moved sent file to Logs/20150601T211904/Express0001.lzma.bak 2015-06-01T21:21:53.490Z,1433193713.490 [DataOverHttps](INFO): SBD MOMSN=3530302 2015-06-01T21:21:53.986Z,1433193713.986 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients. 2015-06-01T21:21:53.993Z,1433193713.993 [Startup:StartupSatComms:B] Stopped 2015-06-01T21:21:53.993Z,1433193713.993 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2015-06-01T21:21:53.993Z,1433193713.993 [Startup:StartupSatComms] Stopped 2015-06-01T21:21:53.993Z,1433193713.993 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2015-06-01T21:21:53.994Z,1433193713.994 [Startup](INFO): Completed Startup 2015-06-01T21:21:53.994Z,1433193713.994 [Startup] Stopped 2015-06-01T21:21:53.994Z,1433193713.994 [Startup](INFO): Aggregate::uninitialize Startup 2015-06-01T21:21:53.994Z,1433193713.994 [Startup:A.GoToSurface] Stopped 2015-06-01T21:21:53.994Z,1433193713.994 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2015-06-01T21:21:54.412Z,1433193714.412 [MissionManager](IMPORTANT): Started mission Default 2015-06-01T21:21:54.412Z,1433193714.412 [Default] Running Loop=1 2015-06-01T21:21:54.412Z,1433193714.412 [Default](INFO): Aggregate::initialize Default 2015-06-01T21:21:54.413Z,1433193714.413 [Default:A.GoToSurface] Running Loop=1 2015-06-01T21:21:54.413Z,1433193714.413 [Default:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2015-06-01T21:21:54.413Z,1433193714.413 [Default:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2015-06-01T21:21:54.413Z,1433193714.413 [Default:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2015-06-01T21:21:54.414Z,1433193714.414 [Default:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s. 2015-06-01T21:21:54.439Z,1433193714.439 [Default:WaitAtTheSurface] Running Loop=1 2015-06-01T21:21:54.440Z,1433193714.440 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface 2015-06-