2012-09-19T14:56:48.488Z,1348066608.489 [Supervisor](DEBUG): Initializing supervisor. 2012-09-19T14:56:48.492Z,1348066608.492 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0 2012-09-19T14:56:48.493Z,1348066608.493 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2012-09-19T14:56:48.493Z,1348066608.493 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0 2012-09-19T14:56:48.497Z,1348066608.497 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2012-09-19T14:56:48.509Z,1348066608.509 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2012-09-19T14:56:48.510Z,1348066608.510 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0 2012-09-19T14:56:48.511Z,1348066608.511 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread. 2012-09-19T14:56:48.512Z,1348066608.512 [Supervisor](INFO): Looking for Config files in directory: Config/ 2012-09-19T14:56:48.513Z,1348066608.513 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2012-09-19T14:56:48.793Z,1348066608.793 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2012-09-19T14:56:48.794Z,1348066608.794 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2012-09-19T14:56:48.973Z,1348066608.973 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2012-09-19T14:56:48.973Z,1348066608.973 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2012-09-19T14:56:49.098Z,1348066609.098 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2012-09-19T14:56:49.099Z,1348066609.099 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2012-09-19T14:56:49.294Z,1348066609.295 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2012-09-19T14:56:49.295Z,1348066609.295 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2012-09-19T14:56:49.432Z,1348066609.432 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2012-09-19T14:56:49.433Z,1348066609.433 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2012-09-19T14:56:49.665Z,1348066609.665 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2012-09-19T14:56:49.666Z,1348066609.666 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2012-09-19T14:56:49.835Z,1348066609.835 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2012-09-19T14:56:49.836Z,1348066609.836 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2012-09-19T14:56:50.089Z,1348066610.089 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2012-09-19T14:56:50.090Z,1348066610.090 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2012-09-19T14:56:50.188Z,1348066610.188 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2012-09-19T14:56:50.189Z,1348066610.189 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2012-09-19T14:56:50.678Z,1348066610.678 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2012-09-19T14:56:50.679Z,1348066610.679 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2012-09-19T14:56:50.793Z,1348066610.793 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2012-09-19T14:56:50.794Z,1348066610.793 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2012-09-19T14:56:50.878Z,1348066610.878 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2012-09-19T14:56:50.879Z,1348066610.879 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2012-09-19T14:56:50.980Z,1348066610.980 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2012-09-19T14:56:51.108Z,1348066611.109 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2012-09-19T14:56:51.194Z,1348066611.194 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2012-09-19T14:56:51.296Z,1348066611.296 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2012-09-19T14:56:51.396Z,1348066611.395 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2012-09-19T14:56:51.514Z,1348066611.514 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2012-09-19T14:56:51.603Z,1348066611.603 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2012-09-19T14:56:51.696Z,1348066611.696 [Supervisor](IMPORTANT): Reading configuration overrides from Data/config.db 2012-09-19T14:56:51.708Z,1348066611.708 [ComponentRegistry](DEBUG): Loaded Config Component "configDb 2012-09-19T14:56:51.740Z,1348066611.740 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2012-09-19T14:56:51.881Z,1348066611.881 [InternalSim] Loaded 2012-09-19T14:56:51.881Z,1348066611.881 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2012-09-19T14:56:51.882Z,1348066611.882 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2012-09-19T14:56:51.882Z,1348066611.882 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2012-09-19T14:56:51.941Z,1348066611.941 [SBIT](DEBUG): Construct Startup Built In Test. 2012-09-19T14:56:51.954Z,1348066611.954 [SBIT] Loaded 2012-09-19T14:56:51.954Z,1348066611.954 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2012-09-19T14:56:51.955Z,1348066611.955 [IBIT](DEBUG): Construct Initiated Built In Test. 2012-09-19T14:56:51.983Z,1348066611.983 [IBIT] Loaded 2012-09-19T14:56:51.983Z,1348066611.983 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2012-09-19T14:56:51.986Z,1348066611.986 [CBIT](DEBUG): Construct CBIT Built In Test. 2012-09-19T14:56:52.101Z,1348066612.101 [CBIT] Loaded 2012-09-19T14:56:52.102Z,1348066612.102 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2012-09-19T14:56:52.102Z,1348066612.102 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2012-09-19T14:56:52.103Z,1348066612.103 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2012-09-19T14:56:52.249Z,1348066612.249 [BuoyancyServo] Loaded 2012-09-19T14:56:52.249Z,1348066612.249 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2012-09-19T14:56:52.259Z,1348066612.259 [ElevatorServo] Loaded 2012-09-19T14:56:52.260Z,1348066612.260 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2012-09-19T14:56:52.271Z,1348066612.271 [MassServo] Loaded 2012-09-19T14:56:52.271Z,1348066612.271 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2012-09-19T14:56:52.283Z,1348066612.283 [RudderServo] Loaded 2012-09-19T14:56:52.283Z,1348066612.283 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2012-09-19T14:56:52.295Z,1348066612.295 [ThrusterServo] Loaded 2012-09-19T14:56:52.295Z,1348066612.295 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2012-09-19T14:56:52.296Z,1348066612.296 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2012-09-19T14:56:52.296Z,1348066612.296 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2012-09-19T14:56:52.315Z,1348066612.315 [DepthRateCalculator] Loaded 2012-09-19T14:56:52.315Z,1348066612.315 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2012-09-19T14:56:54.938Z,1348066614.938 [HFRadarModelCalc] Loaded 2012-09-19T14:56:54.939Z,1348066614.939 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread. 2012-09-19T14:56:54.955Z,1348066614.954 [NavChart] Loaded 2012-09-19T14:56:54.955Z,1348066614.955 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2012-09-19T14:56:54.961Z,1348066614.961 [PitchRateCalculator] Loaded 2012-09-19T14:56:54.961Z,1348066614.961 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2012-09-19T14:56:54.967Z,1348066614.967 [SpeedCalculator] Loaded 2012-09-19T14:56:54.968Z,1348066614.968 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2012-09-19T14:56:54.983Z,1348066614.983 [TempGradientCalculator] Loaded 2012-09-19T14:56:54.983Z,1348066614.983 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2012-09-19T14:56:54.989Z,1348066614.989 [YawRateCalculator] Loaded 2012-09-19T14:56:54.989Z,1348066614.989 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2012-09-19T14:56:55.008Z,1348066615.008 [Navigation] Loaded 2012-09-19T14:56:55.009Z,1348066615.009 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread. 2012-09-19T14:56:55.009Z,1348066615.009 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2012-09-19T14:56:55.010Z,1348066615.010 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2012-09-19T14:56:55.236Z,1348066615.236 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2012-09-19T14:56:55.236Z,1348066615.236 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2012-09-19T14:56:55.259Z,1348066615.259 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2012-09-19T14:56:55.260Z,1348066615.260 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2012-09-19T14:56:55.301Z,1348066615.301 [VerticalControl](DEBUG): Construct VerticalControl. 2012-09-19T14:56:55.345Z,1348066615.345 [VerticalControl] Loaded 2012-09-19T14:56:55.346Z,1348066615.346 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2012-09-19T14:56:55.347Z,1348066615.347 [HorizontalControl](DEBUG): Construct HorizontalControl. 2012-09-19T14:56:55.367Z,1348066615.367 [HorizontalControl] Loaded 2012-09-19T14:56:55.367Z,1348066615.367 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2012-09-19T14:56:55.368Z,1348066615.368 [SpeedControl](DEBUG): Construct SpeedControl. 2012-09-19T14:56:55.370Z,1348066615.370 [SpeedControl] Loaded 2012-09-19T14:56:55.370Z,1348066615.370 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2012-09-19T14:56:55.371Z,1348066615.371 [LoopControl](DEBUG): Construct LoopControl. 2012-09-19T14:56:55.372Z,1348066615.372 [LoopControl] Loaded 2012-09-19T14:56:55.372Z,1348066615.372 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2012-09-19T14:56:55.373Z,1348066615.372 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2012-09-19T14:56:55.373Z,1348066615.373 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2012-09-19T14:56:55.379Z,1348066615.378 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2012-09-19T14:56:55.383Z,1348066615.383 [AsyncPiEstimator] Loaded 2012-09-19T14:56:55.384Z,1348066615.384 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2012-09-19T14:56:55.385Z,1348066615.385 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4060A4E0 2012-09-19T14:56:55.386Z,1348066615.385 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2012-09-19T14:56:55.386Z,1348066615.386 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2012-09-19T14:56:55.512Z,1348066615.512 [AHRS_sp3003D] Loaded 2012-09-19T14:56:55.512Z,1348066615.512 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2012-09-19T14:56:55.526Z,1348066615.526 [Depth_Keller] Loaded 2012-09-19T14:56:55.526Z,1348066615.526 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2012-09-19T14:56:55.532Z,1348066615.532 [DropWeight] Loaded 2012-09-19T14:56:55.532Z,1348066615.532 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2012-09-19T14:56:55.647Z,1348066615.647 [DVL_micro] Loaded 2012-09-19T14:56:55.648Z,1348066615.648 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread. 2012-09-19T14:56:55.649Z,1348066615.649 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4068A4E0 2012-09-19T14:56:55.730Z,1348066615.730 [NAL9602] Loaded 2012-09-19T14:56:55.730Z,1348066615.730 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2012-09-19T14:56:55.779Z,1348066615.779 [Onboard] Loaded 2012-09-19T14:56:55.780Z,1348066615.780 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2012-09-19T14:56:55.786Z,1348066615.786 [Radio_Freewave] Loaded 2012-09-19T14:56:55.787Z,1348066615.787 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread. 2012-09-19T14:56:55.788Z,1348066615.788 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2012-09-19T14:56:55.788Z,1348066615.788 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2012-09-19T14:56:55.861Z,1348066615.861 [CTD_NeilBrown] Loaded 2012-09-19T14:56:55.862Z,1348066615.862 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2012-09-19T14:56:55.863Z,1348066615.863 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E24E0 2012-09-19T14:56:55.873Z,1348066615.873 [PAR_Licor] Loaded 2012-09-19T14:56:55.873Z,1348066615.873 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2012-09-19T14:56:55.890Z,1348066615.890 [Turbulence_NPS] Loaded 2012-09-19T14:56:55.890Z,1348066615.890 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread. 2012-09-19T14:56:55.893Z,1348066615.894 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407124E0 2012-09-19T14:56:55.923Z,1348066615.923 [WetLabsBB2FL] Loaded 2012-09-19T14:56:55.924Z,1348066615.924 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2012-09-19T14:56:55.924Z,1348066615.924 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407424E0 2012-09-19T14:56:55.925Z,1348066615.925 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2012-09-19T14:56:55.928Z,1348066615.928 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2012-09-19T14:56:55.929Z,1348066615.929 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2012-09-19T14:56:55.935Z,1348066615.935 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2012-09-19T14:56:55.936Z,1348066615.936 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407724E0 2012-09-19T14:56:55.940Z,1348066615.940 [Supervisor](DEBUG): Running supervisor. 2012-09-19T14:56:55.944Z,1348066615.944 [controlThread](DEBUG): Initializing ControlThread 2012-09-19T14:56:55.945Z,1348066615.945 [InternalSim](DEBUG): InternalSim initializing... 2012-09-19T14:56:55.979Z,1348066615.979 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2012-09-19T14:56:55.989Z,1348066615.989 [SBIT](INFO): Initialize SBIT Component. 2012-09-19T14:56:55.989Z,1348066615.990 [SBIT](IMPORTANT): Tethys CM Info: $Rev: 9842 2012-09-19T14:56:55.990Z,1348066615.990 [IBIT](INFO): Initialize IBIT Component. 2012-09-19T14:56:55.992Z,1348066615.992 [CBIT](DEBUG): Initialize CBIT Component. 2012-09-19T14:56:55.993Z,1348066615.993 [CBIT](CRITICAL): Watchdog Timer failed to initialize. 2012-09-19T14:56:55.993Z,1348066615.993 [CBIT] Hardware Fault, FailCount= 1 2012-09-19T14:56:55.993Z,1348066615.993 [CBIT](ERROR): Hardware Fault 2012-09-19T14:56:56.003Z,1348066616.003 [DVL_micro](INFO): Initializing 2012-09-19T14:56:56.003Z,1348066616.003 [DVL_micro](INFO): start:Powering up 2012-09-19T14:56:56.016Z,1348066616.016 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2012-09-19T14:56:56.020Z,1348066616.020 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2012-09-19T14:56:56.021Z,1348066616.021 [NavChart](DEBUG): Initialize NavChart Derivation. 2012-09-19T14:56:56.021Z,1348066616.021 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2012-09-19T14:56:56.022Z,1348066616.022 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2012-09-19T14:56:56.022Z,1348066616.022 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2012-09-19T14:56:56.024Z,1348066616.024 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2012-09-19T14:56:56.024Z,1348066616.024 [Navigation](DEBUG): Initializing Navigation. 2012-09-19T14:56:56.024Z,1348066616.024 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2012-09-19T14:56:56.026Z,1348066616.026 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2012-09-19T14:56:56.027Z,1348066616.027 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2012-09-19T14:56:56.028Z,1348066616.028 [LoopControl](DEBUG): Initialize LoopControlComponent. 2012-09-19T14:56:56.040Z,1348066616.040 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS. 2012-09-19T14:56:56.058Z,1348066616.057 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2012-09-19T14:56:56.060Z,1348066616.060 [WetLabsBB2FL](INFO): Powering down 2012-09-19T14:56:56.093Z,1348066616.093 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T14:56:56.134Z,1348066616.134 [MissionManager](DEBUG): 2012-09-19T14:56:56.134Z,1348066616.134 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2012-09-19T14:56:56.216Z,1348066616.216 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool 2012-09-19T14:56:56.218Z,1348066616.218 [Default:GPS:A.SetSpeed](DEBUG): Construct. 2012-09-19T14:56:56.236Z,1348066616.236 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T14:56:56.254Z,1348066616.253 [Default:Iridium:A.SetSpeed](DEBUG): Construct. 2012-09-19T14:56:56.258Z,1348066616.258 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T14:56:56.272Z,1348066616.272 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2012-09-19T14:56:56.290Z,1348066616.290 [Default:D.SetSpeed](DEBUG): Construct. 2012-09-19T14:56:56.299Z,1348066616.299 [Default:E.GoToSurface](DEBUG): Construct GoToSurface. 2012-09-19T14:56:56.308Z,1348066616.308 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2012-09-19T14:56:56.312Z,1348066616.312 [Default:F.Wait](DEBUG): Construct Wait. 2012-09-19T14:56:56.320Z,1348066616.320 [MissionManager](DEBUG): 400 400 Burn 300 Dropped drop weight due to communications timeout 5.0 1.0 5 2012-09-19T14:56:56.324Z,1348066616.324 [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-19T14:56:56.329Z,1348066616.329 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2012-09-19T14:56:56.337Z,1348066616.337 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2012-09-19T14:56:56.345Z,1348066616.345 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2012-09-19T14:56:56.354Z,1348066616.354 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2012-09-19T14:56:56.354Z,1348066616.354 [NavChartDb](INFO): Creating index for Soundings 2012-09-19T14:56:56.362Z,1348066616.362 [NavChartDb](INFO): Creating index for Contour 0p0 2012-09-19T14:56:56.365Z,1348066616.365 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2012-09-19T14:56:56.370Z,1348066616.369 [NavChartDb](INFO): Creating index for Contour 1p8 2012-09-19T14:56:56.372Z,1348066616.372 [NavChartDb](INFO): Creating index for Contour 3p6 2012-09-19T14:56:56.374Z,1348066616.374 [NavChartDb](INFO): Creating index for Contour 5p4 2012-09-19T14:56:56.382Z,1348066616.382 [NavChartDb](INFO): Creating index for Contour 9p1 2012-09-19T14:56:56.384Z,1348066616.385 [NavChartDb](INFO): Creating index for Contour 10p9 2012-09-19T14:56:56.386Z,1348066616.386 [NavChartDb](INFO): Creating index for Contour 18p2 2012-09-19T14:56:56.393Z,1348066616.392 [NavChartDb](INFO): Creating index for Contour 36p5 2012-09-19T14:56:56.394Z,1348066616.394 [NavChartDb](INFO): Creating index for Contour 54p8 2012-09-19T14:56:56.396Z,1348066616.396 [NavChartDb](INFO): Creating index for Contour 73p1 2012-09-19T14:56:56.398Z,1348066616.398 [NavChartDb](INFO): Creating index for Contour 91p4 2012-09-19T14:56:56.400Z,1348066616.400 [NavChartDb](INFO): Creating index for Contour 182p8 2012-09-19T14:56:56.402Z,1348066616.402 [NavChartDb](INFO): Creating index for Contour 365p7 2012-09-19T14:56:56.404Z,1348066616.404 [NavChartDb](INFO): Creating index for Contour 548p6 2012-09-19T14:56:56.406Z,1348066616.406 [NavChartDb](INFO): Creating index for Contour 731p5 2012-09-19T14:56:56.412Z,1348066616.412 [NavChartDb](INFO): Creating index for Contour 914p4 2012-09-19T14:56:56.414Z,1348066616.414 [NavChartDb](INFO): Creating index for Contour 1097p2 2012-09-19T14:56:56.416Z,1348066616.416 [NavChartDb](INFO): Creating index for Contour 1280p1 2012-09-19T14:56:56.418Z,1348066616.418 [NavChartDb](INFO): Creating index for Contour 1463p0 2012-09-19T14:56:56.420Z,1348066616.420 [NavChartDb](INFO): Creating index for Contour 1645p9 2012-09-19T14:56:56.422Z,1348066616.422 [NavChartDb](INFO): Creating index for Contour 1828p8 2012-09-19T14:56:56.428Z,1348066616.428 [NavChartDb](INFO): Creating index for Contour 2011p6 2012-09-19T14:56:56.430Z,1348066616.430 [NavChartDb](INFO): Creating index for Contour 2194p5 2012-09-19T14:56:56.432Z,1348066616.432 [NavChartDb](INFO): Creating index for Contour 2377p4 2012-09-19T14:56:56.434Z,1348066616.434 [NavChartDb](INFO): Creating index for Contour 2560p3 2012-09-19T14:56:56.436Z,1348066616.436 [NavChartDb](INFO): Creating index for Contour 2743p2 2012-09-19T14:56:56.438Z,1348066616.438 [NavChartDb](INFO): Creating index for Contour 2926p0 2012-09-19T14:56:56.440Z,1348066616.440 [NavChartDb](INFO): Creating index for Contour 3108p9 2012-09-19T14:56:56.442Z,1348066616.442 [NavChartDb](INFO): Creating index for Contour 3291p8 2012-09-19T14:56:56.468Z,1348066616.468 [NavChartDb](INFO): Creating index for Contour 3474p7 2012-09-19T14:56:56.469Z,1348066616.469 [NavChartDb](INFO): Creating index for Contour 3657p6 2012-09-19T14:56:56.503Z,1348066616.503 [Radio_Freewave](INFO): Powering up 2012-09-19T14:56:56.751Z,1348066616.751 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2012-09-19T14:56:56.759Z,1348066616.759 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2012-09-19T14:56:56.771Z,1348066616.771 [ElevatorServo](DEBUG): Initializing EZServoServo. 2012-09-19T14:56:56.791Z,1348066616.791 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2012-09-19T14:56:56.797Z,1348066616.797 [MassServo](DEBUG): Initializing EZServoServo. 2012-09-19T14:56:56.798Z,1348066616.798 [MassServo](DEBUG): Initializing MassServo. 2012-09-19T14:56:56.804Z,1348066616.804 [RudderServo](DEBUG): Initializing EZServoServo. 2012-09-19T14:56:56.805Z,1348066616.805 [RudderServo](DEBUG): Initializing RudderServo. 2012-09-19T14:56:56.811Z,1348066616.811 [ThrusterServo](DEBUG): Initializing EZServoServo. 2012-09-19T14:56:56.812Z,1348066616.812 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2012-09-19T14:56:56.827Z,1348066616.827 [CBIT](DEBUG): Uninitialize CBIT Component. 2012-09-19T14:56:57.642Z,1348066617.642 [DVL_micro](INFO): Querying output modes 2012-09-19T14:56:57.642Z,1348066617.642 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-09-19T14:56:59.192Z,1348066619.192 [AHRS_sp3003D](ERROR): SP3003D failed to initialize 2012-09-19T14:56:59.192Z,1348066619.192 [AHRS_sp3003D] Hardware Fault, FailCount= 1 2012-09-19T14:56:59.192Z,1348066619.192 [AHRS_sp3003D](ERROR): Hardware Fault 2012-09-19T14:56:59.659Z,1348066619.659 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:56:59.659Z,1348066619.659 [DVL_micro](INFO): Output Modes: No Response 2012-09-19T14:56:59.659Z,1348066619.659 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-09-19T14:56:59.727Z,1348066619.727 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout 2012-09-19T14:56:59.727Z,1348066619.727 [BuoyancyServo](FAULT): Buoyancy failed to initialize 2012-09-19T14:56:59.727Z,1348066619.727 [BuoyancyServo] Communications Fault, FailCount= 1 2012-09-19T14:56:59.727Z,1348066619.727 [BuoyancyServo](ERROR): Communications Fault 2012-09-19T14:57:00.235Z,1348066620.235 [ElevatorServo](ERROR): Elevator initialization uart error I:serial timeout 2012-09-19T14:57:00.235Z,1348066620.235 [ElevatorServo](FAULT): Elevator failed to initialize 2012-09-19T14:57:00.235Z,1348066620.235 [ElevatorServo] Communications Fault, FailCount= 1 2012-09-19T14:57:00.235Z,1348066620.235 [ElevatorServo](ERROR): Communications Fault 2012-09-19T14:57:00.747Z,1348066620.747 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2012-09-19T14:57:00.747Z,1348066620.747 [RudderServo](FAULT): Rudder failed to initialize 2012-09-19T14:57:00.747Z,1348066620.747 [RudderServo] Communications Fault, FailCount= 1 2012-09-19T14:57:00.747Z,1348066620.747 [RudderServo](ERROR): Communications Fault 2012-09-19T14:57:01.255Z,1348066621.255 [ThrusterServo](ERROR): Thruster initialization uart error serial timeout 2012-09-19T14:57:01.255Z,1348066621.255 [ThrusterServo](FAULT): Thruster failed to initialize 2012-09-19T14:57:01.255Z,1348066621.255 [ThrusterServo] Communications Fault, FailCount= 1 2012-09-19T14:57:01.255Z,1348066621.255 [ThrusterServo](ERROR): Communications Fault 2012-09-19T14:57:01.368Z,1348066621.368 [AHRS_sp3003D](INFO): Powering down 2012-09-19T14:57:01.458Z,1348066621.458 [NAL9602](INFO): Powering up NAL9602 2012-09-19T14:57:01.478Z,1348066621.478 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2012-09-19T14:57:01.478Z,1348066621.478 [BuoyancyServo](INFO): Powering down 2012-09-19T14:57:01.501Z,1348066621.501 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2012-09-19T14:57:01.501Z,1348066621.501 [ElevatorServo](INFO): Powering down 2012-09-19T14:57:01.663Z,1348066621.663 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:01.668Z,1348066621.668 [DVL_micro](INFO): pause:Powering down 2012-09-19T14:57:01.669Z,1348066621.669 [DVL_micro](INFO): NQ1 requested 2012-09-19T14:57:01.669Z,1348066621.670 [DVL_micro](INFO): resume:Powering up 2012-09-19T14:57:02.027Z,1348066622.027 [MassServo](FAULT): Mass shifter EEPROM initialization uart error serial timeout 2012-09-19T14:57:02.027Z,1348066622.027 [MassServo] Communications Fault, FailCount= 1 2012-09-19T14:57:02.027Z,1348066622.027 [MassServo](ERROR): Communications Fault 2012-09-19T14:57:02.028Z,1348066622.028 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2012-09-19T14:57:02.028Z,1348066622.028 [RudderServo](INFO): Powering down 2012-09-19T14:57:02.045Z,1348066622.046 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2012-09-19T14:57:02.046Z,1348066622.046 [ThrusterServo](INFO): Powering down 2012-09-19T14:57:02.182Z,1348066622.182 [MassServo](DEBUG): Uninitialize Mass Servo. 2012-09-19T14:57:02.182Z,1348066622.182 [MassServo](INFO): Powering down 2012-09-19T14:57:03.175Z,1348066623.175 [DVL_micro](INFO): Querying output modes 2012-09-19T14:57:03.175Z,1348066623.175 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-09-19T14:57:05.180Z,1348066625.180 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:05.180Z,1348066625.180 [DVL_micro](INFO): Output Modes: No Response 2012-09-19T14:57:05.180Z,1348066625.180 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-09-19T14:57:07.183Z,1348066627.183 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:07.184Z,1348066627.184 [DVL_micro](INFO): NQ1 requested 2012-09-19T14:57:08.691Z,1348066628.691 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0 2012-09-19T14:57:10.695Z,1348066630.695 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:10.695Z,1348066630.695 [DVL_micro](INFO): Enabling NQ1 output 2012-09-19T14:57:10.695Z,1348066630.695 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1 2012-09-19T14:57:11.769Z,1348066631.769 [SBIT](IMPORTANT): Beginning Startup BIT 2012-09-19T14:57:12.699Z,1348066632.699 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:12.699Z,1348066632.699 [DVL_micro](INFO): Querying output modes 2012-09-19T14:57:12.699Z,1348066632.699 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-09-19T14:57:14.155Z,1348066634.155 [NAL9602](ERROR): NAL9602 initialize uart error: serial timeout 2012-09-19T14:57:14.155Z,1348066634.155 [NAL9602] Communications Fault, FailCount= 1 2012-09-19T14:57:14.155Z,1348066634.155 [NAL9602](ERROR): Communications Fault 2012-09-19T14:57:14.256Z,1348066634.256 [NAL9602](INFO): Powering down 2012-09-19T14:57:14.703Z,1348066634.703 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:14.703Z,1348066634.703 [DVL_micro](INFO): Output Modes: No Response 2012-09-19T14:57:14.703Z,1348066634.703 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-09-19T14:57:16.707Z,1348066636.707 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:17.029Z,1348066637.029 [PAR_Licor](ERROR): PAR reading out of range: -0.019074 uMol/s/m2 2012-09-19T14:57:18.711Z,1348066638.711 [DVL_micro](INFO): NQ1 requested 2012-09-19T14:57:19.034Z,1348066639.034 [PAR_Licor](ERROR): PAR reading out of range: -0.019074 uMol/s/m2 2012-09-19T14:57:19.835Z,1348066639.835 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T14:57:20.219Z,1348066640.219 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0 2012-09-19T14:57:22.223Z,1348066642.223 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:22.223Z,1348066642.223 [DVL_micro](INFO): Enabling NQ1 output 2012-09-19T14:57:22.223Z,1348066642.223 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1 2012-09-19T14:57:22.629Z,1348066642.629 [PAR_Licor](ERROR): PAR reading out of range: -0.025432 uMol/s/m2 2012-09-19T14:57:24.227Z,1348066644.227 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:24.227Z,1348066644.227 [DVL_micro](INFO): Querying output modes 2012-09-19T14:57:24.227Z,1348066644.227 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-09-19T14:57:24.230Z,1348066644.230 [PAR_Licor](ERROR): PAR reading out of range: -0.027021 uMol/s/m2 2012-09-19T14:57:25.042Z,1348066645.042 [SBIT](FAULT): Mass: EXPECTED:0.004800 ACTUAL:-0.000990 2012-09-19T14:57:26.231Z,1348066646.231 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:26.231Z,1348066646.231 [DVL_micro](INFO): Output Modes: No Response 2012-09-19T14:57:26.231Z,1348066646.231 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-09-19T14:57:27.431Z,1348066647.431 [PAR_Licor](ERROR): PAR reading out of range: -0.027021 uMol/s/m2 2012-09-19T14:57:28.235Z,1348066648.235 [DVL_micro](DEBUG): cmdResponse: 2012-09-19T14:57:28.235Z,1348066648.235 [DVL_micro](ERROR): No DVL communication! Re-initializing 2012-09-19T14:57:28.235Z,1348066648.235 [DVL_micro] Communications Fault, FailCount= 1 2012-09-19T14:57:28.235Z,1348066648.235 [DVL_micro](ERROR): Communications Fault 2012-09-19T14:57:28.237Z,1348066648.237 [DVL_micro](INFO): uninitialize:Powering down 2012-09-19T14:57:38.658Z,1348066658.658 [PAR_Licor](ERROR): PAR reading out of range: -0.012716 uMol/s/m2 2012-09-19T14:57:42.642Z,1348066662.642 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T14:57:47.042Z,1348066667.042 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T14:57:50.247Z,1348066670.247 [PAR_Licor](ERROR): PAR reading out of range: -0.050864 uMol/s/m2 2012-09-19T14:57:52.631Z,1348066672.631 [PAR_Licor](ERROR): PAR reading out of range: -0.042916 uMol/s/m2 2012-09-19T14:57:53.842Z,1348066673.842 [PAR_Licor](ERROR): PAR reading out of range: -0.003179 uMol/s/m2 2012-09-19T14:57:57.042Z,1348066677.042 [PAR_Licor](ERROR): PAR reading out of range: -0.006358 uMol/s/m2 2012-09-19T14:57:59.858Z,1348066679.858 [PAR_Licor](ERROR): PAR reading out of range: -0.009537 uMol/s/m2 2012-09-19T14:58:05.469Z,1348066685.469 [SBIT](CRITICAL): SBIT FAILED 2012-09-19T14:58:05.842Z,1348066685.842 [PAR_Licor](ERROR): PAR reading out of range: -0.036558 uMol/s/m2 2012-09-19T14:58:05.854Z,1348066685.853 [MissionManager](IMPORTANT): Started mission Startup 2012-09-19T14:58:05.854Z,1348066685.854 [Startup] Running Loop=1 2012-09-19T14:58:05.854Z,1348066685.854 [Startup](INFO): Aggregate::initialize Startup 2012-09-19T14:58:05.854Z,1348066685.854 [Startup:A.GoToSurface] Running Loop=1 2012-09-19T14:58:05.854Z,1348066685.854 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T14:58:05.868Z,1348066685.868 [Startup:StartupSatComms] Running Loop=1 2012-09-19T14:58:05.868Z,1348066685.868 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2012-09-19T14:58:05.868Z,1348066685.868 [Startup:StartupSatComms:A] Running Loop=1 2012-09-19T14:58:06.257Z,1348066686.257 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-09-19T14:58:07.042Z,1348066687.042 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2 2012-09-19T14:58:08.658Z,1348066688.658 [PAR_Licor](ERROR): PAR reading out of range: -0.063580 uMol/s/m2 2012-09-19T14:58:17.042Z,1348066697.042 [PAR_Licor](ERROR): PAR reading out of range: -0.019074 uMol/s/m2 2012-09-19T14:58:17.842Z,1348066697.842 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2 2012-09-19T14:58:18.658Z,1348066698.658 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2 2012-09-19T14:58:20.242Z,1348066700.242 [PAR_Licor](ERROR): PAR reading out of range: -0.011126 uMol/s/m2 2012-09-19T14:58:23.042Z,1348066703.042 [PAR_Licor](ERROR): PAR reading out of range: -0.003179 uMol/s/m2 2012-09-19T14:58:24.242Z,1348066704.242 [PAR_Licor](ERROR): PAR reading out of range: -0.020663 uMol/s/m2 2012-09-19T14:58:25.042Z,1348066705.042 [PAR_Licor](ERROR): PAR reading out of range: -0.011126 uMol/s/m2 2012-09-19T14:58:25.858Z,1348066705.858 [PAR_Licor](ERROR): PAR reading out of range: -0.020663 uMol/s/m2 2012-09-19T14:58:28.439Z,1348066708.439 [PAR_Licor](ERROR): PAR reading out of range: -0.065169 uMol/s/m2 2012-09-19T14:58:29.842Z,1348066709.842 [PAR_Licor](ERROR): PAR reading out of range: -0.009537 uMol/s/m2 2012-09-19T14:58:31.442Z,1348066711.442 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2 2012-09-19T14:58:33.038Z,1348066713.038 [PAR_Licor](ERROR): PAR reading out of range: -0.006358 uMol/s/m2 2012-09-19T14:58:33.842Z,1348066713.842 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T14:58:39.842Z,1348066719.842 [PAR_Licor](ERROR): PAR reading out of range: -0.004768 uMol/s/m2 2012-09-19T14:58:42.242Z,1348066722.242 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2 2012-09-19T14:58:43.842Z,1348066723.842 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T14:58:45.842Z,1348066725.842 [PAR_Licor](ERROR): PAR reading out of range: -0.014305 uMol/s/m2 2012-09-19T14:58:47.042Z,1348066727.042 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2 2012-09-19T14:58:49.442Z,1348066729.442 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T14:58:50.642Z,1348066730.642 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2 2012-09-19T14:58:52.242Z,1348066732.242 [PAR_Licor](ERROR): PAR reading out of range: -0.052453 uMol/s/m2 2012-09-19T14:58:54.243Z,1348066734.243 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2 2012-09-19T14:58:57.442Z,1348066737.442 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2 2012-09-19T14:58:58.242Z,1348066738.242 [PAR_Licor](ERROR): PAR reading out of range: -0.036558 uMol/s/m2 2012-09-19T14:59:01.042Z,1348066741.042 [PAR_Licor](ERROR): PAR reading out of range: -0.023842 uMol/s/m2 2012-09-19T14:59:03.842Z,1348066743.842 [PAR_Licor](ERROR): PAR reading out of range: -0.009537 uMol/s/m2 2012-09-19T14:59:04.642Z,1348066744.642 [PAR_Licor](ERROR): PAR reading out of range: -0.047685 uMol/s/m2 2012-09-19T14:59:06.264Z,1348066746.263 [Startup:StartupSatComms:A](INFO): Timed out from 2012-09-19T14:58:05.9Z 2012-09-19T14:59:06.264Z,1348066746.264 [Startup:StartupSatComms:A_Timeout] Running Loop=1 2012-09-19T14:59:06.264Z,1348066746.264 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout 2012-09-19T14:59:06.264Z,1348066746.264 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout 2012-09-19T14:59:06.264Z,1348066746.264 [Startup:StartupSatComms:A] Stopped 2012-09-19T14:59:06.264Z,1348066746.264 [Startup:StartupSatComms:B] Running Loop=1 2012-09-19T14:59:06.642Z,1348066746.642 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2 2012-09-19T14:59:06.664Z,1348066746.664 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-09-19T14:59:14.242Z,1348066754.242 [PAR_Licor](ERROR): PAR reading out of range: -0.047685 uMol/s/m2 2012-09-19T14:59:16.242Z,1348066756.242 [PAR_Licor](ERROR): PAR reading out of range: -0.007947 uMol/s/m2 2012-09-19T14:59:18.642Z,1348066758.642 [PAR_Licor](ERROR): PAR reading out of range: -0.007947 uMol/s/m2 2012-09-19T14:59:21.442Z,1348066761.442 [PAR_Licor](ERROR): PAR reading out of range: -0.060401 uMol/s/m2 2012-09-19T14:59:25.042Z,1348066765.042 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2 2012-09-19T14:59:28.242Z,1348066768.242 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2 2012-09-19T14:59:29.442Z,1348066769.442 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2 2012-09-19T14:59:30.290Z,1348066770.290 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2 2012-09-19T14:59:31.053Z,1348066771.053 [PAR_Licor](ERROR): PAR reading out of range: -0.007947 uMol/s/m2 2012-09-19T14:59:33.042Z,1348066773.042 [PAR_Licor](ERROR): PAR reading out of range: -0.019074 uMol/s/m2 2012-09-19T14:59:35.458Z,1348066775.458 [PAR_Licor](ERROR): PAR reading out of range: -0.020663 uMol/s/m2 2012-09-19T14:59:37.842Z,1348066777.842 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T14:59:38.642Z,1348066778.642 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2 2012-09-19T14:59:41.442Z,1348066781.442 [PAR_Licor](ERROR): PAR reading out of range: -0.003179 uMol/s/m2 2012-09-19T14:59:43.442Z,1348066783.442 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2 2012-09-19T14:59:45.442Z,1348066785.442 [PAR_Licor](ERROR): PAR reading out of range: -0.004768 uMol/s/m2 2012-09-19T14:59:47.042Z,1348066787.042 [PAR_Licor](ERROR): PAR reading out of range: -0.003179 uMol/s/m2 2012-09-19T14:59:54.642Z,1348066794.642 [PAR_Licor](ERROR): PAR reading out of range: -0.012716 uMol/s/m2 2012-09-19T14:59:56.642Z,1348066796.642 [PAR_Licor](ERROR): PAR reading out of range: -0.012716 uMol/s/m2 2012-09-19T15:00:00.535Z,1348066800.535 [CommandLine](IMPORTANT): got command show stack 2012-09-19T15:00:00.535Z,1348066800.535 [CommandLine](INFO): Behavior Stack: 2012-09-19T15:00:00.536Z,1348066800.536 [Startup](INFO): Priority 0: Startup:A.GoToSurface 2012-09-19T15:00:00.536Z,1348066800.536 [Startup:StartupSatComms](INFO): Priority 1: Startup:StartupSatComms:B 2012-09-19T15:00:06.660Z,1348066806.660 [Startup:StartupSatComms:B](INFO): Timed out from 2012-09-19T14:59:06.3Z 2012-09-19T15:00:06.660Z,1348066806.660 [Startup:StartupSatComms:A_Timeout] Running Loop=1 2012-09-19T15:00:06.660Z,1348066806.660 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout 2012-09-19T15:00:06.660Z,1348066806.660 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout 2012-09-19T15:00:06.660Z,1348066806.661 [Startup:StartupSatComms:B] Stopped 2012-09-19T15:00:06.661Z,1348066806.661 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2012-09-19T15:00:06.661Z,1348066806.661 [Startup:StartupSatComms] Stopped 2012-09-19T15:00:06.661Z,1348066806.661 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2012-09-19T15:00:06.662Z,1348066806.662 [Startup](INFO): Completed Startup 2012-09-19T15:00:06.662Z,1348066806.662 [Startup] Stopped 2012-09-19T15:00:06.662Z,1348066806.662 [Startup](INFO): Aggregate::uninitialize Startup 2012-09-19T15:00:06.662Z,1348066806.662 [Startup:A.GoToSurface] Stopped 2012-09-19T15:00:06.662Z,1348066806.662 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T15:00:07.052Z,1348066807.052 [MissionManager](IMPORTANT): Started mission Default 2012-09-19T15:00:07.052Z,1348066807.052 [Default] Running Loop=1 2012-09-19T15:00:07.053Z,1348066807.053 [Default](INFO): Aggregate::initialize Default 2012-09-19T15:00:07.053Z,1348066807.053 [Default:D.SetSpeed] Running Loop=1 2012-09-19T15:00:07.053Z,1348066807.053 [Default:D.SetSpeed](DEBUG): Initialize. 2012-09-19T15:00:07.053Z,1348066807.053 [Default:E.GoToSurface] Running Loop=1 2012-09-19T15:00:07.053Z,1348066807.053 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T15:00:07.053Z,1348066807.053 [Default:Iridium] Running Loop=1 2012-09-19T15:00:07.053Z,1348066807.053 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2012-09-19T15:00:07.053Z,1348066807.053 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-09-19T15:00:07.054Z,1348066807.053 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2012-09-19T15:00:07.054Z,1348066807.054 [Default:Iridium:B.GoToSurface] Running Loop=1 2012-09-19T15:00:07.054Z,1348066807.054 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T15:00:07.054Z,1348066807.054 [Default:E.GoToSurface] Running Loop=1 2012-09-19T15:00:07.059Z,1348066807.059 [Default:D.SetSpeed] Running Loop=1 2012-09-19T15:00:07.076Z,1348066807.076 [Default:CallIridium] Running Loop=1 2012-09-19T15:00:07.076Z,1348066807.076 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2012-09-19T15:00:07.076Z,1348066807.076 [Default:CallIridium:A] Running Loop=1 2012-09-19T15:00:07.078Z,1348066807.078 [Default:CallIridium:A] Stopped 2012-09-19T15:00:07.078Z,1348066807.078 [Default:CallIridium:B] Running Loop=1 2012-09-19T15:00:07.078Z,1348066807.078 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2012-09-19T15:00:07.083Z,1348066807.083 [Default:Iridium:B.GoToSurface] Stopped 2012-09-19T15:00:07.083Z,1348066807.083 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T15:00:07.083Z,1348066807.083 [Default:Iridium:Read_Iridium] Running Loop=1 2012-09-19T15:00:07.083Z,1348066807.083 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-09-19T15:00:07.100Z,1348066807.100 [Default:GPS] Running Loop=1 2012-09-19T15:00:07.100Z,1348066807.100 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2012-09-19T15:00:07.100Z,1348066807.100 [Default:GPS:A.SetSpeed] Running Loop=1 2012-09-19T15:00:07.100Z,1348066807.100 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2012-09-19T15:00:07.101Z,1348066807.101 [Default:GPS:B.GoToSurface] Running Loop=1 2012-09-19T15:00:07.101Z,1348066807.101 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-09-19T15:00:07.110Z,1348066807.110 [Default:GPS:B.GoToSurface] Stopped 2012-09-19T15:00:07.110Z,1348066807.110 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-09-19T15:00:07.110Z,1348066807.110 [Default:GPS:Read_GPS] Running Loop=1 2012-09-19T15:00:07.110Z,1348066807.110 [Default:GPS:A.SetSpeed] Running Loop=1 2012-09-19T15:00:07.462Z,1348066807.462 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-09-19T15:00:07.464Z,1348066807.464 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-09-19T15:00:11.027Z,1348066811.027 [CommandLine](IMPORTANT): got command get depth 2012-09-19T15:00:11.028Z,1348066811.028 [CommandLine](IMPORTANT): depth -0.005588 meter 2012-09-19T15:00:14.642Z,1348066814.642 [PAR_Licor](ERROR): PAR reading out of range: -0.007947 uMol/s/m2 2012-09-19T15:00:19.842Z,1348066819.842 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2 2012-09-19T15:00:21.458Z,1348066821.458 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2 2012-09-19T15:00:22.642Z,1348066822.642 [PAR_Licor](ERROR): PAR reading out of range: -0.006358 uMol/s/m2 2012-09-19T15:00:23.442Z,1348066823.442 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2 2012-09-19T15:00:24.290Z,1348066824.290 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree 2012-09-19T15:00:24.303Z,1348066824.303 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree 2012-09-19T15:00:24.765Z,1348066824.765 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2012-09-19T15:00:27.042Z,1348066827.042 [PAR_Licor](ERROR): PAR reading out of range: -0.025432 uMol/s/m2 2012-09-19T15:00:31.842Z,1348066831.842 [PAR_Licor](ERROR): PAR reading out of range: -0.036558 uMol/s/m2 2012-09-19T15:00:32.683Z,1348066832.683 [PAR_Licor](ERROR): PAR reading out of range: -0.039737 uMol/s/m2 2012-09-19T15:00:32.891Z,1348066832.891 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree 2012-09-19T15:00:32.892Z,1348066832.892 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree 2012-09-19T15:00:33.346Z,1348066833.346 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool 2012-09-19T15:00:53.442Z,1348066853.442 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2 2012-09-19T15:00:55.042Z,1348066855.042 [PAR_Licor](ERROR): PAR reading out of range: -0.060401 uMol/s/m2 2012-09-19T15:00:55.842Z,1348066855.842 [PAR_Licor](ERROR): PAR reading out of range: -0.009537 uMol/s/m2 2012-09-19T15:00:57.058Z,1348066857.058 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2 2012-09-19T15:00:57.842Z,1348066857.842 [PAR_Licor](ERROR): PAR reading out of range: -0.019074 uMol/s/m2 2012-09-19T15:00:59.442Z,1348066859.442 [PAR_Licor](ERROR): PAR reading out of range: -0.012716 uMol/s/m2 2012-09-19T15:01:03.842Z,1348066863.842 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2 2012-09-19T15:01:05.466Z,1348066865.466 [PAR_Licor](ERROR): PAR reading out of range: -0.055632 uMol/s/m2 2012-09-19T15:01:06.242Z,1348066866.242 [PAR_Licor](ERROR): PAR reading out of range: -0.027021 uMol/s/m2 2012-09-19T15:01:09.042Z,1348066869.042 [PAR_Licor](ERROR): PAR reading out of range: -0.012716 uMol/s/m2 2012-09-19T15:01:11.442Z,1348066871.442 [PAR_Licor](ERROR): PAR reading out of range: -0.004768 uMol/s/m2 2012-09-19T15:01:14.658Z,1348066874.658 [PAR_Licor](ERROR): PAR reading out of range: -0.039737 uMol/s/m2 2012-09-19T15:01:15.442Z,1348066875.442 [PAR_Licor](ERROR): PAR reading out of range: -0.014305 uMol/s/m2 2012-09-19T15:01:16.642Z,1348066876.642 [PAR_Licor](ERROR): PAR reading out of range: 0.000000 uMol/s/m2