2012-09-19T16:50:44.500Z,1348073444.500 [Supervisor](DEBUG): Initializing supervisor. 2012-09-19T16:50:44.503Z,1348073444.503 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0 2012-09-19T16:50:44.503Z,1348073444.503 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2012-09-19T16:50:44.507Z,1348073444.507 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0 2012-09-19T16:50:44.510Z,1348073444.510 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2012-09-19T16:50:44.521Z,1348073444.521 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2012-09-19T16:50:44.523Z,1348073444.523 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0 2012-09-19T16:50:44.524Z,1348073444.524 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread. 2012-09-19T16:50:44.524Z,1348073444.524 [Supervisor](INFO): Looking for Config files in directory: Config/ 2012-09-19T16:50:44.527Z,1348073444.527 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2012-09-19T16:50:44.844Z,1348073444.844 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2012-09-19T16:50:44.846Z,1348073444.846 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2012-09-19T16:50:45.051Z,1348073445.051 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2012-09-19T16:50:45.052Z,1348073445.052 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2012-09-19T16:50:45.146Z,1348073445.146 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2012-09-19T16:50:45.148Z,1348073445.148 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2012-09-19T16:50:45.368Z,1348073445.368 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2012-09-19T16:50:45.368Z,1348073445.368 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2012-09-19T16:50:45.522Z,1348073445.522 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2012-09-19T16:50:45.524Z,1348073445.524 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2012-09-19T16:50:45.788Z,1348073445.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2012-09-19T16:50:45.788Z,1348073445.788 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2012-09-19T16:50:45.981Z,1348073445.981 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2012-09-19T16:50:45.983Z,1348073445.983 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2012-09-19T16:50:46.268Z,1348073446.268 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2012-09-19T16:50:46.270Z,1348073446.270 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2012-09-19T16:50:46.383Z,1348073446.383 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2012-09-19T16:50:46.384Z,1348073446.384 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2012-09-19T16:50:46.848Z,1348073446.848 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2012-09-19T16:50:46.849Z,1348073446.849 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2012-09-19T16:50:46.977Z,1348073446.977 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2012-09-19T16:50:46.977Z,1348073446.977 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2012-09-19T16:50:47.072Z,1348073447.072 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2012-09-19T16:50:47.075Z,1348073447.076 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2012-09-19T16:50:47.186Z,1348073447.187 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2012-09-19T16:50:47.335Z,1348073447.335 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2012-09-19T16:50:47.431Z,1348073447.431 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2012-09-19T16:50:47.542Z,1348073447.542 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2012-09-19T16:50:47.655Z,1348073447.655 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2012-09-19T16:50:47.788Z,1348073447.788 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2012-09-19T16:50:47.890Z,1348073447.890 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2012-09-19T16:50:48.036Z,1348073448.036 [Supervisor](FAULT): Ignoring configuration overrides from Data/config.db 2012-09-19T16:50:48.380Z,1348073448.380 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2012-09-19T16:50:49.387Z,1348073449.388 [InternalSim] Loaded 2012-09-19T16:50:49.388Z,1348073449.388 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2012-09-19T16:50:49.389Z,1348073449.389 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2012-09-19T16:50:49.389Z,1348073449.389 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2012-09-19T16:50:49.472Z,1348073449.472 [SBIT](DEBUG): Construct Startup Built In Test. 2012-09-19T16:50:49.485Z,1348073449.485 [SBIT] Loaded 2012-09-19T16:50:49.486Z,1348073449.486 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2012-09-19T16:50:49.486Z,1348073449.487 [IBIT](DEBUG): Construct Initiated Built In Test. 2012-09-19T16:50:49.519Z,1348073449.519 [IBIT] Loaded 2012-09-19T16:50:49.519Z,1348073449.519 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2012-09-19T16:50:49.522Z,1348073449.522 [CBIT](DEBUG): Construct CBIT Built In Test. 2012-09-19T16:50:49.658Z,1348073449.658 [CBIT] Loaded 2012-09-19T16:50:49.658Z,1348073449.658 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2012-09-19T16:50:49.659Z,1348073449.659 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2012-09-19T16:50:49.659Z,1348073449.659 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2012-09-19T16:50:49.833Z,1348073449.833 [BuoyancyServo] Loaded 2012-09-19T16:50:49.833Z,1348073449.833 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2012-09-19T16:50:49.843Z,1348073449.843 [ElevatorServo] Loaded 2012-09-19T16:50:49.843Z,1348073449.843 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2012-09-19T16:50:49.855Z,1348073449.855 [MassServo] Loaded 2012-09-19T16:50:49.855Z,1348073449.855 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2012-09-19T16:50:49.871Z,1348073449.871 [RudderServo] Loaded 2012-09-19T16:50:49.872Z,1348073449.872 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2012-09-19T16:50:49.883Z,1348073449.883 [ThrusterServo] Loaded 2012-09-19T16:50:49.883Z,1348073449.883 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2012-09-19T16:50:49.884Z,1348073449.884 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2012-09-19T16:50:49.885Z,1348073449.885 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2012-09-19T16:50:49.918Z,1348073449.918 [DepthRateCalculator] Loaded 2012-09-19T16:50:49.918Z,1348073449.918 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2012-09-19T16:50:53.017Z,1348073453.017 [HFRadarModelCalc] Loaded 2012-09-19T16:50:53.018Z,1348073453.017 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread. 2012-09-19T16:50:53.034Z,1348073453.034 [NavChart] Loaded 2012-09-19T16:50:53.034Z,1348073453.034 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2012-09-19T16:50:53.040Z,1348073453.040 [PitchRateCalculator] Loaded 2012-09-19T16:50:53.040Z,1348073453.040 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2012-09-19T16:50:53.047Z,1348073453.047 [SpeedCalculator] Loaded 2012-09-19T16:50:53.047Z,1348073453.047 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2012-09-19T16:50:53.062Z,1348073453.062 [TempGradientCalculator] Loaded 2012-09-19T16:50:53.063Z,1348073453.063 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2012-09-19T16:50:53.069Z,1348073453.069 [YawRateCalculator] Loaded 2012-09-19T16:50:53.069Z,1348073453.069 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2012-09-19T16:50:53.089Z,1348073453.089 [Navigation] Loaded 2012-09-19T16:50:53.089Z,1348073453.089 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread. 2012-09-19T16:50:53.089Z,1348073453.089 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2012-09-19T16:50:53.090Z,1348073453.090 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2012-09-19T16:50:53.388Z,1348073453.388 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2012-09-19T16:50:53.389Z,1348073453.389 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2012-09-19T16:50:53.429Z,1348073453.429 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2012-09-19T16:50:53.430Z,1348073453.430 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2012-09-19T16:50:53.505Z,1348073453.505 [VerticalControl](DEBUG): Construct VerticalControl. 2012-09-19T16:50:53.554Z,1348073453.554 [VerticalControl] Loaded 2012-09-19T16:50:53.555Z,1348073453.555 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2012-09-19T16:50:53.556Z,1348073453.556 [HorizontalControl](DEBUG): Construct HorizontalControl. 2012-09-19T16:50:53.580Z,1348073453.580 [HorizontalControl] Loaded 2012-09-19T16:50:53.581Z,1348073453.581 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2012-09-19T16:50:53.582Z,1348073453.582 [SpeedControl](DEBUG): Construct SpeedControl. 2012-09-19T16:50:53.584Z,1348073453.584 [SpeedControl] Loaded 2012-09-19T16:50:53.584Z,1348073453.584 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2012-09-19T16:50:53.585Z,1348073453.585 [LoopControl](DEBUG): Construct LoopControl. 2012-09-19T16:50:53.585Z,1348073453.585 [LoopControl] Loaded 2012-09-19T16:50:53.586Z,1348073453.586 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2012-09-19T16:50:53.586Z,1348073453.586 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2012-09-19T16:50:53.587Z,1348073453.587 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2012-09-19T16:50:53.595Z,1348073453.595 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2012-09-19T16:50:53.600Z,1348073453.600 [AsyncPiEstimator] Loaded 2012-09-19T16:50:53.600Z,1348073453.600 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2012-09-19T16:50:53.603Z,1348073453.603 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4060A4E0 2012-09-19T16:50:53.603Z,1348073453.603 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2012-09-19T16:50:53.604Z,1348073453.604 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2012-09-19T16:50:53.782Z,1348073453.782 [AHRS_sp3003D] Loaded 2012-09-19T16:50:53.782Z,1348073453.782 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2012-09-19T16:50:53.800Z,1348073453.800 [Depth_Keller] Loaded 2012-09-19T16:50:53.801Z,1348073453.801 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2012-09-19T16:50:53.811Z,1348073453.811 [DropWeight] Loaded 2012-09-19T16:50:53.811Z,1348073453.811 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2012-09-19T16:50:53.942Z,1348073453.942 [DVL_micro] Loaded 2012-09-19T16:50:53.943Z,1348073453.943 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread. 2012-09-19T16:50:53.947Z,1348073453.947 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4068A4E0 2012-09-19T16:50:54.040Z,1348073454.040 [NAL9602] Loaded 2012-09-19T16:50:54.041Z,1348073454.041 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2012-09-19T16:50:54.096Z,1348073454.096 [Onboard] Loaded 2012-09-19T16:50:54.096Z,1348073454.096 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2012-09-19T16:50:54.107Z,1348073454.107 [Radio_Freewave] Loaded 2012-09-19T16:50:54.108Z,1348073454.108 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread. 2012-09-19T16:50:54.108Z,1348073454.108 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2012-09-19T16:50:54.109Z,1348073454.109 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2012-09-19T16:50:54.215Z,1348073454.215 [CTD_NeilBrown] Loaded 2012-09-19T16:50:54.215Z,1348073454.216 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2012-09-19T16:50:54.219Z,1348073454.219 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E24E0 2012-09-19T16:50:54.229Z,1348073454.229 [PAR_Licor] Loaded 2012-09-19T16:50:54.229Z,1348073454.229 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2012-09-19T16:50:54.250Z,1348073454.250 [Turbulence_NPS] Loaded 2012-09-19T16:50:54.250Z,1348073454.250 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread. 2012-09-19T16:50:54.255Z,1348073454.255 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407124E0 2012-09-19T16:50:54.289Z,1348073454.289 [WetLabsBB2FL] Loaded 2012-09-19T16:50:54.289Z,1348073454.289 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2012-09-19T16:50:54.291Z,1348073454.291 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407424E0 2012-09-19T16:50:54.291Z,1348073454.291 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2012-09-19T16:50:54.294Z,1348073454.294 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2012-09-19T16:50:54.295Z,1348073454.295 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2012-09-19T16:50:54.301Z,1348073454.301 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2012-09-19T16:50:54.303Z,1348073454.303 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407724E0 2012-09-19T16:50:54.307Z,1348073454.307 [Supervisor](DEBUG): Running supervisor. 2012-09-19T16:50:54.311Z,1348073454.311 [controlThread](DEBUG): Initializing ControlThread 2012-09-19T16:50:54.312Z,1348073454.312 [InternalSim](DEBUG): InternalSim initializing... 2012-09-19T16:50:54.424Z,1348073454.424 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2012-09-19T16:50:54.585Z,1348073454.585 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2012-09-19T16:50:54.628Z,1348073454.628 [DVL_micro](INFO): Initializing 2012-09-19T16:50:54.628Z,1348073454.628 [DVL_micro](INFO): start:Powering up 2012-09-19T16:50:54.631Z,1348073454.631 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS. 2012-09-19T16:50:54.642Z,1348073454.642 [SBIT](INFO): Initialize SBIT Component. 2012-09-19T16:50:54.642Z,1348073454.642 [SBIT](IMPORTANT): Tethys CM Info: $Rev: 9842 2012-09-19T16:50:54.644Z,1348073454.644 [WetLabsBB2FL](INFO): Powering down 2012-09-19T16:50:54.663Z,1348073454.663 [IBIT](INFO): Initialize IBIT Component. 2012-09-19T16:50:54.664Z,1348073454.664 [CBIT](DEBUG): Initialize CBIT Component. 2012-09-19T16:50:54.664Z,1348073454.664 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2012-09-19T16:50:54.665Z,1348073454.665 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2012-09-19T16:50:54.692Z,1348073454.692 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2012-09-19T16:50:54.693Z,1348073454.693 [NavChart](DEBUG): Initialize NavChart Derivation. 2012-09-19T16:50:54.693Z,1348073454.693 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2012-09-19T16:50:54.693Z,1348073454.693 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2012-09-19T16:50:54.694Z,1348073454.694 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2012-09-19T16:50:54.695Z,1348073454.695 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2012-09-19T16:50:54.696Z,1348073454.696 [Navigation](DEBUG): Initializing Navigation. 2012-09-19T16:50:54.696Z,1348073454.696 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2012-09-19T16:50:54.698Z,1348073454.698 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2012-09-19T16:50:54.699Z,1348073454.699 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2012-09-19T16:50:54.700Z,1348073454.700 [LoopControl](DEBUG): Initialize LoopControlComponent. 2012-09-19T16:50:54.706Z,1348073454.706 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2012-09-19T16:50:54.802Z,1348073454.802 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T16:50:54.812Z,1348073454.812 [MissionManager](DEBUG): 2012-09-19T16:50:54.813Z,1348073454.813 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2012-09-19T16:50:54.886Z,1348073454.886 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool 2012-09-19T16:50:54.888Z,1348073454.888 [Default:GPS:A.SetSpeed](DEBUG): Construct. 2012-09-19T16:50:54.891Z,1348073454.891 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T16:50:54.900Z,1348073454.900 [Default:Iridium:A.SetSpeed](DEBUG): Construct. 2012-09-19T16:50:54.907Z,1348073454.907 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T16:50:54.913Z,1348073454.913 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2012-09-19T16:50:54.923Z,1348073454.923 [Default:D.SetSpeed](DEBUG): Construct. 2012-09-19T16:50:54.926Z,1348073454.926 [Default:E.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T16:50:54.931Z,1348073454.931 [Default:F.Wait](DEBUG): Construct Wait. 2012-09-19T16:50:54.935Z,1348073454.935 [MissionManager](DEBUG): 400 400 Burn 300 Dropped drop weight due to communications timeout 5.0 1.0 5 2012-09-19T16:50:54.939Z,1348073454.939 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger, 2012-09-19T16:50:54.962Z,1348073454.962 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2012-09-19T16:50:55.115Z,1348073455.115 [Depth_Keller](INFO): A/D timeout, 2 tries over 139 ms 2012-09-19T16:50:55.116Z,1348073455.115 [Depth_Keller] Data Fault, FailCount= 1 2012-09-19T16:50:55.116Z,1348073455.116 [Depth_Keller](ERROR): Data Fault 2012-09-19T16:50:55.143Z,1348073455.143 [Radio_Freewave](INFO): Powering up 2012-09-19T16:50:55.249Z,1348073455.249 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:50:55.251Z,1348073455.251 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2012-09-19T16:50:55.257Z,1348073455.257 [ElevatorServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:50:55.259Z,1348073455.259 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2012-09-19T16:50:55.265Z,1348073455.265 [MassServo](DEBUG): Initializing MassServo. 2012-09-19T16:50:55.271Z,1348073455.271 [RudderServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:50:55.275Z,1348073455.275 [RudderServo](DEBUG): Initializing RudderServo. 2012-09-19T16:50:55.280Z,1348073455.280 [ThrusterServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:50:55.282Z,1348073455.282 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2012-09-19T16:50:55.301Z,1348073455.300 [CBIT](ERROR): Data Fault in component: Depth_Keller 2012-09-19T16:50:55.301Z,1348073455.301 [CBIT](INFO): Clearing failed state for component Depth_Keller 2012-09-19T16:50:55.301Z,1348073455.301 [Depth_Keller] No Fault, FailCount= 1 2012-09-19T16:50:56.215Z,1348073456.215 [DVL_micro](INFO): Querying output modes 2012-09-19T16:50:56.215Z,1348073456.215 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-09-19T16:50:56.219Z,1348073456.219 [DVL_micro](DEBUG): cmdResponse: 01 03 16 2012-09-19T16:50:56.219Z,1348073456.219 [DVL_micro](INFO): NQ1 output enabled 2012-09-19T16:50:56.219Z,1348073456.219 [DVL_micro](INFO): RSSI output enabled 2012-09-19T16:50:56.219Z,1348073456.219 [DVL_micro](INFO): ADCP output enabled 2012-09-19T16:50:56.220Z,1348073456.220 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-09-19T16:50:56.227Z,1348073456.227 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 2012-09-19T16:50:56.232Z,1348073456.232 [DVL_micro](INFO): pause:Powering down 2012-09-19T16:50:59.426Z,1348073459.425 [NAL9602](INFO): Powering up NAL9602 2012-09-19T16:51:00.417Z,1348073460.417 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2012-09-19T16:51:00.434Z,1348073460.434 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2012-09-19T16:51:00.487Z,1348073460.487 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2012-09-19T16:51:00.503Z,1348073460.503 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2012-09-19T16:51:00.523Z,1348073460.523 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2012-09-19T16:51:00.524Z,1348073460.524 [NavChartDb](INFO): Creating index for Soundings 2012-09-19T16:51:00.527Z,1348073460.527 [NavChartDb](INFO): Creating index for Contour 0p0 2012-09-19T16:51:00.529Z,1348073460.529 [NavChartDb](INFO): Creating index for Contour 1p8 2012-09-19T16:51:00.531Z,1348073460.531 [NavChartDb](INFO): Creating index for Contour 3p6 2012-09-19T16:51:00.533Z,1348073460.533 [NavChartDb](INFO): Creating index for Contour 5p4 2012-09-19T16:51:00.579Z,1348073460.579 [NavChartDb](INFO): Creating index for Contour 9p1 2012-09-19T16:51:00.581Z,1348073460.581 [NavChartDb](INFO): Creating index for Contour 10p9 2012-09-19T16:51:00.583Z,1348073460.583 [NavChartDb](INFO): Creating index for Contour 18p2 2012-09-19T16:51:00.585Z,1348073460.585 [NavChartDb](INFO): Creating index for Contour 36p5 2012-09-19T16:51:00.719Z,1348073460.719 [NavChartDb](INFO): Creating index for Contour 54p8 2012-09-19T16:51:00.721Z,1348073460.721 [NavChartDb](INFO): Creating index for Contour 73p1 2012-09-19T16:51:01.063Z,1348073461.063 [NavChartDb](INFO): Creating index for Contour 91p4 2012-09-19T16:51:01.065Z,1348073461.065 [NavChartDb](INFO): Creating index for Contour 182p8 2012-09-19T16:51:01.112Z,1348073461.112 [NavChartDb](INFO): Creating index for Contour 365p7 2012-09-19T16:51:01.114Z,1348073461.114 [NavChartDb](INFO): Creating index for Contour 548p6 2012-09-19T16:51:01.236Z,1348073461.237 [NavChartDb](INFO): Creating index for Contour 731p5 2012-09-19T16:51:01.461Z,1348073461.461 [NavChartDb](INFO): Creating index for Contour 914p4 2012-09-19T16:51:01.479Z,1348073461.479 [NavChartDb](INFO): Creating index for Contour 1097p2 2012-09-19T16:51:01.481Z,1348073461.481 [NavChartDb](INFO): Creating index for Contour 1280p1 2012-09-19T16:51:01.551Z,1348073461.551 [NavChartDb](INFO): Creating index for Contour 1463p0 2012-09-19T16:51:01.553Z,1348073461.553 [NavChartDb](INFO): Creating index for Contour 1645p9 2012-09-19T16:51:01.571Z,1348073461.571 [NavChartDb](INFO): Creating index for Contour 1828p8 2012-09-19T16:51:01.573Z,1348073461.573 [NavChartDb](INFO): Creating index for Contour 2011p6 2012-09-19T16:51:01.668Z,1348073461.668 [NavChartDb](INFO): Creating index for Contour 2194p5 2012-09-19T16:51:01.670Z,1348073461.670 [NavChartDb](INFO): Creating index for Contour 2377p4 2012-09-19T16:51:01.884Z,1348073461.884 [NavChartDb](INFO): Creating index for Contour 2560p3 2012-09-19T16:51:01.886Z,1348073461.886 [NavChartDb](INFO): Creating index for Contour 2743p2 2012-09-19T16:51:01.904Z,1348073461.904 [NavChartDb](INFO): Creating index for Contour 2926p0 2012-09-19T16:51:01.906Z,1348073461.906 [NavChartDb](INFO): Creating index for Contour 3108p9 2012-09-19T16:51:01.924Z,1348073461.924 [NavChartDb](INFO): Creating index for Contour 3291p8 2012-09-19T16:51:01.926Z,1348073461.926 [NavChartDb](INFO): Creating index for Contour 3474p7 2012-09-19T16:51:02.100Z,1348073462.100 [NavChartDb](INFO): Creating index for Contour 3657p6 2012-09-19T16:51:10.055Z,1348073470.055 [NAL9602](INFO): NAL9602 initialized 2012-09-19T16:51:10.447Z,1348073470.447 [SBIT](IMPORTANT): Beginning Startup BIT 2012-09-19T16:51:10.449Z,1348073470.450 [CBIT](IMPORTANT): Beginning GF scan 2012-09-19T16:51:12.471Z,1348073472.471 [ElevatorServo](FAULT): Overload Error 2012-09-19T16:51:12.471Z,1348073472.471 [ElevatorServo] Hardware Fault, FailCount= 1 2012-09-19T16:51:12.471Z,1348073472.471 [ElevatorServo](ERROR): Hardware Fault 2012-09-19T16:51:12.522Z,1348073472.522 [CBIT](ERROR): Hardware Fault in component: ElevatorServo 2012-09-19T16:51:12.845Z,1348073472.845 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2012-09-19T16:51:12.845Z,1348073472.845 [ElevatorServo](INFO): Powering down 2012-09-19T16:51:12.882Z,1348073472.882 [CBIT](INFO): Clearing failed state for component ElevatorServo 2012-09-19T16:51:12.882Z,1348073472.882 [ElevatorServo] No Fault, FailCount= 1 2012-09-19T16:51:13.644Z,1348073473.644 [ElevatorServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:51:13.764Z,1348073473.764 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened 2012-09-19T16:51:13.764Z,1348073473.764 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2012-09-19T16:51:16.025Z,1348073476.025 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2012-09-19T16:51:16.025Z,1348073476.025 [DropWeight] Hardware Fault, FailCount= 1 2012-09-19T16:51:16.025Z,1348073476.025 [DropWeight](ERROR): Hardware Fault 2012-09-19T16:51:16.067Z,1348073476.067 [CBIT](ERROR): Hardware Fault in component: DropWeight 2012-09-19T16:51:16.068Z,1348073476.068 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2012-09-19T16:51:18.467Z,1348073478.467 [ElevatorServo](FAULT): Overload Error 2012-09-19T16:51:18.467Z,1348073478.467 [ElevatorServo] Hardware Fault, FailCount= 2 2012-09-19T16:51:18.467Z,1348073478.467 [ElevatorServo](ERROR): Hardware Fault 2012-09-19T16:51:18.495Z,1348073478.496 [CBIT](ERROR): Hardware Fault in component: ElevatorServo 2012-09-19T16:51:18.843Z,1348073478.843 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2012-09-19T16:51:18.843Z,1348073478.843 [ElevatorServo](INFO): Powering down 2012-09-19T16:51:18.848Z,1348073478.848 [CBIT](INFO): Clearing failed state for component ElevatorServo 2012-09-19T16:51:18.848Z,1348073478.848 [ElevatorServo] No Fault, FailCount= 2 2012-09-19T16:51:19.643Z,1348073479.643 [ElevatorServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:51:19.764Z,1348073479.764 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened 2012-09-19T16:51:19.764Z,1348073479.764 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2012-09-19T16:51:23.670Z,1348073483.670 [SBIT](FAULT): Elevator: EXPECTED:15.000000 ACTUAL:0.015396 2012-09-19T16:51:24.467Z,1348073484.467 [ElevatorServo](FAULT): Overload Error 2012-09-19T16:51:24.467Z,1348073484.467 [ElevatorServo] Hardware Fault, FailCount= 3 2012-09-19T16:51:24.467Z,1348073484.467 [ElevatorServo](ERROR): Hardware Fault 2012-09-19T16:51:24.495Z,1348073484.495 [CBIT](ERROR): Hardware Fault in component: ElevatorServo 2012-09-19T16:51:24.496Z,1348073484.496 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo 2012-09-19T16:51:24.843Z,1348073484.843 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2012-09-19T16:51:24.843Z,1348073484.843 [ElevatorServo](INFO): Powering down 2012-09-19T16:51:36.849Z,1348073496.849 [CBIT](IMPORTANT): No ground fault detected 2012-09-19T16:52:04.447Z,1348073524.447 [SBIT](CRITICAL): SBIT FAILED 2012-09-19T16:52:04.845Z,1348073524.845 [MissionManager](IMPORTANT): Started mission Startup 2012-09-19T16:52:04.845Z,1348073524.845 [Startup] Running Loop=1 2012-09-19T16:52:04.846Z,1348073524.846 [Startup](INFO): Aggregate::initialize Startup 2012-09-19T16:52:04.846Z,1348073524.846 [Startup:A.GoToSurface] Running Loop=1 2012-09-19T16:52:04.846Z,1348073524.846 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:52:04.852Z,1348073524.852 [Startup:StartupSatComms] Running Loop=1 2012-09-19T16:52:04.852Z,1348073524.852 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2012-09-19T16:52:04.852Z,1348073524.852 [Startup:StartupSatComms:A] Running Loop=1 2012-09-19T16:52:05.239Z,1348073525.239 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-09-19T16:53:05.238Z,1348073585.238 [Startup:StartupSatComms:A](INFO): Timed out from 2012-09-19T16:52:04.9Z 2012-09-19T16:53:05.238Z,1348073585.238 [Startup:StartupSatComms:A_Timeout] Running Loop=1 2012-09-19T16:53:05.238Z,1348073585.238 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout 2012-09-19T16:53:05.239Z,1348073585.239 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout 2012-09-19T16:53:05.239Z,1348073585.239 [Startup:StartupSatComms:A] Stopped 2012-09-19T16:53:05.239Z,1348073585.239 [Startup:StartupSatComms:B] Running Loop=1 2012-09-19T16:53:05.638Z,1348073585.638 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-09-19T16:54:05.306Z,1348073645.306 [Startup:StartupSatComms:B](INFO): Timed out from 2012-09-19T16:53:05.2Z 2012-09-19T16:54:05.306Z,1348073645.306 [Startup:StartupSatComms:A_Timeout] Running Loop=1 2012-09-19T16:54:05.306Z,1348073645.306 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout 2012-09-19T16:54:05.307Z,1348073645.307 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout 2012-09-19T16:54:05.307Z,1348073645.307 [Startup:StartupSatComms:B] Stopped 2012-09-19T16:54:05.307Z,1348073645.307 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2012-09-19T16:54:05.307Z,1348073645.307 [Startup:StartupSatComms] Stopped 2012-09-19T16:54:05.307Z,1348073645.307 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2012-09-19T16:54:05.308Z,1348073645.308 [Startup](INFO): Completed Startup 2012-09-19T16:54:05.308Z,1348073645.308 [Startup] Stopped 2012-09-19T16:54:05.308Z,1348073645.308 [Startup](INFO): Aggregate::uninitialize Startup 2012-09-19T16:54:05.308Z,1348073645.308 [Startup:A.GoToSurface] Stopped 2012-09-19T16:54:05.308Z,1348073645.308 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T16:54:05.703Z,1348073645.704 [MissionManager](IMPORTANT): Started mission Default 2012-09-19T16:54:05.704Z,1348073645.704 [Default] Running Loop=1 2012-09-19T16:54:05.704Z,1348073645.704 [Default](INFO): Aggregate::initialize Default 2012-09-19T16:54:05.704Z,1348073645.704 [Default:D.SetSpeed] Running Loop=1 2012-09-19T16:54:05.704Z,1348073645.704 [Default:D.SetSpeed](DEBUG): Initialize. 2012-09-19T16:54:05.704Z,1348073645.704 [Default:E.GoToSurface] Running Loop=1 2012-09-19T16:54:05.704Z,1348073645.704 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:54:05.704Z,1348073645.704 [Default:Iridium] Running Loop=1 2012-09-19T16:54:05.705Z,1348073645.704 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2012-09-19T16:54:05.705Z,1348073645.705 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-09-19T16:54:05.705Z,1348073645.705 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2012-09-19T16:54:05.705Z,1348073645.705 [Default:Iridium:B.GoToSurface] Running Loop=1 2012-09-19T16:54:05.705Z,1348073645.705 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:54:05.705Z,1348073645.705 [Default:E.GoToSurface] Running Loop=1 2012-09-19T16:54:05.711Z,1348073645.711 [Default:D.SetSpeed] Running Loop=1 2012-09-19T16:54:05.716Z,1348073645.716 [Default:CallIridium] Running Loop=1 2012-09-19T16:54:05.716Z,1348073645.716 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2012-09-19T16:54:05.716Z,1348073645.716 [Default:CallIridium:A] Running Loop=1 2012-09-19T16:54:05.718Z,1348073645.718 [Default:CallIridium:A] Stopped 2012-09-19T16:54:05.718Z,1348073645.718 [Default:CallIridium:B] Running Loop=1 2012-09-19T16:54:05.718Z,1348073645.718 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2012-09-19T16:54:05.724Z,1348073645.724 [Default:Iridium:B.GoToSurface] Stopped 2012-09-19T16:54:05.724Z,1348073645.724 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T16:54:05.724Z,1348073645.724 [Default:Iridium:Read_Iridium] Running Loop=1 2012-09-19T16:54:05.725Z,1348073645.724 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-09-19T16:54:05.729Z,1348073645.729 [Default:GPS] Running Loop=1 2012-09-19T16:54:05.729Z,1348073645.730 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2012-09-19T16:54:05.730Z,1348073645.730 [Default:GPS:A.SetSpeed] Running Loop=1 2012-09-19T16:54:05.730Z,1348073645.730 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2012-09-19T16:54:05.730Z,1348073645.730 [Default:GPS:B.GoToSurface] Running Loop=1 2012-09-19T16:54:05.730Z,1348073645.730 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:54:05.735Z,1348073645.735 [Default:GPS:B.GoToSurface] Stopped 2012-09-19T16:54:05.735Z,1348073645.736 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T16:54:05.736Z,1348073645.736 [Default:GPS:Read_GPS] Running Loop=1 2012-09-19T16:54:05.736Z,1348073645.736 [Default:GPS:A.SetSpeed] Running Loop=1 2012-09-19T16:54:06.110Z,1348073646.110 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-09-19T16:54:06.113Z,1348073646.113 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-09-19T16:55:27.687Z,1348073727.687 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_1km.xml 2012-09-19T16:55:27.687Z,1348073727.687 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_1km.xml 2012-09-19T16:55:27.701Z,1348073727.701 [MissionManager](INFO): Inserting Stack: Missions/Transport/transit.xml 2012-09-19T16:55:27.768Z,1348073727.768 [MissionManager](INFO): DefineArg transit_1km:transit.Depth = 10.000000 m 2012-09-19T16:55:27.771Z,1348073727.771 [MissionManager](INFO): DefineArg transit_1km:transit.MaxDepth = 20.000000 m 2012-09-19T16:55:27.774Z,1348073727.774 [MissionManager](INFO): DefineArg transit_1km:transit.Wpt1Lat = nan arcdeg 2012-09-19T16:55:27.777Z,1348073727.777 [MissionManager](INFO): DefineArg transit_1km:transit.Wpt1Lon = nan arcdeg 2012-09-19T16:55:27.780Z,1348073727.780 [MissionManager](INFO): DefineArg transit_1km:transit.Northings = 0.000000 m 2012-09-19T16:55:27.783Z,1348073727.783 [MissionManager](INFO): DefineArg transit_1km:transit.Eastings = 0.000000 m 2012-09-19T16:55:27.786Z,1348073727.786 [MissionManager](INFO): DefineArg transit_1km:transit.Speed = 1.000000 m/s 2012-09-19T16:55:27.789Z,1348073727.789 [MissionManager](INFO): DefineArg transit_1km:transit.MassHold = 1 bool 2012-09-19T16:55:27.792Z,1348073727.792 [MissionManager](INFO): DefineArg transit_1km:transit.BuoyancyHold = 1 bool 2012-09-19T16:55:27.795Z,1348073727.795 [MissionManager](INFO): DefineArg transit_1km:transit.BuoyancyNeutral = 0.000330 n/a 2012-09-19T16:55:27.799Z,1348073727.799 [MissionManager](INFO): DefineArg transit_1km:transit.MassDefault = 0.000000 n/a 2012-09-19T16:55:27.802Z,1348073727.802 [MissionManager](INFO): DefineArg transit_1km:transit.MinOffshore = 1.000000 km 2012-09-19T16:55:27.805Z,1348073727.805 [MissionManager](INFO): DefineArg transit_1km:transit.NeedCommsTime = 30.000000 min 2012-09-19T16:55:27.808Z,1348073727.808 [MissionManager](INFO): DefineArg transit_1km:transit.MinAltitude = 7.000000 m 2012-09-19T16:55:27.811Z,1348073727.811 [MissionManager](INFO): DefineArg transit_1km:transit.TimeoutDuration = 240.000000 min 2012-09-19T16:55:27.813Z,1348073727.813 [transit_1km:transit:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope. 2012-09-19T16:55:27.821Z,1348073727.821 [transit_1km:transit:B.DepthEnvelope](DEBUG): Construct DepthEnvelope. 2012-09-19T16:55:27.830Z,1348073727.830 [transit_1km:transit:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope. 2012-09-19T16:55:27.838Z,1348073727.838 [transit_1km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T16:55:27.844Z,1348073727.844 [transit_1km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct. 2012-09-19T16:55:27.855Z,1348073727.855 [transit_1km:transit:BuoyancyHold.Buoyancy](DEBUG): Construct Buoyancy. 2012-09-19T16:55:27.859Z,1348073727.859 [transit_1km:transit:MassHold.Pitch](DEBUG): Construct. 2012-09-19T16:55:27.865Z,1348073727.865 [transit_1km:transit:WaypointOne:A.Pitch](DEBUG): Construct. 2012-09-19T16:55:27.871Z,1348073727.871 [transit_1km:transit:WaypointOne:B.SetSpeed](DEBUG): Construct. 2012-09-19T16:55:27.874Z,1348073727.874 [transit_1km:transit:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint. 2012-09-19T16:55:27.882Z,1348073727.882 [MissionManager](INFO): RedefineArg transit_1km:transit.Wpt1Lat = 36.815600 arcdeg 2012-09-19T16:55:27.883Z,1348073727.883 [MissionManager](INFO): RedefineArg transit_1km:transit.Wpt1Lon = -121.806000 arcdeg 2012-09-19T16:55:27.885Z,1348073727.885 [MissionManager](INFO): RedefineArg transit_1km:transit.TimeoutDuration = 90.000000 min 2012-09-19T16:55:27.887Z,1348073727.887 [MissionManager](INFO): RedefineArg transit_1km:transit.MinOffshore = 300.000000 m 2012-09-19T16:55:27.894Z,1348073727.894 [MissionManager](DEBUG): Vehicle transits to the 1km waypoint and can be commanded to use/hold mass or buoyancy. 36.8156 -121.806 90 300 2012-09-19T16:55:27.894Z,1348073727.894 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_1km.xml 2012-09-19T16:55:28.139Z,1348073728.139 [Default] Stopped 2012-09-19T16:55:28.140Z,1348073728.139 [Default](INFO): Aggregate::uninitialize Default 2012-09-19T16:55:28.140Z,1348073728.140 [Default:GPS] Stopped 2012-09-19T16:55:28.140Z,1348073728.140 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2012-09-19T16:55:28.140Z,1348073728.140 [Default:GPS:A.SetSpeed] Stopped 2012-09-19T16:55:28.140Z,1348073728.140 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2012-09-19T16:55:28.140Z,1348073728.140 [Default:GPS:Read_GPS] Stopped 2012-09-19T16:55:28.140Z,1348073728.140 [Default:Iridium] Stopped 2012-09-19T16:55:28.140Z,1348073728.140 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2012-09-19T16:55:28.140Z,1348073728.140 [Default:Iridium:A.SetSpeed] Stopped 2012-09-19T16:55:28.140Z,1348073728.140 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2012-09-19T16:55:28.140Z,1348073728.140 [Default:Iridium:Read_Iridium] Stopped 2012-09-19T16:55:28.140Z,1348073728.140 [Default:CallIridium] Stopped 2012-09-19T16:55:28.140Z,1348073728.141 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2012-09-19T16:55:28.141Z,1348073728.141 [Default:CallIridium:B] Stopped 2012-09-19T16:55:28.141Z,1348073728.141 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B 2012-09-19T16:55:28.141Z,1348073728.141 [Default:D.SetSpeed] Stopped 2012-09-19T16:55:28.141Z,1348073728.141 [Default:D.SetSpeed](DEBUG): Uninitialize. 2012-09-19T16:55:28.141Z,1348073728.141 [Default:E.GoToSurface] Stopped 2012-09-19T16:55:28.141Z,1348073728.141 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T16:55:28.141Z,1348073728.141 [MissionManager](IMPORTANT): Started mission transit_1km 2012-09-19T16:55:28.141Z,1348073728.141 [transit_1km] Running Loop=1 2012-09-19T16:55:28.141Z,1348073728.141 [transit_1km](INFO): Aggregate::initialize transit_1km 2012-09-19T16:55:28.142Z,1348073728.142 [transit_1km:transit] Running Loop=1 2012-09-19T16:55:28.142Z,1348073728.142 [transit_1km:transit](INFO): Aggregate::initialize transit_1km:transit 2012-09-19T16:55:28.142Z,1348073728.142 [transit_1km:transit:A.AltitudeEnvelope] Running Loop=1 2012-09-19T16:55:28.142Z,1348073728.142 [transit_1km:transit:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent. 2012-09-19T16:55:28.142Z,1348073728.142 [transit_1km:transit:B.DepthEnvelope] Running Loop=1 2012-09-19T16:55:28.142Z,1348073728.142 [transit_1km:transit:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent. 2012-09-19T16:55:28.143Z,1348073728.143 [transit_1km:transit:C.OffshoreEnvelope] Running Loop=1 2012-09-19T16:55:28.143Z,1348073728.143 [transit_1km:transit:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent. 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:BuoyancyHold.Buoyancy] Running Loop=1 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:BuoyancyHold.Buoyancy](DEBUG): Initialize Buoyancy Component. 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:MassHold.Pitch] Running Loop=1 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:MassHold.Pitch](DEBUG): Initialize. 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:SURFACECOMMS] Running Loop=1 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:SURFACECOMMS](INFO): Aggregate::initialize transit_1km:transit:SURFACECOMMS 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:SURFACECOMMS:A.GoToSurface] Running Loop=1 2012-09-19T16:55:28.144Z,1348073728.144 [transit_1km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:55:28.145Z,1348073728.145 [transit_1km:transit:MassHold.Pitch] Running Loop=1 2012-09-19T16:55:28.149Z,1348073728.149 [transit_1km:transit:BuoyancyHold.Buoyancy] Running Loop=1 2012-09-19T16:55:28.154Z,1348073728.154 [transit_1km:transit:NeedComms] Running Loop=1 2012-09-19T16:55:28.154Z,1348073728.154 [transit_1km:transit:NeedComms](INFO): Aggregate::initialize transit_1km:transit:NeedComms 2012-09-19T16:55:28.155Z,1348073728.155 [transit_1km:transit:NeedComms:NEEDCOMMS] Running Loop=1 2012-09-19T16:55:28.155Z,1348073728.155 [transit_1km:transit:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_1km:transit:NeedComms:NEEDCOMMS 2012-09-19T16:55:28.160Z,1348073728.160 [transit_1km:transit:SURFACECOMMS:B] Running Loop=1 2012-09-19T16:55:28.160Z,1348073728.160 [transit_1km:transit:SURFACECOMMS:B](INFO): Aggregate::initialize transit_1km:transit:SURFACECOMMS:B 2012-09-19T16:55:28.160Z,1348073728.160 [transit_1km:transit:SURFACECOMMS:B:A.SetSpeed] Running Loop=1 2012-09-19T16:55:28.160Z,1348073728.160 [transit_1km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize. 2012-09-19T16:55:28.160Z,1348073728.160 [transit_1km:transit:SURFACECOMMS:B:B] Running Loop=1 2012-09-19T16:55:28.160Z,1348073728.160 [transit_1km:transit:C.OffshoreEnvelope] Running Loop=1 2012-09-19T16:55:28.160Z,1348073728.160 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:28.165Z,1348073728.165 [transit_1km:transit:B.DepthEnvelope] Running Loop=1 2012-09-19T16:55:28.170Z,1348073728.170 [transit_1km:transit:A.AltitudeEnvelope] Running Loop=1 2012-09-19T16:55:28.307Z,1348073728.307 [DVL_micro](INFO): RSSI unrequested 2012-09-19T16:55:28.307Z,1348073728.307 [DVL_micro](INFO): ADCP unrequested 2012-09-19T16:55:28.308Z,1348073728.308 [DVL_micro](INFO): resume:Powering up 2012-09-19T16:55:28.846Z,1348073728.846 [transit_1km:transit:MassHold.Pitch] Preempted 2012-09-19T16:55:28.846Z,1348073728.846 [transit_1km:transit:BuoyancyHold.Buoyancy] Preempted 2012-09-19T16:55:28.847Z,1348073728.847 [transit_1km:transit:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-09-19T16:55:28.848Z,1348073728.848 [transit_1km:transit:SURFACECOMMS:B:A.SetSpeed] Running Loop=1 2012-09-19T16:55:28.854Z,1348073728.853 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:29.239Z,1348073729.239 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:29.639Z,1348073729.639 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:29.815Z,1348073729.815 [DVL_micro](INFO): Querying output modes 2012-09-19T16:55:29.815Z,1348073729.815 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-09-19T16:55:29.823Z,1348073729.823 [DVL_micro](DEBUG): cmdResponse: 01 03 16 2012-09-19T16:55:29.823Z,1348073729.823 [DVL_micro](INFO): NQ1 output enabled 2012-09-19T16:55:29.823Z,1348073729.823 [DVL_micro](INFO): RSSI output enabled 2012-09-19T16:55:29.823Z,1348073729.823 [DVL_micro](INFO): ADCP output enabled 2012-09-19T16:55:29.823Z,1348073729.823 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-09-19T16:55:29.831Z,1348073729.831 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 2012-09-19T16:55:29.832Z,1348073729.832 [DVL_micro](INFO): RSSI unrequested 2012-09-19T16:55:29.833Z,1348073729.833 [DVL_micro](INFO): ADCP unrequested 2012-09-19T16:55:30.040Z,1348073730.040 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:30.041Z,1348073730.041 [transit_1km:transit:A.AltitudeEnvelope](ERROR): Altitude Measurement is not Active. 2012-09-19T16:55:30.441Z,1348073730.441 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:30.847Z,1348073730.847 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:31.239Z,1348073731.239 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:31.671Z,1348073731.671 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:32.065Z,1348073732.065 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:32.471Z,1348073732.471 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:32.862Z,1348073732.862 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:33.261Z,1348073733.261 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:33.665Z,1348073733.665 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:34.073Z,1348073734.073 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:34.465Z,1348073734.465 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:34.866Z,1348073734.866 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:35.265Z,1348073735.265 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:35.665Z,1348073735.665 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:36.071Z,1348073736.071 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:36.484Z,1348073736.484 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:36.865Z,1348073736.865 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:37.263Z,1348073737.263 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:37.661Z,1348073737.661 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:38.073Z,1348073738.073 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:38.470Z,1348073738.470 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:38.866Z,1348073738.866 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:39.262Z,1348073739.261 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:39.666Z,1348073739.666 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:40.084Z,1348073740.084 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:40.461Z,1348073740.461 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:40.870Z,1348073740.870 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:41.265Z,1348073741.265 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:41.669Z,1348073741.670 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:42.066Z,1348073742.066 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:42.465Z,1348073742.465 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:42.865Z,1348073742.865 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:43.265Z,1348073743.265 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:43.698Z,1348073743.698 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:44.087Z,1348073744.087 [transit_1km:transit:C.OffshoreEnvelope](ERROR): Location Measurement is not Active. 2012-09-19T16:55:44.226Z,1348073744.226 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree 2012-09-19T16:55:44.231Z,1348073744.231 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree 2012-09-19T16:55:44.479Z,1348073744.479 [transit_1km:transit:SURFACECOMMS:B:B] Stopped 2012-09-19T16:55:44.479Z,1348073744.480 [transit_1km:transit:SURFACECOMMS:B:C] Running Loop=1 2012-09-19T16:55:44.503Z,1348073744.503 [NavChartDb](INFO): Charting Soundings 2012-09-19T16:55:44.680Z,1348073744.680 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2012-09-19T16:55:45.318Z,1348073745.318 [transit_1km:transit:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-09-19T16:55:45.320Z,1348073745.320 [transit_1km:transit:SURFACECOMMS:B:C] Stopped 2012-09-19T16:55:45.320Z,1348073745.320 [transit_1km:transit:SURFACECOMMS:B:D] Running Loop=1 2012-09-19T16:55:45.799Z,1348073745.799 [transit_1km:transit:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-09-19T16:55:53.231Z,1348073753.231 [CommandLine](IMPORTANT): got command show stack 2012-09-19T16:55:53.231Z,1348073753.231 [CommandLine](INFO): Behavior Stack: 2012-09-19T16:55:53.232Z,1348073753.232 [transit_1km:transit](INFO): Priority 0: transit_1km:transit:A.AltitudeEnvelope 2012-09-19T16:55:53.232Z,1348073753.232 [transit_1km:transit](INFO): Priority 1: transit_1km:transit:B.DepthEnvelope 2012-09-19T16:55:53.232Z,1348073753.232 [transit_1km:transit](INFO): Priority 2: transit_1km:transit:C.OffshoreEnvelope 2012-09-19T16:55:53.233Z,1348073753.233 [transit_1km:transit:SURFACECOMMS](INFO): Priority 3: transit_1km:transit:SURFACECOMMS:A.GoToSurface 2012-09-19T16:55:53.233Z,1348073753.233 [transit_1km:transit:SURFACECOMMS:B](INFO): Priority 4: transit_1km:transit:SURFACECOMMS:B:A.SetSpeed 2012-09-19T16:55:53.233Z,1348073753.233 [transit_1km:transit:SURFACECOMMS:B](INFO): Priority 5: transit_1km:transit:SURFACECOMMS:B:D 2012-09-19T16:56:16.079Z,1348073776.079 [CommandLine](IMPORTANT): got command get depth 2012-09-19T16:56:16.080Z,1348073776.080 [CommandLine](IMPORTANT): depth -0.013388 meter 2012-09-19T16:56:16.144Z,1348073776.144 [CBIT](INFO): Clearing failed count for component DropWeight 2012-09-19T16:56:16.144Z,1348073776.144 [DropWeight] No Fault, FailCount= 1 2012-09-19T16:56:18.683Z,1348073778.683 [NavChartDb](INFO): Charting 0p0 2012-09-19T16:56:39.583Z,1348073799.583 [CommandLine](IMPORTANT): got command show stack 2012-09-19T16:56:39.583Z,1348073799.583 [CommandLine](INFO): Behavior Stack: 2012-09-19T16:56:39.584Z,1348073799.584 [transit_1km:transit](INFO): Priority 0: transit_1km:transit:A.AltitudeEnvelope 2012-09-19T16:56:39.584Z,1348073799.584 [transit_1km:transit](INFO): Priority 1: transit_1km:transit:B.DepthEnvelope 2012-09-19T16:56:39.584Z,1348073799.584 [transit_1km:transit](INFO): Priority 2: transit_1km:transit:C.OffshoreEnvelope 2012-09-19T16:56:39.585Z,1348073799.585 [transit_1km:transit:SURFACECOMMS](INFO): Priority 3: transit_1km:transit:SURFACECOMMS:A.GoToSurface 2012-09-19T16:56:39.585Z,1348073799.585 [transit_1km:transit:SURFACECOMMS:B](INFO): Priority 4: transit_1km:transit:SURFACECOMMS:B:A.SetSpeed 2012-09-19T16:56:39.585Z,1348073799.585 [transit_1km:transit:SURFACECOMMS:B](INFO): Priority 5: transit_1km:transit:SURFACECOMMS:B:D 2012-09-19T16:56:57.571Z,1348073817.571 [CommandLine](IMPORTANT): got command get platform_propeller_rotation_rate 2012-09-19T16:56:57.572Z,1348073817.572 [CommandLine](IMPORTANT): platform_propeller_rotation_rate 0.000000 radian_per_second 2012-09-19T16:57:19.081Z,1348073839.081 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree 2012-09-19T16:57:19.082Z,1348073839.082 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree 2012-09-19T16:57:19.114Z,1348073839.114 [transit_1km:transit:SURFACECOMMS:B:D] Stopped 2012-09-19T16:57:19.114Z,1348073839.114 [transit_1km:transit:SURFACECOMMS:B](INFO): Completed transit_1km:transit:SURFACECOMMS:B 2012-09-19T16:57:19.114Z,1348073839.114 [transit_1km:transit:SURFACECOMMS:B] Stopped 2012-09-19T16:57:19.114Z,1348073839.114 [transit_1km:transit:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_1km:transit:SURFACECOMMS:B 2012-09-19T16:57:19.114Z,1348073839.114 [transit_1km:transit:SURFACECOMMS:B:A.SetSpeed] Stopped 2012-09-19T16:57:19.123Z,1348073839.122 [transit_1km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize. 2012-09-19T16:57:19.123Z,1348073839.123 [transit_1km:transit:SURFACECOMMS](INFO): Completed transit_1km:transit:SURFACECOMMS 2012-09-19T16:57:19.123Z,1348073839.124 [transit_1km:transit:SURFACECOMMS] Stopped 2012-09-19T16:57:19.124Z,1348073839.124 [transit_1km:transit:SURFACECOMMS](INFO): Aggregate::uninitialize transit_1km:transit:SURFACECOMMS 2012-09-19T16:57:19.124Z,1348073839.124 [transit_1km:transit:SURFACECOMMS:A.GoToSurface] Stopped 2012-09-19T16:57:19.124Z,1348073839.124 [transit_1km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T16:57:19.124Z,1348073839.124 [transit_1km:transit:WaypointOne] Running Loop=1 2012-09-19T16:57:19.124Z,1348073839.124 [transit_1km:transit:WaypointOne](INFO): Aggregate::initialize transit_1km:transit:WaypointOne 2012-09-19T16:57:19.124Z,1348073839.124 [transit_1km:transit:WaypointOne:A.Pitch] Running Loop=1 2012-09-19T16:57:19.124Z,1348073839.124 [transit_1km:transit:WaypointOne:A.Pitch](DEBUG): Initialize. 2012-09-19T16:57:19.124Z,1348073839.125 [transit_1km:transit:WaypointOne:B.SetSpeed] Running Loop=1 2012-09-19T16:57:19.125Z,1348073839.125 [transit_1km:transit:WaypointOne:B.SetSpeed](DEBUG): Initialize. 2012-09-19T16:57:19.125Z,1348073839.125 [transit_1km:transit:WaypointOne:WaypointW1.Waypoint] Running Loop=1 2012-09-19T16:57:19.125Z,1348073839.125 [transit_1km:transit:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent. 2012-09-19T16:57:19.516Z,1348073839.516 [transit_1km:transit:WaypointOne:B.SetSpeed] Running Loop=1 2012-09-19T16:57:19.529Z,1348073839.529 [transit_1km:transit:WaypointOne:A.Pitch] Running Loop=1 2012-09-19T16:57:19.542Z,1348073839.542 [transit_1km:transit:MassHold.Pitch] Running Loop=1 2012-09-19T16:57:19.542Z,1348073839.542 [transit_1km:transit:BuoyancyHold.Buoyancy] Running Loop=1 2012-09-19T16:57:19.551Z,1348073839.551 [transit_1km:transit:NeedComms:NEEDCOMMS](INFO): Completed transit_1km:transit:NeedComms:NEEDCOMMS 2012-09-19T16:57:19.551Z,1348073839.551 [transit_1km:transit:NeedComms:NEEDCOMMS] Stopped 2012-09-19T16:57:19.551Z,1348073839.551 [transit_1km:transit:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_1km:transit:NeedComms:NEEDCOMMS 2012-09-19T16:57:19.552Z,1348073839.552 [transit_1km:transit:NeedComms](INFO): Completed transit_1km:transit:NeedComms 2012-09-19T16:57:19.552Z,1348073839.552 [transit_1km:transit:NeedComms] Stopped 2012-09-19T16:57:19.552Z,1348073839.552 [transit_1km:transit:NeedComms](INFO): Aggregate::uninitialize transit_1km:transit:NeedComms 2012-09-19T16:57:19.571Z,1348073839.571 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2012-09-19T16:57:21.627Z,1348073841.627 [RudderServo](ERROR): getPosition uart error serial timeout 2012-09-19T16:57:21.627Z,1348073841.627 [RudderServo](FAULT): Rudder uart error - getPosition..serial timeout 2012-09-19T16:57:21.627Z,1348073841.627 [RudderServo] Communications Fault, FailCount= 1 2012-09-19T16:57:21.627Z,1348073841.627 [RudderServo](ERROR): Communications Fault 2012-09-19T16:57:21.630Z,1348073841.630 [CBIT](ERROR): Communications Fault in component: RudderServo 2012-09-19T16:57:22.124Z,1348073842.124 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2012-09-19T16:57:22.124Z,1348073842.124 [RudderServo](INFO): Powering down 2012-09-19T16:57:22.145Z,1348073842.145 [CBIT](INFO): Clearing failed state for component RudderServo 2012-09-19T16:57:22.146Z,1348073842.145 [RudderServo] No Fault, FailCount= 1 2012-09-19T16:57:23.804Z,1348073843.804 [RudderServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:57:24.511Z,1348073844.511 [RudderServo](DEBUG): Initialization error opening port: port not yet opened 2012-09-19T16:57:24.511Z,1348073844.511 [RudderServo](DEBUG): Initializing RudderServo. 2012-09-19T16:57:25.082Z,1348073845.082 [NAL9602](INFO): Powering down 2012-09-19T16:57:34.715Z,1348073854.715 [CommandLine](IMPORTANT): got command show stack 2012-09-19T16:57:34.715Z,1348073854.715 [CommandLine](INFO): Behavior Stack: 2012-09-19T16:57:34.716Z,1348073854.716 [transit_1km:transit](INFO): Priority 0: transit_1km:transit:A.AltitudeEnvelope 2012-09-19T16:57:34.716Z,1348073854.716 [transit_1km:transit](INFO): Priority 1: transit_1km:transit:B.DepthEnvelope 2012-09-19T16:57:34.716Z,1348073854.717 [transit_1km:transit](INFO): Priority 2: transit_1km:transit:C.OffshoreEnvelope 2012-09-19T16:57:34.717Z,1348073854.717 [transit_1km:transit](INFO): Priority 3: transit_1km:transit:BuoyancyHold.Buoyancy 2012-09-19T16:57:34.717Z,1348073854.717 [transit_1km:transit](INFO): Priority 4: transit_1km:transit:MassHold.Pitch 2012-09-19T16:57:34.717Z,1348073854.717 [transit_1km:transit:WaypointOne](INFO): Priority 5: transit_1km:transit:WaypointOne:A.Pitch 2012-09-19T16:57:34.718Z,1348073854.718 [transit_1km:transit:WaypointOne](INFO): Priority 6: transit_1km:transit:WaypointOne:B.SetSpeed 2012-09-19T16:57:34.718Z,1348073854.718 [transit_1km:transit:WaypointOne](INFO): Priority 7: transit_1km:transit:WaypointOne:WaypointW1.Waypoint 2012-09-19T16:57:41.687Z,1348073861.687 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2012-09-19T16:57:44.843Z,1348073864.843 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2012-09-19T16:57:59.627Z,1348073879.627 [CommandLine](IMPORTANT): got command get platform_propeller_rotation_rate 2012-09-19T16:57:59.628Z,1348073879.628 [CommandLine](IMPORTANT): platform_propeller_rotation_rate 0.000000 radian_per_second 2012-09-19T16:58:06.507Z,1348073886.507 [CommandLine](IMPORTANT): got command show stack 2012-09-19T16:58:06.507Z,1348073886.507 [CommandLine](INFO): Behavior Stack: 2012-09-19T16:58:06.508Z,1348073886.508 [transit_1km:transit](INFO): Priority 0: transit_1km:transit:A.AltitudeEnvelope 2012-09-19T16:58:06.508Z,1348073886.508 [transit_1km:transit](INFO): Priority 1: transit_1km:transit:B.DepthEnvelope 2012-09-19T16:58:06.508Z,1348073886.508 [transit_1km:transit](INFO): Priority 2: transit_1km:transit:C.OffshoreEnvelope 2012-09-19T16:58:06.509Z,1348073886.509 [transit_1km:transit](INFO): Priority 3: transit_1km:transit:BuoyancyHold.Buoyancy 2012-09-19T16:58:06.509Z,1348073886.509 [transit_1km:transit](INFO): Priority 4: transit_1km:transit:MassHold.Pitch 2012-09-19T16:58:06.509Z,1348073886.509 [transit_1km:transit:WaypointOne](INFO): Priority 5: transit_1km:transit:WaypointOne:A.Pitch 2012-09-19T16:58:06.510Z,1348073886.510 [transit_1km:transit:WaypointOne](INFO): Priority 6: transit_1km:transit:WaypointOne:B.SetSpeed 2012-09-19T16:58:06.510Z,1348073886.510 [transit_1km:transit:WaypointOne](INFO): Priority 7: transit_1km:transit:WaypointOne:WaypointW1.Waypoint 2012-09-19T16:58:40.299Z,1348073920.299 [CommandLine](IMPORTANT): got command stop 2012-09-19T16:58:40.300Z,1348073920.300 [transit_1km] Stopped 2012-09-19T16:58:40.300Z,1348073920.300 [transit_1km](INFO): Aggregate::uninitialize transit_1km 2012-09-19T16:58:40.301Z,1348073920.300 [transit_1km:transit] Stopped 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit](INFO): Aggregate::uninitialize transit_1km:transit 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:A.AltitudeEnvelope] Stopped 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent. 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:B.DepthEnvelope] Stopped 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:B.DepthEnvelope](DEBUG): Uninitialize. 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:C.OffshoreEnvelope] Stopped 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent. 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:BuoyancyHold.Buoyancy] Stopped 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:BuoyancyHold.Buoyancy](DEBUG): Uninitialize Buoyancy Component. 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:MassHold.Pitch] Stopped 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:WaypointOne] Stopped 2012-09-19T16:58:40.301Z,1348073920.301 [transit_1km:transit:WaypointOne](INFO): Aggregate::uninitialize transit_1km:transit:WaypointOne 2012-09-19T16:58:40.301Z,1348073920.302 [transit_1km:transit:WaypointOne:A.Pitch] Stopped 2012-09-19T16:58:40.302Z,1348073920.302 [transit_1km:transit:WaypointOne:B.SetSpeed] Stopped 2012-09-19T16:58:40.302Z,1348073920.302 [transit_1km:transit:WaypointOne:B.SetSpeed](DEBUG): Uninitialize. 2012-09-19T16:58:40.302Z,1348073920.302 [transit_1km:transit:WaypointOne:WaypointW1.Waypoint] Stopped 2012-09-19T16:58:40.302Z,1348073920.302 [transit_1km:transit:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent. 2012-09-19T16:58:40.849Z,1348073920.849 [MissionManager](IMPORTANT): Started mission Default 2012-09-19T16:58:40.849Z,1348073920.849 [Default] Running Loop=1 2012-09-19T16:58:40.849Z,1348073920.849 [Default](INFO): Aggregate::initialize Default 2012-09-19T16:58:40.850Z,1348073920.849 [Default:D.SetSpeed] Running Loop=1 2012-09-19T16:58:40.850Z,1348073920.849 [Default:D.SetSpeed](DEBUG): Initialize. 2012-09-19T16:58:40.850Z,1348073920.850 [Default:E.GoToSurface] Running Loop=1 2012-09-19T16:58:40.850Z,1348073920.850 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:58:40.850Z,1348073920.850 [Default:Iridium] Running Loop=1 2012-09-19T16:58:40.850Z,1348073920.850 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2012-09-19T16:58:40.850Z,1348073920.850 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-09-19T16:58:40.850Z,1348073920.850 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2012-09-19T16:58:40.854Z,1348073920.855 [Default:Iridium:B.GoToSurface] Running Loop=1 2012-09-19T16:58:40.855Z,1348073920.855 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:58:40.857Z,1348073920.856 [Default:Iridium:B.GoToSurface] Stopped 2012-09-19T16:58:40.857Z,1348073920.857 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T16:58:40.857Z,1348073920.857 [Default:Iridium:Read_Iridium] Running Loop=1 2012-09-19T16:58:40.857Z,1348073920.857 [Default:GPS] Running Loop=1 2012-09-19T16:58:40.857Z,1348073920.857 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2012-09-19T16:58:40.857Z,1348073920.857 [Default:GPS:A.SetSpeed] Running Loop=1 2012-09-19T16:58:40.857Z,1348073920.857 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2012-09-19T16:58:40.858Z,1348073920.858 [Default:GPS:B.GoToSurface] Running Loop=1 2012-09-19T16:58:40.858Z,1348073920.858 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T16:58:40.858Z,1348073920.858 [Default:GPS:B.GoToSurface] Stopped 2012-09-19T16:58:40.863Z,1348073920.863 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T16:58:40.863Z,1348073920.863 [Default:GPS:Read_GPS] Running Loop=1 2012-09-19T16:58:42.366Z,1348073922.366 [NAL9602](INFO): Powering up 2012-09-19T16:58:43.567Z,1348073923.567 [RudderServo](FAULT): Rudder uart error: serial timeout 2012-09-19T16:58:43.567Z,1348073923.567 [RudderServo] Communications Fault, FailCount= 1 2012-09-19T16:58:43.567Z,1348073923.567 [RudderServo](ERROR): Communications Fault 2012-09-19T16:58:43.570Z,1348073923.570 [CBIT](ERROR): Communications Fault in component: RudderServo 2012-09-19T16:58:44.008Z,1348073924.008 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2012-09-19T16:58:44.008Z,1348073924.008 [RudderServo](INFO): Powering down 2012-09-19T16:58:44.015Z,1348073924.015 [CBIT](INFO): Clearing failed state for component RudderServo 2012-09-19T16:58:44.015Z,1348073924.015 [RudderServo] No Fault, FailCount= 1 2012-09-19T16:58:44.964Z,1348073924.964 [RudderServo](DEBUG): Initializing EZServoServo. 2012-09-19T16:58:45.336Z,1348073925.336 [RudderServo](DEBUG): Initialization error opening port: port not yet opened 2012-09-19T16:58:45.336Z,1348073925.336 [RudderServo](DEBUG): Initializing RudderServo. 2012-09-19T16:58:53.279Z,1348073933.279 [NAL9602](INFO): NAL9602 initialized 2012-09-19T17:00:23.895Z,1348074023.895 [CommandLine](IMPORTANT): got command quit 2012-09-19T17:00:24.959Z,1348074024.958 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2012-09-19T17:00:24.959Z,1348074024.959 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler