2012-10-17T19:02:39.660Z,1350500559.660 [Supervisor](DEBUG): Initializing supervisor.
2012-10-17T19:02:39.663Z,1350500559.663 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-10-17T19:02:39.664Z,1350500559.664 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-10-17T19:02:39.664Z,1350500559.664 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-10-17T19:02:39.669Z,1350500559.669 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-10-17T19:02:39.681Z,1350500559.681 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-10-17T19:02:39.682Z,1350500559.682 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-10-17T19:02:39.683Z,1350500559.683 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-10-17T19:02:39.683Z,1350500559.683 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-10-17T19:02:39.686Z,1350500559.686 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-10-17T19:02:40.043Z,1350500560.043 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-10-17T19:02:40.043Z,1350500560.043 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-10-17T19:02:40.228Z,1350500560.228 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-10-17T19:02:40.229Z,1350500560.229 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-10-17T19:02:40.312Z,1350500560.312 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-10-17T19:02:40.313Z,1350500560.313 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-10-17T19:02:40.520Z,1350500560.520 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-10-17T19:02:40.520Z,1350500560.520 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-10-17T19:02:40.656Z,1350500560.656 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-10-17T19:02:40.657Z,1350500560.657 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-10-17T19:02:40.896Z,1350500560.896 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-10-17T19:02:40.896Z,1350500560.896 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-10-17T19:02:41.067Z,1350500561.067 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-10-17T19:02:41.068Z,1350500561.068 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-10-17T19:02:41.332Z,1350500561.332 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-10-17T19:02:41.332Z,1350500561.332 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-10-17T19:02:41.430Z,1350500561.430 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-10-17T19:02:41.431Z,1350500561.431 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-10-17T19:02:41.848Z,1350500561.848 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-10-17T19:02:41.849Z,1350500561.849 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-10-17T19:02:41.961Z,1350500561.961 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-10-17T19:02:41.962Z,1350500561.962 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-10-17T19:02:42.044Z,1350500562.044 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-10-17T19:02:42.048Z,1350500562.048 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-10-17T19:02:42.147Z,1350500562.147 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-10-17T19:02:42.276Z,1350500562.276 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-10-17T19:02:42.359Z,1350500562.359 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-10-17T19:02:42.458Z,1350500562.458 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-10-17T19:02:42.557Z,1350500562.557 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-10-17T19:02:42.678Z,1350500562.678 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-10-17T19:02:42.843Z,1350500562.843 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-10-17T19:02:42.927Z,1350500562.927 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2012-10-17T19:02:42.958Z,1350500562.958 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-10-17T19:02:43.142Z,1350500563.142 [InternalSim] Loaded
2012-10-17T19:02:43.142Z,1350500563.142 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-10-17T19:02:43.143Z,1350500563.143 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-10-17T19:02:43.144Z,1350500563.144 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-10-17T19:02:43.224Z,1350500563.224 [SBIT](DEBUG): Construct Startup Built In Test.
2012-10-17T19:02:43.239Z,1350500563.239 [SBIT] Loaded
2012-10-17T19:02:43.239Z,1350500563.239 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-10-17T19:02:43.240Z,1350500563.240 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-10-17T19:02:43.269Z,1350500563.270 [IBIT] Loaded
2012-10-17T19:02:43.270Z,1350500563.270 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-10-17T19:02:43.273Z,1350500563.273 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-10-17T19:02:43.397Z,1350500563.397 [CBIT] Loaded
2012-10-17T19:02:43.398Z,1350500563.398 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-10-17T19:02:43.398Z,1350500563.398 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-10-17T19:02:43.399Z,1350500563.399 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-10-17T19:02:43.565Z,1350500563.565 [BuoyancyServo] Loaded
2012-10-17T19:02:43.565Z,1350500563.565 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-10-17T19:02:43.575Z,1350500563.575 [ElevatorServo] Loaded
2012-10-17T19:02:43.575Z,1350500563.575 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-10-17T19:02:43.588Z,1350500563.588 [RudderServo] Loaded
2012-10-17T19:02:43.589Z,1350500563.589 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-10-17T19:02:43.601Z,1350500563.601 [ThrusterServo] Loaded
2012-10-17T19:02:43.601Z,1350500563.601 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-10-17T19:02:43.602Z,1350500563.602 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-10-17T19:02:43.602Z,1350500563.602 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-10-17T19:02:43.635Z,1350500563.635 [DepthRateCalculator] Loaded
2012-10-17T19:02:43.635Z,1350500563.635 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-10-17T19:02:47.942Z,1350500567.942 [HFRadarModelCalc] Loaded
2012-10-17T19:02:47.943Z,1350500567.943 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-10-17T19:02:47.960Z,1350500567.960 [NavChart] Loaded
2012-10-17T19:02:47.960Z,1350500567.960 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-10-17T19:02:47.966Z,1350500567.966 [PitchRateCalculator] Loaded
2012-10-17T19:02:47.966Z,1350500567.967 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-10-17T19:02:47.973Z,1350500567.973 [SpeedCalculator] Loaded
2012-10-17T19:02:47.973Z,1350500567.973 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-10-17T19:02:47.989Z,1350500567.989 [TempGradientCalculator] Loaded
2012-10-17T19:02:47.989Z,1350500567.989 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-10-17T19:02:47.995Z,1350500567.995 [YawRateCalculator] Loaded
2012-10-17T19:02:47.995Z,1350500567.995 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-10-17T19:02:48.015Z,1350500568.015 [Navigation] Loaded
2012-10-17T19:02:48.016Z,1350500568.016 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-10-17T19:02:48.016Z,1350500568.016 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-10-17T19:02:48.017Z,1350500568.017 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-10-17T19:02:48.294Z,1350500568.294 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-10-17T19:02:48.295Z,1350500568.295 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-10-17T19:02:48.335Z,1350500568.335 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-10-17T19:02:48.336Z,1350500568.336 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-10-17T19:02:48.398Z,1350500568.398 [VerticalControl](DEBUG): Construct VerticalControl.
2012-10-17T19:02:48.445Z,1350500568.445 [VerticalControl] Loaded
2012-10-17T19:02:48.445Z,1350500568.445 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-10-17T19:02:48.446Z,1350500568.446 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-10-17T19:02:48.468Z,1350500568.468 [HorizontalControl] Loaded
2012-10-17T19:02:48.468Z,1350500568.468 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-10-17T19:02:48.469Z,1350500568.469 [SpeedControl](DEBUG): Construct SpeedControl.
2012-10-17T19:02:48.471Z,1350500568.471 [SpeedControl] Loaded
2012-10-17T19:02:48.471Z,1350500568.471 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-10-17T19:02:48.472Z,1350500568.472 [LoopControl](DEBUG): Construct LoopControl.
2012-10-17T19:02:48.473Z,1350500568.473 [LoopControl] Loaded
2012-10-17T19:02:48.473Z,1350500568.473 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-10-17T19:02:48.473Z,1350500568.473 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-10-17T19:02:48.474Z,1350500568.474 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-10-17T19:02:48.482Z,1350500568.482 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-10-17T19:02:48.487Z,1350500568.487 [AsyncPiEstimator] Loaded
2012-10-17T19:02:48.488Z,1350500568.487 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-10-17T19:02:48.489Z,1350500568.489 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406724E0
2012-10-17T19:02:48.489Z,1350500568.489 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-10-17T19:02:48.490Z,1350500568.490 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-10-17T19:02:48.663Z,1350500568.663 [AHRS_sp3003D] Loaded
2012-10-17T19:02:48.663Z,1350500568.663 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-10-17T19:02:48.936Z,1350500568.936 [Batt_Ocean_Server] Loaded
2012-10-17T19:02:48.936Z,1350500568.936 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-10-17T19:02:48.950Z,1350500568.950 [Depth_Keller] Loaded
2012-10-17T19:02:48.950Z,1350500568.950 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-10-17T19:02:48.956Z,1350500568.956 [DropWeight] Loaded
2012-10-17T19:02:48.956Z,1350500568.956 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-10-17T19:02:49.081Z,1350500569.081 [DVL_micro] Loaded
2012-10-17T19:02:49.081Z,1350500569.081 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-10-17T19:02:49.082Z,1350500569.082 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406F34E0
2012-10-17T19:02:49.170Z,1350500569.170 [NAL9602] Loaded
2012-10-17T19:02:49.170Z,1350500569.170 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-10-17T19:02:49.223Z,1350500569.223 [Onboard] Loaded
2012-10-17T19:02:49.223Z,1350500569.223 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-10-17T19:02:49.230Z,1350500569.230 [Radio_Freewave] Loaded
2012-10-17T19:02:49.230Z,1350500569.230 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-10-17T19:02:49.231Z,1350500569.231 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-10-17T19:02:49.232Z,1350500569.232 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-10-17T19:02:49.329Z,1350500569.329 [CTD_NeilBrown] Loaded
2012-10-17T19:02:49.330Z,1350500569.330 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-10-17T19:02:49.331Z,1350500569.331 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4074B4E0
2012-10-17T19:02:49.342Z,1350500569.342 [PAR_Licor] Loaded
2012-10-17T19:02:49.342Z,1350500569.342 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-10-17T19:02:49.360Z,1350500569.360 [Turbulence_NPS] Loaded
2012-10-17T19:02:49.361Z,1350500569.361 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-10-17T19:02:49.362Z,1350500569.362 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 4077B4E0
2012-10-17T19:02:49.393Z,1350500569.393 [WetLabsBB2FL] Loaded
2012-10-17T19:02:49.394Z,1350500569.394 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-10-17T19:02:49.395Z,1350500569.395 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407AB4E0
2012-10-17T19:02:49.395Z,1350500569.395 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-10-17T19:02:49.398Z,1350500569.398 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-10-17T19:02:49.399Z,1350500569.399 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-10-17T19:02:49.408Z,1350500569.408 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-10-17T19:02:49.410Z,1350500569.410 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407DB4E0
2012-10-17T19:02:49.415Z,1350500569.415 [Supervisor](DEBUG): Running supervisor.
2012-10-17T19:02:49.416Z,1350500569.416 [CommandLine](INFO): Thread ID is 5742
2012-10-17T19:02:49.420Z,1350500569.420 [controlThread](INFO): Thread ID is 5741
2012-10-17T19:02:49.420Z,1350500569.420 [controlThread](DEBUG): Initializing ControlThread
2012-10-17T19:02:49.420Z,1350500569.420 [CycleStarter](INFO): Thread ID is 5740
2012-10-17T19:02:49.421Z,1350500569.421 [InternalSim](DEBUG): InternalSim initializing...
2012-10-17T19:02:49.518Z,1350500569.518 [AsyncPiEstimator](INFO): Thread ID is 5803
2012-10-17T19:02:49.518Z,1350500569.518 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-10-17T19:02:49.581Z,1350500569.581 [DVL_micro](INFO): Thread ID is 5804
2012-10-17T19:02:49.658Z,1350500569.658 [CTD_NeilBrown](INFO): Thread ID is 5805
2012-10-17T19:02:49.659Z,1350500569.658 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-10-17T19:02:49.661Z,1350500569.661 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-10-17T19:02:49.682Z,1350500569.682 [DVL_micro](INFO): Initializing
2012-10-17T19:02:49.687Z,1350500569.687 [DVL_micro](INFO): start:Powering up
2012-10-17T19:02:49.688Z,1350500569.688 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-17T19:02:49.688Z,1350500569.688 [DVL_micro](INFO): Cycling power to configure device.
2012-10-17T19:02:49.705Z,1350500569.705 [Turbulence_NPS](INFO): Thread ID is 5806
2012-10-17T19:02:49.706Z,1350500569.705 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-10-17T19:02:49.706Z,1350500569.706 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1
2012-10-17T19:02:49.718Z,1350500569.718 [SBIT](INFO): Initialize SBIT Component.
2012-10-17T19:02:49.724Z,1350500569.724 [WetLabsBB2FL](INFO): Thread ID is 5807
2012-10-17T19:02:49.724Z,1350500569.724 [WetLabsBB2FL](INFO): Powering down
2012-10-17T19:02:49.743Z,1350500569.743 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9967
2012-10-17T19:02:49.743Z,1350500569.743 [IBIT](INFO): Initialize IBIT Component.
2012-10-17T19:02:49.744Z,1350500569.744 [CBIT](DEBUG): Initialize CBIT Component.
2012-10-17T19:02:49.745Z,1350500569.745 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2012-10-17T19:02:49.745Z,1350500569.745 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-10-17T19:02:49.752Z,1350500569.752 [NavChartDb](INFO): Thread ID is 5808
2012-10-17T19:02:49.758Z,1350500569.758 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-10-17T19:02:49.764Z,1350500569.764 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-10-17T19:02:49.764Z,1350500569.764 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-10-17T19:02:49.764Z,1350500569.764 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-10-17T19:02:49.765Z,1350500569.765 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-10-17T19:02:49.771Z,1350500569.772 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-10-17T19:02:49.772Z,1350500569.772 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-10-17T19:02:49.772Z,1350500569.772 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-10-17T19:02:49.773Z,1350500569.773 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-10-17T19:02:49.773Z,1350500569.773 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-10-17T19:02:49.774Z,1350500569.774 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-10-17T19:02:49.775Z,1350500569.775 [Navigation](DEBUG): Initializing Navigation.
2012-10-17T19:02:49.775Z,1350500569.775 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-10-17T19:02:49.777Z,1350500569.777 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-10-17T19:02:49.777Z,1350500569.777 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-10-17T19:02:49.778Z,1350500569.778 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-10-17T19:02:49.800Z,1350500569.800 [Turbulence_NPS](INFO): Pause powering down
2012-10-17T19:02:51.364Z,1350500571.364 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-10-17T19:02:51.388Z,1350500571.388 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-10-17T19:02:51.420Z,1350500571.420 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-17T19:02:51.430Z,1350500571.430 [MissionManager](DEBUG):
2012-10-17T19:02:51.431Z,1350500571.431 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-10-17T19:02:51.464Z,1350500571.464 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-10-17T19:02:51.466Z,1350500571.466 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-10-17T19:02:51.469Z,1350500571.469 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-17T19:02:51.477Z,1350500571.477 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-10-17T19:02:51.481Z,1350500571.481 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-17T19:02:51.487Z,1350500571.487 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-10-17T19:02:51.500Z,1350500571.500 [Default:D.SetSpeed](DEBUG): Construct.
2012-10-17T19:02:51.503Z,1350500571.503 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-17T19:02:51.508Z,1350500571.508 [Default:F.Wait](DEBUG): Construct Wait.
2012-10-17T19:02:51.511Z,1350500571.511 [MissionManager](DEBUG):
400
400
Burn 300
Dropped drop weight due to communications timeout
5.0
1.0
5
2012-10-17T19:02:51.515Z,1350500571.515 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,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,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-10-17T19:02:51.538Z,1350500571.538 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-10-17T19:02:51.907Z,1350500571.907 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-17T19:02:51.907Z,1350500571.907 [DVL_micro](INFO): Querying output modes
2012-10-17T19:02:51.908Z,1350500571.908 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606
2012-10-17T19:02:51.983Z,1350500571.983 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-10-17T19:02:51.983Z,1350500571.983 [DVL_micro](INFO): NQ1 output enabled
2012-10-17T19:02:51.983Z,1350500571.983 [DVL_micro](INFO): RSSI output enabled
2012-10-17T19:02:51.983Z,1350500571.983 [DVL_micro](INFO): ADCP output enabled
2012-10-17T19:02:51.984Z,1350500571.984 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525
2012-10-17T19:02:51.991Z,1350500571.991 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON
2012-10-17T19:02:51.996Z,1350500571.996 [DVL_micro](INFO): pause:Powering down
2012-10-17T19:02:52.001Z,1350500572.001 [Radio_Freewave](INFO): Powering up
2012-10-17T19:02:52.119Z,1350500572.119 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-10-17T19:02:52.123Z,1350500572.123 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-10-17T19:02:52.129Z,1350500572.129 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-10-17T19:02:52.130Z,1350500572.130 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-10-17T19:02:52.136Z,1350500572.136 [RudderServo](DEBUG): Initializing EZServoServo.
2012-10-17T19:02:52.139Z,1350500572.139 [RudderServo](DEBUG): Initializing RudderServo.
2012-10-17T19:02:52.145Z,1350500572.145 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-10-17T19:02:52.146Z,1350500572.146 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-10-17T19:02:55.253Z,1350500575.253 [NAL9602](INFO): Powering up NAL9602
2012-10-17T19:03:05.078Z,1350500585.078 [SBIT](IMPORTANT): Beginning Startup BIT
2012-10-17T19:03:05.084Z,1350500585.084 [CBIT](IMPORTANT): Beginning GF scan
2012-10-17T19:03:06.103Z,1350500586.103 [NAL9602](INFO): NAL9602 initialized
2012-10-17T19:03:33.961Z,1350500613.961 [CBIT](IMPORTANT): No ground fault detected
2012-10-17T19:03:58.293Z,1350500638.293 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2012-10-17T19:03:58.294Z,1350500638.294 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree
2012-10-17T19:03:58.933Z,1350500638.933 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2012-10-17T19:04:00.774Z,1350500640.774 [SBIT](IMPORTANT): SBIT PASSED
2012-10-17T19:04:01.044Z,1350500641.044 [MissionManager](IMPORTANT): Started mission Startup
2012-10-17T19:04:01.044Z,1350500641.044 [Startup] Running Loop=1
2012-10-17T19:04:01.044Z,1350500641.044 [Startup](INFO): Aggregate::initialize Startup
2012-10-17T19:04:01.045Z,1350500641.045 [Startup:A.GoToSurface] Running Loop=1
2012-10-17T19:04:01.045Z,1350500641.045 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-17T19:04:01.050Z,1350500641.050 [Startup:StartupSatComms] Running Loop=1
2012-10-17T19:04:01.051Z,1350500641.050 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-10-17T19:04:01.051Z,1350500641.051 [Startup:StartupSatComms:A] Running Loop=1
2012-10-17T19:04:01.382Z,1350500641.382 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-10-17T19:04:06.007Z,1350500646.007 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2012-10-17T19:04:06.007Z,1350500646.007 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree
2012-10-17T19:04:06.507Z,1350500646.507 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2012-10-17T19:04:07.626Z,1350500647.626 [Startup:StartupSatComms:A] Stopped
2012-10-17T19:04:07.626Z,1350500647.626 [Startup:StartupSatComms:B] Running Loop=1
2012-10-17T19:04:07.926Z,1350500647.926 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-10-17T19:04:14.645Z,1350500654.645 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2012-10-17T19:04:14.645Z,1350500654.645 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree
2012-10-17T19:04:15.320Z,1350500655.320 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2012-10-17T19:04:15.412Z,1350500655.412 [Startup:StartupSatComms:B] Stopped
2012-10-17T19:04:15.412Z,1350500655.412 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-10-17T19:04:15.412Z,1350500655.412 [Startup:StartupSatComms] Stopped
2012-10-17T19:04:15.412Z,1350500655.412 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-10-17T19:04:15.413Z,1350500655.413 [Startup](INFO): Completed Startup
2012-10-17T19:04:15.413Z,1350500655.413 [Startup] Stopped
2012-10-17T19:04:15.413Z,1350500655.413 [Startup](INFO): Aggregate::uninitialize Startup
2012-10-17T19:04:15.413Z,1350500655.413 [Startup:A.GoToSurface] Stopped
2012-10-17T19:04:15.414Z,1350500655.414 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-17T19:04:15.678Z,1350500655.678 [MissionManager](IMPORTANT): Started mission Default
2012-10-17T19:04:15.678Z,1350500655.678 [Default] Running Loop=1
2012-10-17T19:04:15.678Z,1350500655.678 [Default](INFO): Aggregate::initialize Default
2012-10-17T19:04:15.678Z,1350500655.678 [Default:D.SetSpeed] Running Loop=1
2012-10-17T19:04:15.679Z,1350500655.679 [Default:D.SetSpeed](DEBUG): Initialize.
2012-10-17T19:04:15.679Z,1350500655.679 [Default:E.GoToSurface] Running Loop=1
2012-10-17T19:04:15.679Z,1350500655.679 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-17T19:04:15.679Z,1350500655.679 [Default:Iridium] Running Loop=1
2012-10-17T19:04:15.679Z,1350500655.679 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-17T19:04:15.679Z,1350500655.679 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-17T19:04:15.679Z,1350500655.679 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-17T19:04:15.680Z,1350500655.680 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-17T19:04:15.680Z,1350500655.680 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-17T19:04:15.680Z,1350500655.680 [Default:E.GoToSurface] Running Loop=1
2012-10-17T19:04:15.685Z,1350500655.685 [Default:D.SetSpeed] Running Loop=1
2012-10-17T19:04:15.695Z,1350500655.695 [Default:Iridium:B.GoToSurface] Stopped
2012-10-17T19:04:15.695Z,1350500655.695 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-17T19:04:15.695Z,1350500655.695 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-17T19:04:15.695Z,1350500655.695 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-17T19:04:15.700Z,1350500655.700 [Default:GPS] Running Loop=1
2012-10-17T19:04:15.700Z,1350500655.700 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-10-17T19:04:15.700Z,1350500655.700 [Default:GPS:A.SetSpeed] Running Loop=1
2012-10-17T19:04:15.700Z,1350500655.700 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-10-17T19:04:15.700Z,1350500655.700 [Default:GPS:B.GoToSurface] Running Loop=1
2012-10-17T19:04:15.700Z,1350500655.700 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-17T19:04:15.705Z,1350500655.705 [Default:GPS:B.GoToSurface] Stopped
2012-10-17T19:04:15.705Z,1350500655.705 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-17T19:04:15.706Z,1350500655.705 [Default:GPS:Read_GPS] Running Loop=1
2012-10-17T19:04:15.706Z,1350500655.705 [Default:GPS:A.SetSpeed] Running Loop=1
2012-10-17T19:04:16.586Z,1350500656.586 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-10-17T19:04:16.589Z,1350500656.589 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-10-17T19:04:25.917Z,1350500665.917 [CommandLine](IMPORTANT): got command run ./Missions/Demo/science_on.xml
2012-10-17T19:04:25.917Z,1350500665.917 [MissionManager](INFO): Loading Mission: ./Missions/Demo/science_on.xml
2012-10-17T19:04:25.937Z,1350500665.937 [MissionManager](INFO): DefineArg science_on.MinAltitude = 1.000000 m
2012-10-17T19:04:25.940Z,1350500665.940 [MissionManager](INFO): DefineArg science_on.Timeout = 1.000000 h
2012-10-17T19:04:25.942Z,1350500665.941 [science_on:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-10-17T19:04:25.949Z,1350500665.949 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2012-10-17T19:04:26.046Z,1350500666.046 [MissionManager](INFO): DefineArg science_on:Science.SampleISUS = 0 bool
2012-10-17T19:04:26.049Z,1350500666.049 [MissionManager](INFO): DefineArg science_on:Science.SampleRSSI = 1 bool
2012-10-17T19:04:26.052Z,1350500666.052 [MissionManager](INFO): DefineArg science_on:Science.SampleADCP = 1 bool
2012-10-17T19:04:26.055Z,1350500666.055 [MissionManager](INFO): DefineArg science_on:Science.PeakDetectChlActive = 0 bool
2012-10-17T19:04:26.057Z,1350500666.057 [MissionManager](INFO): DefineArg science_on:Science.PeakDetectNO3Active = 0 bool
2012-10-17T19:04:26.060Z,1350500666.060 [MissionManager](INFO): DefineArg science_on:Science.PeakDetectRSSIActive = 0 bool
2012-10-17T19:04:26.064Z,1350500666.064 [MissionManager](INFO): DefineArg science_on:Science.EnabledAanderaaO2 = 0.000000 n/a
2012-10-17T19:04:26.067Z,1350500666.067 [MissionManager](INFO): DefineArg science_on:Science.EnabledNeilBrown = 1.000000 n/a
2012-10-17T19:04:26.071Z,1350500666.071 [MissionManager](INFO): DefineArg science_on:Science.EnabledTurbulence_NPS = 1.000000 n/a
2012-10-17T19:04:26.074Z,1350500666.074 [MissionManager](INFO): DefineArg science_on:Science.EnabledWetLabsBB2FL = 1.000000 n/a
2012-10-17T19:04:26.079Z,1350500666.079 [MissionManager](INFO): DefineArg science_on:Science.EnabledDVL = 1.000000 n/a
2012-10-17T19:04:26.083Z,1350500666.083 [MissionManager](INFO): DefineArg science_on:Science.EnabledISUS = 0.000000 n/a
2012-10-17T19:04:26.086Z,1350500666.086 [MissionManager](INFO): DefineOutput science_on:Science.PeakChl = 0.000000 ug/l
2012-10-17T19:04:26.089Z,1350500666.089 [MissionManager](INFO): DefineOutput science_on:Science.PeakChlDepth = 0.000000 m
2012-10-17T19:04:26.093Z,1350500666.093 [MissionManager](INFO): DefineOutput science_on:Science.PeakChlLatitude = nan arcdeg
2012-10-17T19:04:26.096Z,1350500666.096 [MissionManager](INFO): DefineOutput science_on:Science.PeakChlLongitude = nan arcdeg
2012-10-17T19:04:26.099Z,1350500666.099 [MissionManager](INFO): DefineOutput science_on:Science.PeakNO3 = 0.000000 umol/l
2012-10-17T19:04:26.102Z,1350500666.102 [MissionManager](INFO): DefineOutput science_on:Science.PeakNO3Depth = 0.000000 m
2012-10-17T19:04:26.105Z,1350500666.105 [MissionManager](INFO): DefineOutput science_on:Science.PeakNO3Latitude = nan arcdeg
2012-10-17T19:04:26.108Z,1350500666.109 [MissionManager](INFO): DefineOutput science_on:Science.PeakNO3Longitude = nan arcdeg
2012-10-17T19:04:26.112Z,1350500666.112 [MissionManager](INFO): DefineOutput science_on:Science.PeakRSSI = 0.000000 dB
2012-10-17T19:04:26.115Z,1350500666.115 [MissionManager](INFO): DefineOutput science_on:Science.PeakRSSIDepth = 0.000000 m
2012-10-17T19:04:26.118Z,1350500666.118 [MissionManager](INFO): DefineOutput science_on:Science.PeakRSSILatitude = nan arcdeg
2012-10-17T19:04:26.137Z,1350500666.137 [MissionManager](INFO): DefineOutput science_on:Science.PeakRSSILongitude = nan arcdeg
2012-10-17T19:04:26.153Z,1350500666.153 [science_on:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2012-10-17T19:04:26.161Z,1350500666.161 [science_on:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2012-10-17T19:04:26.179Z,1350500666.179 [science_on:Science:PeakDetectRSSI:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2012-10-17T19:04:26.206Z,1350500666.205 [science_on:C.Wait](DEBUG): Construct Wait.
2012-10-17T19:04:26.240Z,1350500666.240 [MissionManager](DEBUG):
Turns science on for a while.
Minimum height above the sea floor for the entire mission.
1.0
Maximum length of mission
1
Safety behavior that keeps vehicle off sea floor
If we're executing here or below, lets' get science data!
2012-10-17T19:04:26.241Z,1350500666.241 [CommandLine](IMPORTANT): Running ./Missions/Demo/science_on.xml
2012-10-17T19:04:26.701Z,1350500666.701 [Default] Stopped
2012-10-17T19:04:26.701Z,1350500666.701 [Default](INFO): Aggregate::uninitialize Default
2012-10-17T19:04:26.701Z,1350500666.701 [Default:GPS] Stopped
2012-10-17T19:04:26.701Z,1350500666.701 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-10-17T19:04:26.701Z,1350500666.701 [Default:GPS:A.SetSpeed] Stopped
2012-10-17T19:04:26.701Z,1350500666.701 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-10-17T19:04:26.701Z,1350500666.701 [Default:GPS:Read_GPS] Stopped
2012-10-17T19:04:26.701Z,1350500666.701 [Default:Iridium] Stopped
2012-10-17T19:04:26.701Z,1350500666.701 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-10-17T19:04:26.702Z,1350500666.702 [Default:Iridium:A.SetSpeed] Stopped
2012-10-17T19:04:26.702Z,1350500666.702 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-10-17T19:04:26.702Z,1350500666.702 [Default:Iridium:Read_Iridium] Stopped
2012-10-17T19:04:26.702Z,1350500666.702 [Default:D.SetSpeed] Stopped
2012-10-17T19:04:26.702Z,1350500666.702 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-10-17T19:04:26.702Z,1350500666.702 [Default:E.GoToSurface] Stopped
2012-10-17T19:04:26.702Z,1350500666.702 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-17T19:04:26.702Z,1350500666.702 [MissionManager](IMPORTANT): Started mission science_on
2012-10-17T19:04:26.702Z,1350500666.702 [science_on] Running Loop=1
2012-10-17T19:04:26.703Z,1350500666.703 [science_on](INFO): Aggregate::initialize science_on
2012-10-17T19:04:26.703Z,1350500666.703 [science_on:A.AltitudeEnvelope] Running Loop=1
2012-10-17T19:04:26.703Z,1350500666.703 [science_on:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-10-17T19:04:26.703Z,1350500666.703 [science_on:Science] Running Loop=1
2012-10-17T19:04:26.703Z,1350500666.703 [science_on:Science](INFO): Aggregate::initialize science_on:Science
2012-10-17T19:04:26.703Z,1350500666.703 [science_on:Science:A] Running Loop=1
2012-10-17T19:04:26.703Z,1350500666.703 [science_on:Science:B] Running Loop=1
2012-10-17T19:04:26.703Z,1350500666.703 [science_on:Science:C] Running Loop=1
2012-10-17T19:04:26.703Z,1350500666.704 [science_on:Science:D] Running Loop=1
2012-10-17T19:04:26.703Z,1350500666.704 [science_on:Science:E] Running Loop=1
2012-10-17T19:04:26.704Z,1350500666.704 [science_on:Science:F] Running Loop=1
2012-10-17T19:04:26.704Z,1350500666.704 [science_on:Science:G] Running Loop=1
2012-10-17T19:04:26.704Z,1350500666.704 [science_on:C.Wait] Running Loop=1
2012-10-17T19:04:26.704Z,1350500666.704 [science_on:C.Wait](DEBUG): Initialize Wait Component.
2012-10-17T19:04:26.709Z,1350500666.708 [science_on:Science] Running Loop=1
2012-10-17T19:04:26.709Z,1350500666.709 [science_on:Science:G] Running Loop=1
2012-10-17T19:04:26.710Z,1350500666.710 [science_on:Science:G](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2012-10-17T19:04:26.711Z,1350500666.711 [science_on:Science:F] Running Loop=1
2012-10-17T19:04:26.712Z,1350500666.712 [science_on:Science:F](DEBUG): Initialize ReadDataComponent to sense DVL_micro.Beam1RSSI
2012-10-17T19:04:26.713Z,1350500666.713 [science_on:Science:E] Running Loop=1
2012-10-17T19:04:26.714Z,1350500666.714 [science_on:Science:E](DEBUG): Initialize ReadDataComponent to sense DVL_micro.AdcpXWaterVelocity
2012-10-17T19:04:26.715Z,1350500666.716 [science_on:Science:D] Running Loop=1
2012-10-17T19:04:26.716Z,1350500666.716 [science_on:Science:D](DEBUG): Initialize ReadDataComponent to sense Turbulence_NPS.MicroCond
2012-10-17T19:04:26.717Z,1350500666.717 [science_on:Science:C] Running Loop=1
2012-10-17T19:04:26.718Z,1350500666.718 [science_on:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2012-10-17T19:04:26.719Z,1350500666.719 [science_on:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2012-10-17T19:04:26.720Z,1350500666.720 [science_on:A.AltitudeEnvelope] Running Loop=1
2012-10-17T19:04:26.817Z,1350500666.817 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-10-17T19:04:26.827Z,1350500666.827 [WetLabsBB2FL](INFO): Opening uart, block timeout 10ths=4
2012-10-17T19:04:26.827Z,1350500666.827 [WetLabsBB2FL](INFO): Powering up
2012-10-17T19:04:26.835Z,1350500666.835 [Turbulence_NPS](INFO): Resume powering up
2012-10-17T19:04:26.836Z,1350500666.836 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1
2012-10-17T19:04:26.839Z,1350500666.839 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-17T19:04:26.839Z,1350500666.839 [DVL_micro](INFO): resume:Powering up
2012-10-17T19:04:26.839Z,1350500666.839 [DVL_micro](INFO): Cycling power to configure device.
2012-10-17T19:04:28.436Z,1350500668.436 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.643350 psu
2012-10-17T19:04:28.640Z,1350500668.640 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.816380 psu
2012-10-17T19:04:28.840Z,1350500668.840 [CTD_NeilBrown](ERROR): Salinity reading out of range: -0.279880 psu
2012-10-17T19:04:28.847Z,1350500668.847 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-17T19:04:28.848Z,1350500668.848 [DVL_micro](INFO): Querying output modes
2012-10-17T19:04:28.848Z,1350500668.848 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606
2012-10-17T19:04:28.855Z,1350500668.855 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-10-17T19:04:28.855Z,1350500668.855 [DVL_micro](INFO): NQ1 output enabled
2012-10-17T19:04:28.855Z,1350500668.855 [DVL_micro](INFO): RSSI output enabled
2012-10-17T19:04:28.856Z,1350500668.856 [DVL_micro](INFO): ADCP output enabled
2012-10-17T19:04:28.856Z,1350500668.856 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525
2012-10-17T19:04:28.863Z,1350500668.863 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON
2012-10-17T19:04:28.999Z,1350500668.999 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=40
2012-10-17T19:04:29.040Z,1350500669.040 [CTD_NeilBrown](ERROR): Salinity reading out of range: -0.405710 psu
2012-10-17T19:04:29.056Z,1350500669.056 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=60
2012-10-17T19:04:29.107Z,1350500669.107 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=16
2012-10-17T19:04:29.160Z,1350500669.159 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=4
2012-10-17T19:04:29.244Z,1350500669.244 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.045330 psu
2012-10-17T19:04:29.439Z,1350500669.439 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=24
2012-10-17T19:04:29.444Z,1350500669.444 [CTD_NeilBrown](ERROR): Salinity reading out of range: -0.153220 psu
2012-10-17T19:04:29.544Z,1350500669.544 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=28
2012-10-17T19:04:29.636Z,1350500669.636 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.419200 psu
2012-10-17T19:04:29.637Z,1350500669.637 [CTD_NeilBrown](ERROR): Pressure reading out of range: -2295.920166 decibar
2012-10-17T19:04:29.643Z,1350500669.643 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=0
2012-10-17T19:04:29.748Z,1350500669.747 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=4
2012-10-17T19:04:29.836Z,1350500669.836 [CTD_NeilBrown](ERROR): Salinity reading out of range: -0.145990 psu
2012-10-17T19:04:29.883Z,1350500669.883 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=8
2012-10-17T19:04:29.940Z,1350500669.940 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=28
2012-10-17T19:04:29.992Z,1350500669.992 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=16
2012-10-17T19:04:30.040Z,1350500670.040 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.137400 psu
2012-10-17T19:04:30.048Z,1350500670.048 [DVL_micro](DEBUG): RSSI read bytes: 620 of 620, #buffered=4
2012-10-17T19:04:30.248Z,1350500670.248 [CTD_NeilBrown](ERROR): Salinity reading out of range: 4.049560 psu
2012-10-17T19:04:30.328Z,1350500670.328 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=24
2012-10-17T19:04:30.432Z,1350500670.432 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=60
2012-10-17T19:04:30.452Z,1350500670.452 [CTD_NeilBrown](ERROR): Salinity reading out of range: 6.301420 psu
2012-10-17T19:04:30.532Z,1350500670.532 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=0
2012-10-17T19:04:30.636Z,1350500670.636 [DVL_micro](DEBUG): RSSI read bytes: 1180 of 1180, #buffered=4
2012-10-17T19:04:30.655Z,1350500670.655 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.040620 psu
2012-10-17T19:04:30.863Z,1350500670.864 [CTD_NeilBrown](ERROR): Salinity reading out of range: 1.100080 psu
2012-10-17T19:04:30.984Z,1350500670.984 [DVL_micro](DEBUG): RSSI read bytes: 1660 of 1660, #buffered=56
2012-10-17T19:04:31.067Z,1350500671.067 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.223990 psu
2012-10-17T19:04:31.127Z,1350500671.127 [DVL_micro](DEBUG): RSSI read bytes: 1660 of 1660, #buffered=28
2012-10-17T19:04:31.271Z,1350500671.271 [DVL_micro](DEBUG): RSSI read bytes: 1660 of 1660, #buffered=32
2012-10-17T19:04:31.272Z,1350500671.272 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.923640 psu
2012-10-17T19:04:31.415Z,1350500671.415 [DVL_micro](DEBUG): RSSI read bytes: 1660 of 1660, #buffered=4
2012-10-17T19:04:31.479Z,1350500671.479 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.547090 psu
2012-10-17T19:04:31.683Z,1350500671.683 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.441690 psu
2012-10-17T19:04:31.758Z,1350500671.758 [DVL_micro](DEBUG): RSSI read bytes: 1336 of 1336, #buffered=252
2012-10-17T19:04:31.851Z,1350500671.852 [DVL_micro](DEBUG): RSSI read bytes: 1336 of 1336, #buffered=4
2012-10-17T19:04:31.887Z,1350500671.887 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.489970 psu
2012-10-17T19:04:31.972Z,1350500671.972 [DVL_micro](DEBUG): RSSI read bytes: 1336 of 1336, #buffered=44
2012-10-17T19:04:32.087Z,1350500672.088 [DVL_micro](DEBUG): RSSI read bytes: 1336 of 1336, #buffered=4
2012-10-17T19:04:32.092Z,1350500672.092 [CTD_NeilBrown](ERROR): Salinity reading out of range: 3.185050 psu
2012-10-17T19:04:32.296Z,1350500672.296 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.357300 psu
2012-10-17T19:04:32.500Z,1350500672.500 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.189390 psu
2012-10-17T19:04:32.612Z,1350500672.612 [DVL_micro](DEBUG): RSSI read bytes: 2712 of 2712, #buffered=28
2012-10-17T19:04:32.712Z,1350500672.712 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.134590 psu
2012-10-17T19:04:32.847Z,1350500672.847 [DVL_micro](DEBUG): RSSI read bytes: 2712 of 2712, #buffered=36
2012-10-17T19:04:32.905Z,1350500672.905 [CTD_NeilBrown](ERROR): Salinity reading out of range: -0.096910 psu
2012-10-17T19:04:33.083Z,1350500673.083 [DVL_micro](DEBUG): RSSI read bytes: 2712 of 2712, #buffered=12
2012-10-17T19:04:33.112Z,1350500673.112 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.104200 psu
2012-10-17T19:04:33.312Z,1350500673.312 [CTD_NeilBrown](ERROR): Salinity reading out of range: -6.066550 psu
2012-10-17T19:04:33.324Z,1350500673.323 [DVL_micro](DEBUG): RSSI read bytes: 2712 of 2712, #buffered=4
2012-10-17T19:04:33.516Z,1350500673.516 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.541360 psu
2012-10-17T19:04:33.725Z,1350500673.725 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.259180 psu
2012-10-17T19:04:34.020Z,1350500674.020 [CTD_NeilBrown](ERROR): Salinity reading out of range: -0.596030 psu
2012-10-17T19:04:34.227Z,1350500674.227 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.518530 psu
2012-10-17T19:04:34.239Z,1350500674.239 [DVL_micro](DEBUG): RSSI read bytes: 5432 of 5432, #buffered=28
2012-10-17T19:04:34.309Z,1350500674.309 [NAL9602](INFO): Powering down
2012-10-17T19:04:34.431Z,1350500674.431 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.201740 psu
2012-10-17T19:04:34.635Z,1350500674.635 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.552500 psu
2012-10-17T19:04:34.715Z,1350500674.715 [DVL_micro](DEBUG): RSSI read bytes: 5432 of 5432, #buffered=5
2012-10-17T19:04:34.840Z,1350500674.839 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.057520 psu
2012-10-17T19:04:35.047Z,1350500675.047 [CTD_NeilBrown](ERROR): Salinity reading out of range: 3.703220 psu
2012-10-17T19:04:35.191Z,1350500675.191 [DVL_micro](DEBUG): RSSI read bytes: 5432 of 5432, #buffered=13
2012-10-17T19:04:35.251Z,1350500675.251 [CTD_NeilBrown](ERROR): Salinity reading out of range: 1.033450 psu
2012-10-17T19:04:35.456Z,1350500675.456 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.179250 psu
2012-10-17T19:04:35.660Z,1350500675.659 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.262660 psu
2012-10-17T19:04:35.661Z,1350500675.661 [DVL_micro](DEBUG): RSSI read bytes: 5432 of 5432, #buffered=4
2012-10-17T19:04:35.674Z,1350500675.674 [CommandLine](IMPORTANT): got command stop
2012-10-17T19:04:35.868Z,1350500675.868 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.806870 psu
2012-10-17T19:04:36.001Z,1350500676.001 [science_on] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on](INFO): Aggregate::uninitialize science_on
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:A.AltitudeEnvelope] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science](INFO): Aggregate::uninitialize science_on:Science
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science:A] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science:B] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science:C] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science:D] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science:E] Stopped
2012-10-17T19:04:36.002Z,1350500676.002 [science_on:Science:F] Stopped
2012-10-17T19:04:36.004Z,1350500676.004 [science_on:Science:G] Stopped
2012-10-17T19:04:36.005Z,1350500676.005 [science_on:C.Wait] Stopped
2012-10-17T19:04:36.005Z,1350500676.005 [science_on:C.Wait](DEBUG): Uninitialize Wait Component.
2012-10-17T19:04:36.029Z,1350500676.029 [Turbulence_NPS](INFO): Pause powering down
2012-10-17T19:04:36.072Z,1350500676.072 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.115520 psu
2012-10-17T19:04:36.227Z,1350500676.227 [WetLabsBB2FL](INFO): Powering down
2012-10-17T19:04:36.353Z,1350500676.353 [MissionManager](IMPORTANT): Started mission Default
2012-10-17T19:04:36.353Z,1350500676.353 [Default] Running Loop=1
2012-10-17T19:04:36.353Z,1350500676.353 [Default](INFO): Aggregate::initialize Default
2012-10-17T19:04:36.353Z,1350500676.353 [Default:D.SetSpeed] Running Loop=1
2012-10-17T19:04:36.354Z,1350500676.353 [Default:D.SetSpeed](DEBUG): Initialize.
2012-10-17T19:04:36.354Z,1350500676.354 [Default:E.GoToSurface] Running Loop=1
2012-10-17T19:04:36.354Z,1350500676.354 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-17T19:04:36.354Z,1350500676.354 [Default:Iridium] Running Loop=1
2012-10-17T19:04:36.354Z,1350500676.354 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-17T19:04:36.354Z,1350500676.354 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-17T19:04:36.354Z,1350500676.354 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-17T19:04:36.354Z,1350500676.354 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-17T19:04:36.355Z,1350500676.355 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-17T19:04:36.356Z,1350500676.356 [Default:Iridium:B.GoToSurface] Stopped
2012-10-17T19:04:36.357Z,1350500676.357 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-17T19:04:36.357Z,1350500676.357 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-17T19:04:36.357Z,1350500676.357 [Default:GPS] Running Loop=1
2012-10-17T19:04:36.357Z,1350500676.357 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-10-17T19:04:36.357Z,1350500676.357 [Default:GPS:A.SetSpeed] Running Loop=1
2012-10-17T19:04:36.357Z,1350500676.357 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-10-17T19:04:36.357Z,1350500676.358 [Default:GPS:B.GoToSurface] Running Loop=1
2012-10-17T19:04:36.358Z,1350500676.358 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-17T19:04:36.358Z,1350500676.358 [Default:GPS:B.GoToSurface] Stopped
2012-10-17T19:04:36.358Z,1350500676.358 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-17T19:04:36.359Z,1350500676.359 [Default:GPS:Read_GPS] Running Loop=1
2012-10-17T19:04:36.543Z,1350500676.543 [DVL_micro](DEBUG): NQ1
2012-10-17T19:04:36.566Z,1350500676.566 [DVL_micro](INFO): pause:Powering down
2012-10-17T19:04:37.156Z,1350500677.156 [NAL9602](INFO): Powering up
2012-10-17T19:04:47.963Z,1350500687.963 [NAL9602](INFO): NAL9602 initialized
2012-10-17T19:04:51.840Z,1350500691.840 [CommandLine](IMPORTANT): got command quit
2012-10-17T19:04:52.959Z,1350500692.958 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2012-10-17T19:04:52.959Z,1350500692.959 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-10-17T19:04:53.343Z,1350500693.343 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2012-10-17T19:04:53.599Z,1350500693.599 [WetLabsBB2FL](INFO): Powering down
2012-10-17T19:04:53.611Z,1350500693.611 [ComponentRegistry](INFO): Shutting down Turbulence_NPS ThreadHandler
2012-10-17T19:04:53.819Z,1350500693.819 [Turbulence_NPS](INFO): Uninitialize Powering down
2012-10-17T19:04:53.831Z,1350500693.831 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-10-17T19:04:54.011Z,1350500694.011 [CTD_NeilBrown](INFO): Powering down
2012-10-17T19:04:54.031Z,1350500694.031 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2012-10-17T19:04:54.343Z,1350500694.343 [DVL_micro](INFO): uninitialize:Powering down
2012-10-17T19:04:54.352Z,1350500694.352 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-10-17T19:04:54.519Z,1350500694.519 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-10-17T19:04:54.536Z,1350500694.536 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-10-17T19:04:54.554Z,1350500694.554 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-10-17T19:04:54.748Z,1350500694.748 [controlThread](DEBUG): Uninitializing ControlThread
2012-10-17T19:04:54.749Z,1350500694.749 [AHRS_sp3003D](INFO): Powering down
2012-10-17T19:04:54.836Z,1350500694.836 [NAL9602](INFO): Powering down
2012-10-17T19:04:54.838Z,1350500694.838 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-10-17T19:04:54.838Z,1350500694.838 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-10-17T19:04:54.839Z,1350500694.839 [Default] Stopped
2012-10-17T19:04:54.840Z,1350500694.839 [Default](INFO): Aggregate::uninitialize Default
2012-10-17T19:04:54.840Z,1350500694.840 [Default:GPS] Stopped
2012-10-17T19:04:54.840Z,1350500694.840 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-10-17T19:04:54.840Z,1350500694.840 [Default:GPS:A.SetSpeed] Stopped
2012-10-17T19:04:54.840Z,1350500694.840 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-10-17T19:04:54.840Z,1350500694.840 [Default:GPS:Read_GPS] Stopped
2012-10-17T19:04:54.840Z,1350500694.840 [Default:Iridium] Stopped
2012-10-17T19:04:54.840Z,1350500694.840 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-10-17T19:04:54.840Z,1350500694.840 [Default:Iridium:A.SetSpeed] Stopped
2012-10-17T19:04:54.840Z,1350500694.840 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-10-17T19:04:54.840Z,1350500694.840 [Default:Iridium:Read_Iridium] Stopped
2012-10-17T19:04:54.840Z,1350500694.840 [Default:D.SetSpeed] Stopped
2012-10-17T19:04:54.840Z,1350500694.840 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-10-17T19:04:54.840Z,1350500694.841 [Default:E.GoToSurface] Stopped
2012-10-17T19:04:54.840Z,1350500694.841 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-17T19:04:54.844Z,1350500694.844 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-10-17T19:04:54.845Z,1350500694.845 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-10-17T19:04:54.845Z,1350500694.845 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-10-17T19:04:54.845Z,1350500694.845 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-10-17T19:04:54.846Z,1350500694.846 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-10-17T19:04:54.846Z,1350500694.846 [BuoyancyServo](INFO): Powering down
2012-10-17T19:04:54.851Z,1350500694.851 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-10-17T19:04:54.851Z,1350500694.851 [ElevatorServo](INFO): Powering down
2012-10-17T19:04:54.852Z,1350500694.852 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-10-17T19:04:54.852Z,1350500694.852 [RudderServo](INFO): Powering down
2012-10-17T19:04:54.853Z,1350500694.853 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-10-17T19:04:54.853Z,1350500694.853 [ThrusterServo](INFO): Powering down
2012-10-17T19:04:54.853Z,1350500694.853 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-10-17T19:04:54.854Z,1350500694.854 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-10-17T19:04:54.854Z,1350500694.854 [CBIT](DEBUG): Uninitialize CBIT Component.