2013-09-16T23:10:40.023Z,1379373040.023 [Supervisor](DEBUG): Initializing supervisor.
2013-09-16T23:10:40.026Z,1379373040.026 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-09-16T23:10:40.027Z,1379373040.027 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-09-16T23:10:40.028Z,1379373040.028 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-09-16T23:10:40.031Z,1379373040.031 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-09-16T23:10:40.042Z,1379373040.042 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-09-16T23:10:40.043Z,1379373040.043 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-09-16T23:10:40.044Z,1379373040.044 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-09-16T23:10:40.045Z,1379373040.045 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-09-16T23:10:40.045Z,1379373040.045 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-09-16T23:10:40.047Z,1379373040.047 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-09-16T23:10:40.327Z,1379373040.327 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-09-16T23:10:40.327Z,1379373040.327 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-09-16T23:10:40.519Z,1379373040.519 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-09-16T23:10:40.519Z,1379373040.519 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-09-16T23:10:40.603Z,1379373040.603 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-09-16T23:10:40.604Z,1379373040.604 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-09-16T23:10:40.714Z,1379373040.714 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-09-16T23:10:40.715Z,1379373040.715 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-09-16T23:10:40.858Z,1379373040.858 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-09-16T23:10:40.858Z,1379373040.858 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-09-16T23:10:41.096Z,1379373041.096 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-09-16T23:10:41.097Z,1379373041.097 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-09-16T23:10:41.261Z,1379373041.261 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-09-16T23:10:41.261Z,1379373041.261 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-09-16T23:10:41.523Z,1379373041.523 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-09-16T23:10:41.523Z,1379373041.523 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-09-16T23:10:41.624Z,1379373041.624 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-09-16T23:10:41.625Z,1379373041.625 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-09-16T23:10:42.038Z,1379373042.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-09-16T23:10:42.038Z,1379373042.038 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-09-16T23:10:42.149Z,1379373042.149 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-09-16T23:10:42.150Z,1379373042.150 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-09-16T23:10:42.236Z,1379373042.236 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-09-16T23:10:42.237Z,1379373042.237 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-09-16T23:10:42.333Z,1379373042.333 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-09-16T23:10:42.458Z,1379373042.458 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-09-16T23:10:42.552Z,1379373042.552 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-09-16T23:10:42.656Z,1379373042.656 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-09-16T23:10:42.750Z,1379373042.750 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-09-16T23:10:42.865Z,1379373042.865 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-09-16T23:10:42.959Z,1379373042.959 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-09-16T23:10:43.044Z,1379373043.044 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-09-16T23:10:43.045Z,1379373043.045 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-09-16T23:10:43.048Z,1379373043.048 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-09-16T23:10:43.214Z,1379373043.214 [InternalSim] Loaded
2013-09-16T23:10:43.214Z,1379373043.214 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-09-16T23:10:43.215Z,1379373043.215 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-09-16T23:10:43.215Z,1379373043.215 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-09-16T23:10:43.304Z,1379373043.304 [SBIT](DEBUG): Construct Startup Built In Test.
2013-09-16T23:10:43.333Z,1379373043.333 [SBIT] Loaded
2013-09-16T23:10:43.334Z,1379373043.334 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-09-16T23:10:43.334Z,1379373043.334 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-09-16T23:10:43.364Z,1379373043.364 [IBIT] Loaded
2013-09-16T23:10:43.365Z,1379373043.365 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-09-16T23:10:43.367Z,1379373043.367 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-09-16T23:10:43.484Z,1379373043.484 [CBIT] Loaded
2013-09-16T23:10:43.484Z,1379373043.484 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-09-16T23:10:43.485Z,1379373043.485 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-09-16T23:10:43.485Z,1379373043.485 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-09-16T23:10:43.657Z,1379373043.657 [BuoyancyServo] Loaded
2013-09-16T23:10:43.658Z,1379373043.658 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-09-16T23:10:43.670Z,1379373043.670 [ElevatorServo] Loaded
2013-09-16T23:10:43.670Z,1379373043.670 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-09-16T23:10:43.681Z,1379373043.681 [MassServo] Loaded
2013-09-16T23:10:43.682Z,1379373043.682 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-09-16T23:10:43.693Z,1379373043.693 [RudderServo] Loaded
2013-09-16T23:10:43.693Z,1379373043.693 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-09-16T23:10:43.705Z,1379373043.705 [ThrusterServo] Loaded
2013-09-16T23:10:43.705Z,1379373043.705 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-09-16T23:10:43.705Z,1379373043.705 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-09-16T23:10:43.706Z,1379373043.706 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-09-16T23:10:43.741Z,1379373043.741 [DepthRateCalculator] Loaded
2013-09-16T23:10:43.742Z,1379373043.742 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-09-16T23:10:46.925Z,1379373046.925 [HFRadarModelCalc] Loaded
2013-09-16T23:10:46.925Z,1379373046.925 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-09-16T23:10:46.942Z,1379373046.942 [NavChart] Loaded
2013-09-16T23:10:46.942Z,1379373046.942 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-09-16T23:10:46.948Z,1379373046.948 [PitchRateCalculator] Loaded
2013-09-16T23:10:46.948Z,1379373046.948 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-09-16T23:10:46.959Z,1379373046.959 [SpeedCalculator] Loaded
2013-09-16T23:10:46.959Z,1379373046.959 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-09-16T23:10:46.976Z,1379373046.976 [TempGradientCalculator] Loaded
2013-09-16T23:10:46.976Z,1379373046.976 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-09-16T23:10:46.982Z,1379373046.982 [YawRateCalculator] Loaded
2013-09-16T23:10:46.982Z,1379373046.982 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-09-16T23:10:47.030Z,1379373047.030 [Navigation] Loaded
2013-09-16T23:10:47.030Z,1379373047.030 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-09-16T23:10:47.031Z,1379373047.031 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-09-16T23:10:47.031Z,1379373047.031 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-09-16T23:10:47.275Z,1379373047.275 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-09-16T23:10:47.275Z,1379373047.275 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-09-16T23:10:47.299Z,1379373047.299 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-09-16T23:10:47.299Z,1379373047.299 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-09-16T23:10:47.348Z,1379373047.348 [VerticalControl](DEBUG): Construct VerticalControl.
2013-09-16T23:10:47.443Z,1379373047.443 [VerticalControl] Loaded
2013-09-16T23:10:47.444Z,1379373047.444 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-09-16T23:10:47.444Z,1379373047.444 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-09-16T23:10:47.503Z,1379373047.503 [HorizontalControl] Loaded
2013-09-16T23:10:47.503Z,1379373047.503 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-09-16T23:10:47.504Z,1379373047.504 [SpeedControl](DEBUG): Construct SpeedControl.
2013-09-16T23:10:47.506Z,1379373047.506 [SpeedControl] Loaded
2013-09-16T23:10:47.506Z,1379373047.506 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-09-16T23:10:47.507Z,1379373047.507 [LoopControl](DEBUG): Construct LoopControl.
2013-09-16T23:10:47.507Z,1379373047.507 [LoopControl] Loaded
2013-09-16T23:10:47.508Z,1379373047.508 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-09-16T23:10:47.508Z,1379373047.508 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-09-16T23:10:47.509Z,1379373047.509 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-09-16T23:10:47.515Z,1379373047.515 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-09-16T23:10:47.520Z,1379373047.520 [AsyncPiEstimator] Loaded
2013-09-16T23:10:47.520Z,1379373047.520 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-09-16T23:10:47.521Z,1379373047.521 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-09-16T23:10:47.522Z,1379373047.522 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-09-16T23:10:47.522Z,1379373047.522 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-09-16T23:10:47.720Z,1379373047.720 [AHRS_sp3003D] Loaded
2013-09-16T23:10:47.720Z,1379373047.720 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-09-16T23:10:47.734Z,1379373047.734 [Depth_Keller] Loaded
2013-09-16T23:10:47.734Z,1379373047.734 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-09-16T23:10:47.920Z,1379373047.920 [DVL_micro] Loaded
2013-09-16T23:10:47.921Z,1379373047.921 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-09-16T23:10:47.922Z,1379373047.922 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406CE4E0
2013-09-16T23:10:48.014Z,1379373048.014 [NAL9602] Loaded
2013-09-16T23:10:48.014Z,1379373048.014 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-09-16T23:10:48.058Z,1379373048.058 [Onboard] Loaded
2013-09-16T23:10:48.058Z,1379373048.058 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-09-16T23:10:48.065Z,1379373048.065 [Radio_Freewave] Loaded
2013-09-16T23:10:48.065Z,1379373048.065 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-09-16T23:10:48.208Z,1379373048.208 [DAT] Loaded
2013-09-16T23:10:48.209Z,1379373048.209 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-09-16T23:10:48.216Z,1379373048.216 [SCPI] Loaded
2013-09-16T23:10:48.216Z,1379373048.216 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2013-09-16T23:10:48.216Z,1379373048.216 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-09-16T23:10:48.217Z,1379373048.217 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-09-16T23:10:48.316Z,1379373048.316 [CTD_NeilBrown] Loaded
2013-09-16T23:10:48.317Z,1379373048.317 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-09-16T23:10:48.318Z,1379373048.318 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4072B4E0
2013-09-16T23:10:48.334Z,1379373048.334 [PAR_Licor] Loaded
2013-09-16T23:10:48.334Z,1379373048.334 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2013-09-16T23:10:48.367Z,1379373048.367 [WetLabsBB2FL] Loaded
2013-09-16T23:10:48.367Z,1379373048.367 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-09-16T23:10:48.368Z,1379373048.368 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2013-09-16T23:10:48.369Z,1379373048.369 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-09-16T23:10:48.372Z,1379373048.372 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-09-16T23:10:48.372Z,1379373048.372 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-09-16T23:10:48.379Z,1379373048.379 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-09-16T23:10:48.381Z,1379373048.381 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2013-09-16T23:10:48.385Z,1379373048.385 [Supervisor](DEBUG): Running supervisor.
2013-09-16T23:10:48.386Z,1379373048.386 [CommandLine](INFO): Thread ID is 1848
2013-09-16T23:10:48.388Z,1379373048.388 [controlThread](INFO): Thread ID is 1847
2013-09-16T23:10:48.388Z,1379373048.388 [controlThread](DEBUG): Initializing ControlThread
2013-09-16T23:10:48.389Z,1379373048.389 [CycleStarter](INFO): Thread ID is 1846
2013-09-16T23:10:48.389Z,1379373048.389 [InternalSim](DEBUG):  InternalSim initializing...
2013-09-16T23:10:48.424Z,1379373048.424 [logger](INFO): Thread ID is 1849
2013-09-16T23:10:48.450Z,1379373048.450 [SBIT](INFO): Initialize SBIT Component.
2013-09-16T23:10:48.450Z,1379373048.450 [SBIT](IMPORTANT): Tethys CM Info: 
$Rev:10634
2013-09-16T23:10:48.451Z,1379373048.451 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-09-16T23:10:48.451Z,1379373048.451 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-09-16T23:10:48.451Z,1379373048.451 [IBIT](INFO): Initialize IBIT Component.
2013-09-16T23:10:48.452Z,1379373048.452 [CBIT](DEBUG): Initialize CBIT Component.
2013-09-16T23:10:48.453Z,1379373048.453 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-09-16T23:10:48.464Z,1379373048.464 [AsyncPiEstimator](INFO): Thread ID is 1910
2013-09-16T23:10:48.464Z,1379373048.464 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-09-16T23:10:48.476Z,1379373048.476 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-09-16T23:10:48.477Z,1379373048.477 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-09-16T23:10:48.477Z,1379373048.477 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-09-16T23:10:48.478Z,1379373048.478 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-09-16T23:10:48.478Z,1379373048.478 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-09-16T23:10:48.478Z,1379373048.478 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-09-16T23:10:48.479Z,1379373048.479 [Navigation](DEBUG): Initializing Navigation.
2013-09-16T23:10:48.479Z,1379373048.479 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-09-16T23:10:48.481Z,1379373048.481 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-09-16T23:10:48.482Z,1379373048.482 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-09-16T23:10:48.482Z,1379373048.482 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-09-16T23:10:48.490Z,1379373048.490 [DVL_micro](INFO): Thread ID is 1911
2013-09-16T23:10:48.498Z,1379373048.498 [DVL_micro](INFO): Initializing
2013-09-16T23:10:48.499Z,1379373048.499 [DVL_micro](INFO): start:Powering up
2013-09-16T23:10:48.500Z,1379373048.500 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:10:48.500Z,1379373048.500 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:10:48.515Z,1379373048.515 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-09-16T23:10:48.524Z,1379373048.524 [CTD_NeilBrown](INFO): Thread ID is 1912
2013-09-16T23:10:48.524Z,1379373048.524 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-09-16T23:10:48.530Z,1379373048.530 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T23:10:48.531Z,1379373048.531 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-09-16T23:10:48.533Z,1379373048.533 [WetLabsBB2FL](INFO): Thread ID is 1913
2013-09-16T23:10:48.534Z,1379373048.534 [WetLabsBB2FL](INFO): Powering down
2013-09-16T23:10:48.588Z,1379373048.588 [NavChartDb](INFO): Thread ID is 1914
2013-09-16T23:10:48.591Z,1379373048.591 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-09-16T23:10:48.592Z,1379373048.592 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-09-16T23:10:48.592Z,1379373048.592 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-09-16T23:10:48.592Z,1379373048.592 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-09-16T23:10:48.593Z,1379373048.593 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-09-16T23:10:48.593Z,1379373048.593 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-09-16T23:10:48.593Z,1379373048.593 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-09-16T23:10:48.593Z,1379373048.593 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-09-16T23:10:48.594Z,1379373048.594 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-09-16T23:10:48.618Z,1379373048.618 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2013-09-16T23:10:48.618Z,1379373048.618 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-09-16T23:10:48.706Z,1379373048.706 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-09-16T23:10:48.712Z,1379373048.712 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-09-16T23:10:48.720Z,1379373048.720 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T23:10:48.760Z,1379373048.760 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-09-16T23:10:48.763Z,1379373048.763 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T23:10:48.783Z,1379373048.783 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-09-16T23:10:48.796Z,1379373048.796 [Default:D.SetSpeed](DEBUG): Construct.
2013-09-16T23:10:48.799Z,1379373048.799 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T23:10:48.820Z,1379373048.820 [Default:F.Wait](DEBUG): Construct Wait.
2013-09-16T23:10:48.864Z,1379373048.864 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS" >

        <When>
            <Arg Name="NeedGPS"/>
        </When>

<!-- Run at high speed -->

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

        <ReadDatum Id="Read_GPS">
            <Universal:latitude_fix/>
        </ReadDatum>

        <Assign><Arg Name="NeedGPS"/><False/></Assign>

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute RunIn="Sequence">
                    <Setting><Guidance:Execute.command/><String>Burn 300</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="CallIridium" >

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or><Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>

        <Assign><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

<!-- Wait forever at the surface-->

<!-- Run at low speed -->

    <Guidance:SetSpeed RunIn="Parallel">
        <Setting><Guidance:SetSpeed.period/><Units:second/><Value>5</Value></Setting>
    </Guidance:SetSpeed>

    <Guidance:GoToSurface RunIn="Parallel"/>

    <Guidance:Wait RunIn="Sequence"></Guidance:Wait>

</Mission>


2013-09-16T23:10:48.868Z,1379373048.868 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,SCPI,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,
2013-09-16T23:10:48.907Z,1379373048.907 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:10:48.927Z,1379373048.927 [Depth_Keller](ERROR): Pressure reading out of range: 1831.078247 decibar
2013-09-16T23:10:49.020Z,1379373049.020 [Radio_Freewave](INFO): Powering up
2013-09-16T23:10:49.061Z,1379373049.061 [DAT](INFO): Powering up
2013-09-16T23:10:49.062Z,1379373049.062 [DAT](DEBUG): Initializing DAT.
2013-09-16T23:10:49.390Z,1379373049.390 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T23:10:49.392Z,1379373049.392 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T23:10:49.410Z,1379373049.410 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-09-16T23:10:49.417Z,1379373049.417 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-09-16T23:10:49.423Z,1379373049.423 [MassServo](DEBUG): Initializing EZServoServo.
2013-09-16T23:10:49.449Z,1379373049.449 [MassServo](DEBUG): Initializing MassServo.
2013-09-16T23:10:49.454Z,1379373049.454 [RudderServo](DEBUG): Initializing EZServoServo.
2013-09-16T23:10:49.461Z,1379373049.461 [RudderServo](DEBUG): Initializing RudderServo.
2013-09-16T23:10:49.485Z,1379373049.485 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T23:10:49.493Z,1379373049.493 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T23:10:49.554Z,1379373049.554 [CBIT](FAULT): Main Battery Failure. Count: 1
2013-09-16T23:10:49.769Z,1379373049.769 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:10:49.769Z,1379373049.769 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0xA409A000
2013-09-16T23:10:49.769Z,1379373049.769 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:10:49.769Z,1379373049.769 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2013-09-16T23:10:49.770Z,1379373049.770 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:10:50.498Z,1379373050.498 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-09-16T23:10:50.498Z,1379373050.498 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-09-16T23:10:50.498Z,1379373050.498 [BuoyancyServo] Communications Fault, FailCount= 1
2013-09-16T23:10:50.498Z,1379373050.498 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T23:10:50.627Z,1379373050.627 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:10:50.628Z,1379373050.628 [DVL_micro](INFO): Querying output modes
2013-09-16T23:10:50.628Z,1379373050.628 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:10:50.709Z,1379373050.709 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T23:10:50.709Z,1379373050.709 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:10:50.751Z,1379373050.751 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:10:50.925Z,1379373050.925 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T23:10:50.926Z,1379373050.926 [BuoyancyServo](INFO): Powering down
2013-09-16T23:10:52.164Z,1379373052.164 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:10:52.164Z,1379373052.164 [AHRS_sp3003D] No Fault, FailCount= 1
2013-09-16T23:10:52.324Z,1379373052.324 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:10:52.633Z,1379373052.633 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:10:52.634Z,1379373052.634 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:10:52.634Z,1379373052.634 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:10:53.483Z,1379373053.483 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:10:53.483Z,1379373053.483 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:10:53.483Z,1379373053.483 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2013-09-16T23:10:53.483Z,1379373053.483 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:10:53.486Z,1379373053.486 [NAL9602](INFO): Powering up NAL9602
2013-09-16T23:10:53.750Z,1379373053.750 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T23:10:53.750Z,1379373053.750 [BuoyancyServo] No Fault, FailCount= 1
2013-09-16T23:10:53.750Z,1379373053.750 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:10:53.766Z,1379373053.766 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:10:53.902Z,1379373053.902 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T23:10:54.017Z,1379373054.017 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T23:10:54.637Z,1379373054.637 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:10:54.642Z,1379373054.642 [DVL_micro](INFO): pause:Powering down
2013-09-16T23:10:54.644Z,1379373054.644 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:10:54.649Z,1379373054.649 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:10:54.649Z,1379373054.649 [DVL_micro](INFO): resume:Powering up
2013-09-16T23:10:54.649Z,1379373054.649 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:10:55.304Z,1379373055.304 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:10:55.304Z,1379373055.304 [AHRS_sp3003D] No Fault, FailCount= 2
2013-09-16T23:10:55.625Z,1379373055.625 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:10:56.652Z,1379373056.652 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:10:56.652Z,1379373056.652 [DVL_micro](INFO): Querying output modes
2013-09-16T23:10:56.653Z,1379373056.653 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:10:56.772Z,1379373056.772 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:10:56.772Z,1379373056.772 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:10:56.772Z,1379373056.772 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2013-09-16T23:10:56.772Z,1379373056.772 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:10:56.909Z,1379373056.909 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:10:56.959Z,1379373056.959 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:10:58.211Z,1379373058.211 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:10:58.212Z,1379373058.212 [AHRS_sp3003D] No Fault, FailCount= 3
2013-09-16T23:10:58.530Z,1379373058.530 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:10:58.656Z,1379373058.656 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:10:58.657Z,1379373058.657 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:10:58.657Z,1379373058.657 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:10:59.680Z,1379373059.680 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:10:59.681Z,1379373059.681 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:10:59.681Z,1379373059.681 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2013-09-16T23:10:59.681Z,1379373059.681 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:10:59.757Z,1379373059.757 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:10:59.790Z,1379373059.790 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:11:00.658Z,1379373060.658 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:00.660Z,1379373060.660 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:11:00.661Z,1379373060.661 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:11:01.051Z,1379373061.051 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:11:01.051Z,1379373061.051 [AHRS_sp3003D] No Fault, FailCount= 4
2013-09-16T23:11:01.375Z,1379373061.375 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:11:02.509Z,1379373062.509 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:11:02.509Z,1379373062.509 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:11:02.509Z,1379373062.509 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2013-09-16T23:11:02.509Z,1379373062.509 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:11:02.653Z,1379373062.653 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:11:02.653Z,1379373062.653 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:11:02.677Z,1379373062.677 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:11:02.685Z,1379373062.685 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:11:02.686Z,1379373062.686 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:11:02.855Z,1379373062.855 [CommandLine](FAULT): Scheduling is paused
2013-09-16T23:11:03.954Z,1379373063.954 [SBIT](IMPORTANT): Beginning Startup BIT
2013-09-16T23:11:03.961Z,1379373063.961 [CBIT](IMPORTANT): Beginning GF scan
2013-09-16T23:11:04.336Z,1379373064.336 [NAL9602](INFO): NAL9602 initialized
2013-09-16T23:11:04.692Z,1379373064.692 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:04.692Z,1379373064.692 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:11:04.692Z,1379373064.692 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:11:06.703Z,1379373066.703 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:06.703Z,1379373066.703 [DVL_micro](INFO): Querying output modes
2013-09-16T23:11:06.704Z,1379373066.704 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:11:08.659Z,1379373068.659 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 550.000000 cubic_centimeter
2013-09-16T23:11:08.661Z,1379373068.661 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.buoyancyAction" handled in the control thread.
2013-09-16T23:11:08.707Z,1379373068.707 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:08.707Z,1379373068.707 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:11:08.707Z,1379373068.707 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:11:08.907Z,1379373068.907 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,SCPI,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.buoyancyAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-09-16T23:11:09.082Z,1379373069.082 [DAT](INFO): Powering down
2013-09-16T23:11:10.718Z,1379373070.718 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:12.721Z,1379373072.721 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:11:12.722Z,1379373072.722 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:11:14.724Z,1379373074.724 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:11:14.725Z,1379373074.725 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:11:15.962Z,1379373075.962 [CommandLine](IMPORTANT): got command report mod platform_buoyancy_position
2013-09-16T23:11:16.385Z,1379373076.385 [Reporter](INFO): platform_buoyancy_position 296.792947 cc
2013-09-16T23:11:16.735Z,1379373076.735 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:16.735Z,1379373076.735 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:11:16.735Z,1379373076.735 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:11:16.757Z,1379373076.757 [Reporter](INFO): platform_buoyancy_position 297.330145 cc
2013-09-16T23:11:17.167Z,1379373077.167 [Reporter](INFO): platform_buoyancy_position 299.076026 cc
2013-09-16T23:11:17.559Z,1379373077.559 [Reporter](INFO): platform_buoyancy_position 300.956250 cc
2013-09-16T23:11:17.955Z,1379373077.955 [Reporter](INFO): platform_buoyancy_position 301.224820 cc
2013-09-16T23:11:18.399Z,1379373078.399 [Reporter](INFO): platform_buoyancy_position 303.239329 cc
2013-09-16T23:11:18.746Z,1379373078.746 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:18.746Z,1379373078.746 [DVL_micro](INFO): Querying output modes
2013-09-16T23:11:18.746Z,1379373078.746 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:11:18.835Z,1379373078.835 [Reporter](INFO): platform_buoyancy_position 305.388123 cc
2013-09-16T23:11:19.905Z,1379373079.905 [Reporter](INFO): platform_buoyancy_position 305.522437 cc
2013-09-16T23:11:20.146Z,1379373080.146 [Reporter](INFO): platform_buoyancy_position 307.671231 cc
2013-09-16T23:11:20.514Z,1379373080.514 [Reporter](INFO): platform_buoyancy_position 309.820025 cc
2013-09-16T23:11:20.749Z,1379373080.749 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:20.749Z,1379373080.749 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:11:20.749Z,1379373080.749 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:11:20.911Z,1379373080.911 [Reporter](INFO): platform_buoyancy_position 311.834534 cc
2013-09-16T23:11:21.300Z,1379373081.300 [Reporter](INFO): platform_buoyancy_position 311.968848 cc
2013-09-16T23:11:21.736Z,1379373081.736 [Reporter](INFO): platform_buoyancy_position 314.117642 cc
2013-09-16T23:11:22.537Z,1379373082.537 [Reporter](INFO): platform_buoyancy_position 316.266436 cc
2013-09-16T23:11:22.756Z,1379373082.756 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:23.319Z,1379373083.319 [Reporter](INFO): platform_buoyancy_position 318.415230 cc
2013-09-16T23:11:23.699Z,1379373083.699 [Reporter](INFO): platform_buoyancy_position 320.429739 cc
2013-09-16T23:11:24.107Z,1379373084.107 [Reporter](INFO): platform_buoyancy_position 322.578533 cc
2013-09-16T23:11:24.548Z,1379373084.548 [Reporter](INFO): platform_buoyancy_position 322.712818 cc
2013-09-16T23:11:24.768Z,1379373084.768 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:11:24.768Z,1379373084.768 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:11:25.041Z,1379373085.041 [Reporter](INFO): platform_buoyancy_position 324.727327 cc
2013-09-16T23:11:25.366Z,1379373085.366 [Reporter](INFO): platform_buoyancy_position 324.861641 cc
2013-09-16T23:11:25.650Z,1379373085.650 [Reporter](INFO): platform_buoyancy_position 326.876121 cc
2013-09-16T23:11:26.115Z,1379373086.115 [Reporter](INFO): platform_buoyancy_position 329.159229 cc
2013-09-16T23:11:26.771Z,1379373086.771 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:11:26.771Z,1379373086.771 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:11:26.852Z,1379373086.852 [Reporter](INFO): platform_buoyancy_position 331.173738 cc
2013-09-16T23:11:27.245Z,1379373087.245 [Reporter](INFO): platform_buoyancy_position 331.308052 cc
2013-09-16T23:11:27.645Z,1379373087.645 [Reporter](INFO): platform_buoyancy_position 333.322532 cc
2013-09-16T23:11:28.043Z,1379373088.043 [Reporter](INFO): platform_buoyancy_position 335.471355 cc
2013-09-16T23:11:28.237Z,1379373088.237 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 330.000000 cubic_centimeter
2013-09-16T23:11:28.555Z,1379373088.555 [Reporter](INFO): platform_buoyancy_position 335.605611 cc
2013-09-16T23:11:28.778Z,1379373088.778 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:28.778Z,1379373088.778 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:11:28.778Z,1379373088.778 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:11:30.781Z,1379373090.781 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:30.781Z,1379373090.781 [DVL_micro](INFO): Querying output modes
2013-09-16T23:11:30.781Z,1379373090.781 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:11:30.808Z,1379373090.808 [CBIT](IMPORTANT): No ground fault detected
2013-09-16T23:11:32.788Z,1379373092.788 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:32.788Z,1379373092.788 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:11:32.788Z,1379373092.788 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:11:34.803Z,1379373094.803 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:36.809Z,1379373096.809 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:11:36.809Z,1379373096.809 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:11:38.813Z,1379373098.813 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:11:38.814Z,1379373098.814 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:11:40.820Z,1379373100.820 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:40.820Z,1379373100.820 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:11:40.821Z,1379373100.821 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:11:42.826Z,1379373102.826 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:42.826Z,1379373102.826 [DVL_micro](INFO): Querying output modes
2013-09-16T23:11:42.827Z,1379373102.827 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:11:44.850Z,1379373104.850 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:44.851Z,1379373104.851 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:11:44.851Z,1379373104.851 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:11:46.857Z,1379373106.857 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:48.865Z,1379373108.865 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:11:48.866Z,1379373108.866 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:11:50.524Z,1379373110.524 [CommandLine](IMPORTANT): got command maintain control VerticalControl.massPositionAction -2.000000 centimeter
2013-09-16T23:11:50.525Z,1379373110.525 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.massPositionAction" handled in the control thread.
2013-09-16T23:11:50.697Z,1379373110.697 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,SCPI,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.buoyancyAction,Maintain_VerticalControl.massPositionAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-09-16T23:11:50.868Z,1379373110.868 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:11:50.868Z,1379373110.868 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:11:52.879Z,1379373112.879 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:52.879Z,1379373112.879 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:11:52.879Z,1379373112.879 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:11:54.890Z,1379373114.890 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:54.890Z,1379373114.890 [DVL_micro](INFO): Querying output modes
2013-09-16T23:11:54.890Z,1379373114.890 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:11:56.901Z,1379373116.901 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:11:56.901Z,1379373116.901 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:11:56.901Z,1379373116.901 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:11:57.092Z,1379373117.092 [SBIT](FAULT): Mass: EXPECTED:0.000000 ACTUAL:-0.006684
2013-09-16T23:11:57.092Z,1379373117.092 [SBIT](FAULT): Control surface position failure.
2013-09-16T23:11:57.500Z,1379373117.500 [SBIT](CRITICAL): SBIT FAILED
2013-09-16T23:11:57.848Z,1379373117.848 [MissionManager](IMPORTANT): Started mission Startup
2013-09-16T23:11:57.848Z,1379373117.848 [Startup] Running Loop=1
2013-09-16T23:11:57.848Z,1379373117.848 [Startup](INFO): Aggregate::initialize Startup
2013-09-16T23:11:57.848Z,1379373117.848 [Startup:A.GoToSurface] Running Loop=1
2013-09-16T23:11:57.848Z,1379373117.848 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T23:11:57.863Z,1379373117.863 [Startup:StartupSatComms] Running Loop=1
2013-09-16T23:11:57.863Z,1379373117.863 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-09-16T23:11:57.863Z,1379373117.863 [Startup:StartupSatComms:A] Running Loop=1
2013-09-16T23:11:58.249Z,1379373118.249 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-09-16T23:11:58.908Z,1379373118.908 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:00.912Z,1379373120.912 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:12:00.912Z,1379373120.912 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:12:02.915Z,1379373122.915 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:12:02.915Z,1379373122.915 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:12:04.921Z,1379373124.921 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:04.922Z,1379373124.922 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:12:04.922Z,1379373124.922 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:12:06.933Z,1379373126.933 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:06.933Z,1379373126.933 [DVL_micro](INFO): Querying output modes
2013-09-16T23:12:06.933Z,1379373126.933 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:12:08.940Z,1379373128.940 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:08.940Z,1379373128.940 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:12:08.940Z,1379373128.940 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:12:10.951Z,1379373130.951 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:12.959Z,1379373132.959 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:12:12.959Z,1379373132.959 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:12:14.961Z,1379373134.961 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:12:14.962Z,1379373134.962 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:12:16.964Z,1379373136.964 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:16.964Z,1379373136.964 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:12:16.964Z,1379373136.964 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:12:18.971Z,1379373138.971 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:18.971Z,1379373138.971 [DVL_micro](INFO): Querying output modes
2013-09-16T23:12:18.972Z,1379373138.972 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:12:19.857Z,1379373139.857 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 215.000000 cubic_centimeter
2013-09-16T23:12:20.982Z,1379373140.982 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:20.983Z,1379373140.983 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:12:20.983Z,1379373140.983 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:12:21.517Z,1379373141.517 [Reporter](INFO): platform_buoyancy_position 338.023034 cc
2013-09-16T23:12:21.890Z,1379373141.890 [Reporter](INFO): platform_buoyancy_position 337.888720 cc
2013-09-16T23:12:22.287Z,1379373142.287 [Reporter](INFO): platform_buoyancy_position 337.754434 cc
2013-09-16T23:12:22.985Z,1379373142.985 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:23.092Z,1379373143.092 [Reporter](INFO): platform_buoyancy_position 337.620149 cc
2013-09-16T23:12:23.489Z,1379373143.489 [Reporter](INFO): platform_buoyancy_position 335.605611 cc
2013-09-16T23:12:23.890Z,1379373143.890 [Reporter](INFO): platform_buoyancy_position 333.322532 cc
2013-09-16T23:12:24.682Z,1379373144.682 [Reporter](INFO): platform_buoyancy_position 331.173738 cc
2013-09-16T23:12:24.989Z,1379373144.989 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:12:24.989Z,1379373144.989 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:12:25.087Z,1379373145.087 [Reporter](INFO): platform_buoyancy_position 329.696428 cc
2013-09-16T23:12:25.492Z,1379373145.492 [Reporter](INFO): platform_buoyancy_position 329.024944 cc
2013-09-16T23:12:25.888Z,1379373145.888 [Reporter](INFO): platform_buoyancy_position 326.876121 cc
2013-09-16T23:12:26.289Z,1379373146.289 [Reporter](INFO): platform_buoyancy_position 326.741807 cc
2013-09-16T23:12:26.686Z,1379373146.686 [Reporter](INFO): platform_buoyancy_position 324.861641 cc
2013-09-16T23:12:26.992Z,1379373146.992 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:12:26.992Z,1379373146.992 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:12:27.086Z,1379373147.086 [Reporter](INFO): platform_buoyancy_position 324.458728 cc
2013-09-16T23:12:27.483Z,1379373147.483 [Reporter](INFO): platform_buoyancy_position 322.578533 cc
2013-09-16T23:12:27.888Z,1379373147.888 [Reporter](INFO): platform_buoyancy_position 320.564024 cc
2013-09-16T23:12:28.288Z,1379373148.288 [Reporter](INFO): platform_buoyancy_position 320.429739 cc
2013-09-16T23:12:28.689Z,1379373148.689 [Reporter](INFO): platform_buoyancy_position 318.415230 cc
2013-09-16T23:12:29.009Z,1379373149.009 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:29.009Z,1379373149.009 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:12:29.009Z,1379373149.009 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:12:29.109Z,1379373149.109 [Reporter](INFO): platform_buoyancy_position 316.266436 cc
2013-09-16T23:12:29.887Z,1379373149.887 [Reporter](INFO): platform_buoyancy_position 314.117642 cc
2013-09-16T23:12:30.287Z,1379373150.287 [Reporter](INFO): platform_buoyancy_position 313.983328 cc
2013-09-16T23:12:30.683Z,1379373150.683 [Reporter](INFO): platform_buoyancy_position 311.834534 cc
2013-09-16T23:12:31.022Z,1379373151.022 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:31.022Z,1379373151.022 [DVL_micro](INFO): Querying output modes
2013-09-16T23:12:31.022Z,1379373151.022 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:12:31.092Z,1379373151.092 [Reporter](INFO): platform_buoyancy_position 311.700220 cc
2013-09-16T23:12:31.493Z,1379373151.493 [Reporter](INFO): platform_buoyancy_position 309.685740 cc
2013-09-16T23:12:31.890Z,1379373151.890 [Reporter](INFO): platform_buoyancy_position 307.671231 cc
2013-09-16T23:12:32.294Z,1379373152.294 [Reporter](INFO): platform_buoyancy_position 306.059635 cc
2013-09-16T23:12:32.691Z,1379373152.691 [Reporter](INFO): platform_buoyancy_position 305.522437 cc
2013-09-16T23:12:33.033Z,1379373153.033 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:33.033Z,1379373153.033 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:12:33.033Z,1379373153.033 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:12:33.091Z,1379373153.091 [Reporter](INFO): platform_buoyancy_position 303.507928 cc
2013-09-16T23:12:33.488Z,1379373153.488 [Reporter](INFO): platform_buoyancy_position 303.239329 cc
2013-09-16T23:12:33.893Z,1379373153.893 [Reporter](INFO): platform_buoyancy_position 301.224820 cc
2013-09-16T23:12:34.293Z,1379373154.293 [Reporter](INFO): platform_buoyancy_position 299.344625 cc
2013-09-16T23:12:34.693Z,1379373154.693 [Reporter](INFO): platform_buoyancy_position 298.941741 cc
2013-09-16T23:12:35.044Z,1379373155.044 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:35.091Z,1379373155.091 [Reporter](INFO): platform_buoyancy_position 296.927232 cc
2013-09-16T23:12:35.487Z,1379373155.487 [Reporter](INFO): platform_buoyancy_position 296.658633 cc
2013-09-16T23:12:35.888Z,1379373155.888 [Reporter](INFO): platform_buoyancy_position 294.644124 cc
2013-09-16T23:12:36.289Z,1379373156.289 [Reporter](INFO): platform_buoyancy_position 292.629644 cc
2013-09-16T23:12:37.052Z,1379373157.052 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:12:37.052Z,1379373157.052 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:12:37.090Z,1379373157.090 [Reporter](INFO): platform_buoyancy_position 290.480821 cc
2013-09-16T23:12:37.487Z,1379373157.487 [Reporter](INFO): platform_buoyancy_position 290.346536 cc
2013-09-16T23:12:37.887Z,1379373157.887 [Reporter](INFO): platform_buoyancy_position 288.197713 cc
2013-09-16T23:12:38.288Z,1379373158.288 [Reporter](INFO): platform_buoyancy_position 286.183233 cc
2013-09-16T23:12:38.695Z,1379373158.695 [Reporter](INFO): platform_buoyancy_position 285.914633 cc
2013-09-16T23:12:39.057Z,1379373159.057 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:12:39.057Z,1379373159.057 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:12:39.089Z,1379373159.089 [Reporter](INFO): platform_buoyancy_position 283.900154 cc
2013-09-16T23:12:39.481Z,1379373159.481 [Reporter](INFO): platform_buoyancy_position 283.362955 cc
2013-09-16T23:12:39.890Z,1379373159.890 [Reporter](INFO): platform_buoyancy_position 281.751330 cc
2013-09-16T23:12:40.286Z,1379373160.286 [Reporter](INFO): platform_buoyancy_position 279.602536 cc
2013-09-16T23:12:41.062Z,1379373161.062 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:41.062Z,1379373161.062 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:12:41.062Z,1379373161.062 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:12:41.088Z,1379373161.088 [Reporter](INFO): platform_buoyancy_position 277.453742 cc
2013-09-16T23:12:41.484Z,1379373161.484 [Reporter](INFO): platform_buoyancy_position 275.439234 cc
2013-09-16T23:12:41.889Z,1379373161.889 [Reporter](INFO): platform_buoyancy_position 275.304919 cc
2013-09-16T23:12:42.286Z,1379373162.286 [Reporter](INFO): platform_buoyancy_position 273.156125 cc
2013-09-16T23:12:42.686Z,1379373162.686 [Reporter](INFO): platform_buoyancy_position 272.484613 cc
2013-09-16T23:12:43.069Z,1379373163.069 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:43.069Z,1379373163.069 [DVL_micro](INFO): Querying output modes
2013-09-16T23:12:43.069Z,1379373163.069 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:12:43.083Z,1379373163.083 [Reporter](INFO): platform_buoyancy_position 271.141645 cc
2013-09-16T23:12:43.488Z,1379373163.488 [Reporter](INFO): platform_buoyancy_position 268.992822 cc
2013-09-16T23:12:43.888Z,1379373163.888 [Reporter](INFO): platform_buoyancy_position 268.858508 cc
2013-09-16T23:12:44.293Z,1379373164.293 [Reporter](INFO): platform_buoyancy_position 266.978343 cc
2013-09-16T23:12:44.690Z,1379373164.690 [Reporter](INFO): platform_buoyancy_position 266.575429 cc
2013-09-16T23:12:45.076Z,1379373165.076 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:45.076Z,1379373165.076 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:12:45.076Z,1379373165.076 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:12:45.086Z,1379373165.086 [Reporter](INFO): platform_buoyancy_position 264.560949 cc
2013-09-16T23:12:45.487Z,1379373165.487 [Reporter](INFO): platform_buoyancy_position 262.546411 cc
2013-09-16T23:12:45.895Z,1379373165.895 [Reporter](INFO): platform_buoyancy_position 262.412126 cc
2013-09-16T23:12:46.283Z,1379373166.283 [Reporter](INFO): platform_buoyancy_position 260.397646 cc
2013-09-16T23:12:46.689Z,1379373166.689 [Reporter](INFO): platform_buoyancy_position 258.248852 cc
2013-09-16T23:12:47.079Z,1379373167.079 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:47.086Z,1379373167.086 [Reporter](INFO): platform_buoyancy_position 258.114538 cc
2013-09-16T23:12:47.486Z,1379373167.486 [Reporter](INFO): platform_buoyancy_position 256.100029 cc
2013-09-16T23:12:47.887Z,1379373167.887 [Reporter](INFO): platform_buoyancy_position 255.965715 cc
2013-09-16T23:12:48.283Z,1379373168.283 [Reporter](INFO): platform_buoyancy_position 253.951235 cc
2013-09-16T23:12:48.683Z,1379373168.683 [Reporter](INFO): platform_buoyancy_position 251.936726 cc
2013-09-16T23:12:49.083Z,1379373169.083 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:12:49.084Z,1379373169.084 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:12:49.086Z,1379373169.086 [Reporter](INFO): platform_buoyancy_position 251.668127 cc
2013-09-16T23:12:49.489Z,1379373169.489 [Reporter](INFO): platform_buoyancy_position 249.922246 cc
2013-09-16T23:12:49.889Z,1379373169.889 [Reporter](INFO): platform_buoyancy_position 249.519304 cc
2013-09-16T23:12:50.294Z,1379373170.294 [Reporter](INFO): platform_buoyancy_position 247.370539 cc
2013-09-16T23:12:50.682Z,1379373170.682 [Reporter](INFO): platform_buoyancy_position 245.356030 cc
2013-09-16T23:12:51.083Z,1379373171.083 [Reporter](INFO): platform_buoyancy_position 245.221745 cc
2013-09-16T23:12:51.089Z,1379373171.089 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:12:51.090Z,1379373171.090 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:12:51.484Z,1379373171.484 [Reporter](INFO): platform_buoyancy_position 243.072936 cc
2013-09-16T23:12:51.896Z,1379373171.896 [Reporter](INFO): platform_buoyancy_position 242.267124 cc
2013-09-16T23:12:52.289Z,1379373172.289 [Reporter](INFO): platform_buoyancy_position 241.058442 cc
2013-09-16T23:12:52.690Z,1379373172.690 [Reporter](INFO): platform_buoyancy_position 238.909633 cc
2013-09-16T23:12:53.087Z,1379373173.087 [Reporter](INFO): platform_buoyancy_position 238.775334 cc
2013-09-16T23:12:53.092Z,1379373173.092 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:53.092Z,1379373173.092 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:12:53.093Z,1379373173.093 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:12:53.487Z,1379373173.487 [Reporter](INFO): platform_buoyancy_position 236.626525 cc
2013-09-16T23:12:53.888Z,1379373173.888 [Reporter](INFO): platform_buoyancy_position 234.880616 cc
2013-09-16T23:12:54.289Z,1379373174.289 [Reporter](INFO): platform_buoyancy_position 234.477717 cc
2013-09-16T23:12:54.685Z,1379373174.685 [Reporter](INFO): platform_buoyancy_position 232.597537 cc
2013-09-16T23:12:55.090Z,1379373175.090 [Reporter](INFO): platform_buoyancy_position 232.328923 cc
2013-09-16T23:12:55.099Z,1379373175.099 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:55.099Z,1379373175.099 [DVL_micro](INFO): Querying output modes
2013-09-16T23:12:55.100Z,1379373175.100 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:12:55.490Z,1379373175.490 [Reporter](INFO): platform_buoyancy_position 230.180114 cc
2013-09-16T23:12:55.887Z,1379373175.887 [Reporter](INFO): platform_buoyancy_position 228.299934 cc
2013-09-16T23:12:56.292Z,1379373176.292 [Reporter](INFO): platform_buoyancy_position 228.031335 cc
2013-09-16T23:12:56.688Z,1379373176.688 [Reporter](INFO): platform_buoyancy_position 225.882541 cc
2013-09-16T23:12:57.084Z,1379373177.084 [Reporter](INFO): platform_buoyancy_position 225.748227 cc
2013-09-16T23:12:57.110Z,1379373177.110 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:12:57.110Z,1379373177.110 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:12:57.111Z,1379373177.111 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:12:57.490Z,1379373177.490 [Reporter](INFO): platform_buoyancy_position 223.868046 cc
2013-09-16T23:12:58.253Z,1379373178.253 [Startup:StartupSatComms:A](INFO): Timed out from 2013-09-16T23:11:57.9Z
2013-09-16T23:12:58.253Z,1379373178.253 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-09-16T23:12:58.253Z,1379373178.253 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-09-16T23:12:58.253Z,1379373178.253 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-09-16T23:12:58.253Z,1379373178.253 [Startup:StartupSatComms:A] Stopped
2013-09-16T23:12:58.253Z,1379373178.253 [Startup:StartupSatComms:B] Running Loop=1
2013-09-16T23:12:58.648Z,1379373178.648 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-09-16T23:12:59.117Z,1379373179.117 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:01.129Z,1379373181.129 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:13:01.130Z,1379373181.130 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:13:03.132Z,1379373183.132 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:13:03.133Z,1379373183.133 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:13:05.143Z,1379373185.143 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:05.143Z,1379373185.143 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:13:05.143Z,1379373185.143 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:13:07.146Z,1379373187.146 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:07.146Z,1379373187.146 [DVL_micro](INFO): Querying output modes
2013-09-16T23:13:07.146Z,1379373187.146 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:13:09.149Z,1379373189.149 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:09.149Z,1379373189.149 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:13:09.149Z,1379373189.149 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:13:11.152Z,1379373191.152 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:13.160Z,1379373193.160 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:13:13.160Z,1379373193.160 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:13:15.163Z,1379373195.163 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:13:15.163Z,1379373195.163 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:13:17.169Z,1379373197.169 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:17.170Z,1379373197.170 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:13:17.170Z,1379373197.170 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:13:19.173Z,1379373199.173 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:19.173Z,1379373199.173 [DVL_micro](INFO): Querying output modes
2013-09-16T23:13:19.173Z,1379373199.173 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:13:21.184Z,1379373201.184 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:21.184Z,1379373201.184 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:13:21.184Z,1379373201.184 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:13:23.187Z,1379373203.187 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:25.195Z,1379373205.195 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:13:25.195Z,1379373205.195 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:13:26.996Z,1379373206.996 [CBIT](CRITICAL): Environmental Failure. Press:14.451184 PSI. Humidity:42%. Temp:21 C. ABORTING MISSION
2013-09-16T23:13:27.197Z,1379373207.197 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:13:27.198Z,1379373207.198 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:13:29.200Z,1379373209.200 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:29.200Z,1379373209.200 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:13:29.200Z,1379373209.200 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:13:31.203Z,1379373211.203 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:31.203Z,1379373211.203 [DVL_micro](INFO): Querying output modes
2013-09-16T23:13:31.204Z,1379373211.204 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:13:33.210Z,1379373213.210 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:33.210Z,1379373213.210 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:13:33.211Z,1379373213.211 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:13:35.213Z,1379373215.213 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:37.221Z,1379373217.221 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:13:37.221Z,1379373217.221 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:13:39.224Z,1379373219.224 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:13:39.224Z,1379373219.224 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:13:41.231Z,1379373221.231 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:41.231Z,1379373221.231 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:13:41.231Z,1379373221.231 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:13:43.234Z,1379373223.234 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:43.235Z,1379373223.235 [DVL_micro](INFO): Querying output modes
2013-09-16T23:13:43.235Z,1379373223.235 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:13:45.245Z,1379373225.245 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:45.245Z,1379373225.245 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:13:45.245Z,1379373225.245 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:13:47.248Z,1379373227.248 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:49.260Z,1379373229.260 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:13:49.260Z,1379373229.260 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:13:51.263Z,1379373231.263 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:13:51.263Z,1379373231.263 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:13:53.274Z,1379373233.274 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:53.274Z,1379373233.274 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:13:53.274Z,1379373233.274 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:13:55.281Z,1379373235.281 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:55.281Z,1379373235.281 [DVL_micro](INFO): Querying output modes
2013-09-16T23:13:55.281Z,1379373235.281 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:13:57.292Z,1379373237.292 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:13:57.292Z,1379373237.292 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:13:57.292Z,1379373237.292 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:13:58.687Z,1379373238.687 [Startup:StartupSatComms:B](INFO): Timed out from 2013-09-16T23:12:58.3Z
2013-09-16T23:13:58.687Z,1379373238.687 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-09-16T23:13:58.688Z,1379373238.688 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-09-16T23:13:58.688Z,1379373238.688 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-09-16T23:13:58.688Z,1379373238.688 [Startup:StartupSatComms:B] Stopped
2013-09-16T23:13:58.688Z,1379373238.688 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-09-16T23:13:58.688Z,1379373238.688 [Startup:StartupSatComms] Stopped
2013-09-16T23:13:58.688Z,1379373238.688 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-09-16T23:13:58.689Z,1379373238.689 [Startup](INFO): Completed Startup
2013-09-16T23:13:58.689Z,1379373238.689 [Startup] Stopped
2013-09-16T23:13:58.689Z,1379373238.689 [Startup](INFO): Aggregate::uninitialize Startup
2013-09-16T23:13:58.689Z,1379373238.689 [Startup:A.GoToSurface] Stopped
2013-09-16T23:13:58.689Z,1379373238.689 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-09-16T23:13:58.812Z,1379373238.812 [MissionManager](IMPORTANT): Started mission Default
2013-09-16T23:13:58.812Z,1379373238.812 [Default] Running Loop=1
2013-09-16T23:13:58.812Z,1379373238.812 [Default](INFO): Aggregate::initialize Default
2013-09-16T23:13:58.812Z,1379373238.812 [Default:D.SetSpeed] Running Loop=1
2013-09-16T23:13:58.812Z,1379373238.812 [Default:D.SetSpeed](DEBUG): Initialize.
2013-09-16T23:13:58.813Z,1379373238.813 [Default:E.GoToSurface] Running Loop=1
2013-09-16T23:13:58.813Z,1379373238.813 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T23:13:58.813Z,1379373238.813 [Default:Iridium] Running Loop=1
2013-09-16T23:13:58.813Z,1379373238.813 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-09-16T23:13:58.813Z,1379373238.813 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-09-16T23:13:58.813Z,1379373238.813 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-09-16T23:13:58.813Z,1379373238.813 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-09-16T23:13:58.813Z,1379373238.813 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T23:13:58.814Z,1379373238.814 [Default:E.GoToSurface] Running Loop=1
2013-09-16T23:13:58.819Z,1379373238.819 [Default:D.SetSpeed] Running Loop=1
2013-09-16T23:13:58.824Z,1379373238.824 [Default:CallIridium] Running Loop=1
2013-09-16T23:13:58.825Z,1379373238.825 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-09-16T23:13:58.825Z,1379373238.825 [Default:CallIridium:A] Running Loop=1
2013-09-16T23:13:58.843Z,1379373238.843 [Default:CallIridium:A] Stopped
2013-09-16T23:13:58.843Z,1379373238.843 [Default:CallIridium:B] Running Loop=1
2013-09-16T23:13:58.843Z,1379373238.843 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-09-16T23:13:58.856Z,1379373238.856 [Default:Iridium:B.GoToSurface] Stopped
2013-09-16T23:13:58.856Z,1379373238.856 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-09-16T23:13:58.856Z,1379373238.856 [Default:Iridium:Read_Iridium] Running Loop=1
2013-09-16T23:13:58.856Z,1379373238.856 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-09-16T23:13:58.861Z,1379373238.861 [Default:GPS] Running Loop=1
2013-09-16T23:13:58.861Z,1379373238.861 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-09-16T23:13:58.861Z,1379373238.861 [Default:GPS:A.SetSpeed] Running Loop=1
2013-09-16T23:13:58.861Z,1379373238.861 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-09-16T23:13:58.862Z,1379373238.862 [Default:GPS:B.GoToSurface] Running Loop=1
2013-09-16T23:13:58.862Z,1379373238.862 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T23:13:58.875Z,1379373238.875 [Default:GPS:B.GoToSurface] Stopped
2013-09-16T23:13:58.876Z,1379373238.876 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-09-16T23:13:58.876Z,1379373238.876 [Default:GPS:Read_GPS] Running Loop=1
2013-09-16T23:13:58.876Z,1379373238.876 [Default:GPS:A.SetSpeed] Running Loop=1
2013-09-16T23:13:59.160Z,1379373239.160 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-09-16T23:13:59.164Z,1379373239.164 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-09-16T23:13:59.295Z,1379373239.295 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:01.307Z,1379373241.307 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:14:01.307Z,1379373241.307 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:14:03.309Z,1379373243.309 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:14:03.310Z,1379373243.310 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:14:05.312Z,1379373245.312 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:05.312Z,1379373245.312 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:14:05.312Z,1379373245.312 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:14:07.315Z,1379373247.315 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:07.315Z,1379373247.315 [DVL_micro](INFO): Querying output modes
2013-09-16T23:14:07.316Z,1379373247.316 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:14:09.322Z,1379373249.322 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:09.322Z,1379373249.322 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:14:09.323Z,1379373249.323 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:14:11.338Z,1379373251.338 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:13.341Z,1379373253.341 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:14:13.341Z,1379373253.341 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:14:15.344Z,1379373255.344 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:14:15.344Z,1379373255.344 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:14:17.355Z,1379373257.355 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:17.355Z,1379373257.355 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:14:17.355Z,1379373257.355 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:14:19.366Z,1379373259.366 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:19.366Z,1379373259.366 [DVL_micro](INFO): Querying output modes
2013-09-16T23:14:19.366Z,1379373259.366 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:14:21.377Z,1379373261.377 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:21.377Z,1379373261.377 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:14:21.377Z,1379373261.377 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:14:23.380Z,1379373263.380 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:25.384Z,1379373265.384 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:14:25.384Z,1379373265.384 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:14:27.387Z,1379373267.387 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:14:27.387Z,1379373267.387 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:14:29.389Z,1379373269.389 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:29.390Z,1379373269.390 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:14:29.390Z,1379373269.390 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:14:31.397Z,1379373271.397 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:31.397Z,1379373271.397 [DVL_micro](INFO): Querying output modes
2013-09-16T23:14:31.397Z,1379373271.397 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:14:33.404Z,1379373273.404 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:33.404Z,1379373273.404 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:14:33.404Z,1379373273.404 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:14:33.977Z,1379373273.977 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 80.000000 cubic_centimeter
2013-09-16T23:14:35.415Z,1379373275.415 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:35.545Z,1379373275.545 [Reporter](INFO): platform_buoyancy_position 221.719238 cc
2013-09-16T23:14:36.715Z,1379373276.715 [Reporter](INFO): platform_buoyancy_position 221.584924 cc
2013-09-16T23:14:37.099Z,1379373277.099 [Reporter](INFO): platform_buoyancy_position 219.570429 cc
2013-09-16T23:14:37.446Z,1379373277.446 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:14:37.447Z,1379373277.447 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:14:37.512Z,1379373277.512 [Reporter](INFO): platform_buoyancy_position 219.301815 cc
2013-09-16T23:14:37.916Z,1379373277.916 [Reporter](INFO): platform_buoyancy_position 217.421635 cc
2013-09-16T23:14:38.798Z,1379373278.798 [Reporter](INFO): platform_buoyancy_position 215.138512 cc
2013-09-16T23:14:38.934Z,1379373278.934 [Reporter](INFO): platform_buoyancy_position 214.467043 cc
2013-09-16T23:14:39.287Z,1379373279.287 [Reporter](INFO): platform_buoyancy_position 213.124018 cc
2013-09-16T23:14:39.449Z,1379373279.449 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:14:39.450Z,1379373279.450 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:14:39.691Z,1379373279.691 [Reporter](INFO): platform_buoyancy_position 210.975224 cc
2013-09-16T23:14:40.096Z,1379373280.096 [Reporter](INFO): platform_buoyancy_position 210.840910 cc
2013-09-16T23:14:40.501Z,1379373280.501 [Reporter](INFO): platform_buoyancy_position 208.826415 cc
2013-09-16T23:14:40.889Z,1379373280.889 [Reporter](INFO): platform_buoyancy_position 207.483434 cc
2013-09-16T23:14:41.302Z,1379373281.302 [Reporter](INFO): platform_buoyancy_position 206.677607 cc
2013-09-16T23:14:41.456Z,1379373281.456 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:41.456Z,1379373281.456 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:14:41.456Z,1379373281.456 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:14:41.690Z,1379373281.690 [Reporter](INFO): platform_buoyancy_position 204.528842 cc
2013-09-16T23:14:42.984Z,1379373282.984 [Reporter](INFO): platform_buoyancy_position 200.096925 cc
2013-09-16T23:14:43.121Z,1379373283.121 [Reporter](INFO): platform_buoyancy_position 200.231225 cc
2013-09-16T23:14:43.459Z,1379373283.459 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:43.460Z,1379373283.460 [DVL_micro](INFO): Querying output modes
2013-09-16T23:14:43.460Z,1379373283.460 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:14:43.476Z,1379373283.476 [Reporter](INFO): platform_buoyancy_position 199.694026 cc
2013-09-16T23:14:43.890Z,1379373283.890 [Reporter](INFO): platform_buoyancy_position 198.082431 cc
2013-09-16T23:14:44.294Z,1379373284.294 [Reporter](INFO): platform_buoyancy_position 195.933622 cc
2013-09-16T23:14:44.688Z,1379373284.688 [Reporter](INFO): platform_buoyancy_position 195.799323 cc
2013-09-16T23:14:45.079Z,1379373285.079 [Reporter](INFO): platform_buoyancy_position 193.784814 cc
2013-09-16T23:14:45.477Z,1379373285.477 [Reporter](INFO): platform_buoyancy_position 193.113316 cc
2013-09-16T23:14:45.478Z,1379373285.478 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:45.478Z,1379373285.478 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:14:45.478Z,1379373285.478 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:14:45.890Z,1379373285.890 [Reporter](INFO): platform_buoyancy_position 191.636020 cc
2013-09-16T23:14:46.782Z,1379373286.782 [Reporter](INFO): platform_buoyancy_position 189.352941 cc
2013-09-16T23:14:46.879Z,1379373286.879 [Reporter](INFO): platform_buoyancy_position 187.472717 cc
2013-09-16T23:14:47.271Z,1379373287.271 [Reporter](INFO): platform_buoyancy_position 187.338446 cc
2013-09-16T23:14:47.486Z,1379373287.486 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:47.688Z,1379373287.688 [Reporter](INFO): platform_buoyancy_position 185.189638 cc
2013-09-16T23:14:48.088Z,1379373288.088 [Reporter](INFO): platform_buoyancy_position 184.786710 cc
2013-09-16T23:14:48.489Z,1379373288.489 [Reporter](INFO): platform_buoyancy_position 182.906530 cc
2013-09-16T23:14:48.893Z,1379373288.893 [Reporter](INFO): platform_buoyancy_position 181.026335 cc
2013-09-16T23:14:49.270Z,1379373289.270 [Reporter](INFO): platform_buoyancy_position 180.892035 cc
2013-09-16T23:14:49.493Z,1379373289.493 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:14:49.493Z,1379373289.493 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:14:49.679Z,1379373289.679 [Reporter](INFO): platform_buoyancy_position 178.608912 cc
2013-09-16T23:14:50.087Z,1379373290.087 [Reporter](INFO): platform_buoyancy_position 177.937443 cc
2013-09-16T23:14:50.981Z,1379373290.981 [Reporter](INFO): platform_buoyancy_position 174.445624 cc
2013-09-16T23:14:51.125Z,1379373291.125 [Reporter](INFO): platform_buoyancy_position 174.311310 cc
2013-09-16T23:14:51.490Z,1379373291.490 [Reporter](INFO): platform_buoyancy_position 172.296815 cc
2013-09-16T23:14:51.496Z,1379373291.496 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:14:51.497Z,1379373291.497 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:14:51.887Z,1379373291.887 [Reporter](INFO): platform_buoyancy_position 172.162530 cc
2013-09-16T23:14:52.299Z,1379373292.299 [Reporter](INFO): platform_buoyancy_position 170.148007 cc
2013-09-16T23:14:52.688Z,1379373292.688 [Reporter](INFO): platform_buoyancy_position 167.999242 cc
2013-09-16T23:14:53.056Z,1379373293.056 [Reporter](INFO): platform_buoyancy_position 167.864928 cc
2013-09-16T23:14:53.461Z,1379373293.461 [Reporter](INFO): platform_buoyancy_position 165.984704 cc
2013-09-16T23:14:53.503Z,1379373293.503 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:53.503Z,1379373293.503 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:14:53.503Z,1379373293.503 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:14:53.901Z,1379373293.901 [Reporter](INFO): platform_buoyancy_position 165.716119 cc
2013-09-16T23:14:54.783Z,1379373294.783 [Reporter](INFO): platform_buoyancy_position 161.552831 cc
2013-09-16T23:14:54.923Z,1379373294.923 [Reporter](INFO): platform_buoyancy_position 161.418517 cc
2013-09-16T23:14:55.510Z,1379373295.510 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:55.510Z,1379373295.510 [DVL_micro](INFO): Querying output modes
2013-09-16T23:14:55.510Z,1379373295.510 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:14:55.688Z,1379373295.688 [Reporter](INFO): platform_buoyancy_position 159.404022 cc
2013-09-16T23:14:56.089Z,1379373296.089 [Reporter](INFO): platform_buoyancy_position 157.120914 cc
2013-09-16T23:14:56.505Z,1379373296.505 [Reporter](INFO): platform_buoyancy_position 157.255214 cc
2013-09-16T23:14:56.890Z,1379373296.890 [Reporter](INFO): platform_buoyancy_position 155.106420 cc
2013-09-16T23:14:57.255Z,1379373297.255 [Reporter](INFO): platform_buoyancy_position 154.434907 cc
2013-09-16T23:14:57.521Z,1379373297.521 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:57.521Z,1379373297.521 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:14:57.521Z,1379373297.521 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:14:57.679Z,1379373297.679 [Reporter](INFO): platform_buoyancy_position 152.823297 cc
2013-09-16T23:14:58.099Z,1379373298.099 [Reporter](INFO): platform_buoyancy_position 150.808803 cc
2013-09-16T23:14:58.985Z,1379373298.985 [Reporter](INFO): platform_buoyancy_position 148.525723 cc
2013-09-16T23:14:59.478Z,1379373299.478 [Reporter](INFO): platform_buoyancy_position 146.511200 cc
2013-09-16T23:14:59.529Z,1379373299.529 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:14:59.887Z,1379373299.887 [Reporter](INFO): platform_buoyancy_position 145.839716 cc
2013-09-16T23:15:00.288Z,1379373300.288 [Reporter](INFO): platform_buoyancy_position 144.362421 cc
2013-09-16T23:15:00.689Z,1379373300.689 [Reporter](INFO): platform_buoyancy_position 142.616511 cc
2013-09-16T23:15:01.089Z,1379373301.089 [Reporter](INFO): platform_buoyancy_position 142.213627 cc
2013-09-16T23:15:01.477Z,1379373301.477 [Reporter](INFO): platform_buoyancy_position 139.930518 cc
2013-09-16T23:15:01.532Z,1379373301.532 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:15:01.532Z,1379373301.532 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:15:01.890Z,1379373301.890 [Reporter](INFO): platform_buoyancy_position 137.916009 cc
2013-09-16T23:15:02.779Z,1379373302.779 [Reporter](INFO): platform_buoyancy_position 135.767215 cc
2013-09-16T23:15:03.260Z,1379373303.260 [Reporter](INFO): platform_buoyancy_position 133.618407 cc
2013-09-16T23:15:03.535Z,1379373303.535 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:15:03.535Z,1379373303.535 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:15:03.696Z,1379373303.696 [Reporter](INFO): platform_buoyancy_position 133.484107 cc
2013-09-16T23:15:04.097Z,1379373304.097 [Reporter](INFO): platform_buoyancy_position 131.335328 cc
2013-09-16T23:15:04.498Z,1379373304.498 [Reporter](INFO): platform_buoyancy_position 129.589418 cc
2013-09-16T23:15:04.854Z,1379373304.854 [Reporter](INFO): platform_buoyancy_position 129.320804 cc
2013-09-16T23:15:05.259Z,1379373305.259 [Reporter](INFO): platform_buoyancy_position 127.440624 cc
2013-09-16T23:15:05.542Z,1379373305.542 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:05.542Z,1379373305.542 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:15:05.542Z,1379373305.542 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:15:05.725Z,1379373305.725 [Reporter](INFO): platform_buoyancy_position 126.634826 cc
2013-09-16T23:15:06.104Z,1379373306.104 [Reporter](INFO): platform_buoyancy_position 125.023216 cc
2013-09-16T23:15:07.011Z,1379373307.011 [Reporter](INFO): platform_buoyancy_position 122.740123 cc
2013-09-16T23:15:07.274Z,1379373307.274 [Reporter](INFO): platform_buoyancy_position 120.725606 cc
2013-09-16T23:15:07.515Z,1379373307.515 [Reporter](INFO): platform_buoyancy_position 120.591314 cc
2013-09-16T23:15:07.545Z,1379373307.545 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:07.545Z,1379373307.545 [DVL_micro](INFO): Querying output modes
2013-09-16T23:15:07.545Z,1379373307.545 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:15:07.919Z,1379373307.919 [Reporter](INFO): platform_buoyancy_position 118.442513 cc
2013-09-16T23:15:08.324Z,1379373308.324 [Reporter](INFO): platform_buoyancy_position 118.308220 cc
2013-09-16T23:15:08.708Z,1379373308.708 [Reporter](INFO): platform_buoyancy_position 116.428018 cc
2013-09-16T23:15:09.093Z,1379373309.093 [Reporter](INFO): platform_buoyancy_position 114.413502 cc
2013-09-16T23:15:09.490Z,1379373309.490 [Reporter](INFO): platform_buoyancy_position 114.279210 cc
2013-09-16T23:15:09.548Z,1379373309.548 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:09.548Z,1379373309.548 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:15:09.548Z,1379373309.548 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:15:09.894Z,1379373309.894 [Reporter](INFO): platform_buoyancy_position 111.996116 cc
2013-09-16T23:15:10.808Z,1379373310.808 [Reporter](INFO): platform_buoyancy_position 109.847315 cc
2013-09-16T23:15:11.292Z,1379373311.292 [Reporter](INFO): platform_buoyancy_position 107.832821 cc
2013-09-16T23:15:11.559Z,1379373311.559 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:11.697Z,1379373311.697 [Reporter](INFO): platform_buoyancy_position 105.684012 cc
2013-09-16T23:15:12.094Z,1379373312.094 [Reporter](INFO): platform_buoyancy_position 105.549705 cc
2013-09-16T23:15:12.506Z,1379373312.506 [Reporter](INFO): platform_buoyancy_position 103.669518 cc
2013-09-16T23:15:12.886Z,1379373312.886 [Reporter](INFO): platform_buoyancy_position 103.535211 cc
2013-09-16T23:15:13.292Z,1379373313.292 [Reporter](INFO): platform_buoyancy_position 101.252110 cc
2013-09-16T23:15:13.567Z,1379373313.567 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:15:13.567Z,1379373313.567 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:15:13.704Z,1379373313.704 [Reporter](INFO): platform_buoyancy_position 99.237615 cc
2013-09-16T23:15:14.096Z,1379373314.096 [Reporter](INFO): platform_buoyancy_position 99.103308 cc
2013-09-16T23:15:14.994Z,1379373314.994 [Reporter](INFO): platform_buoyancy_position 94.940013 cc
2013-09-16T23:15:15.569Z,1379373315.569 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:15:15.570Z,1379373315.570 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:15:15.888Z,1379373315.888 [Reporter](INFO): platform_buoyancy_position 92.656912 cc
2013-09-16T23:15:16.300Z,1379373316.300 [Reporter](INFO): platform_buoyancy_position 90.508111 cc
2013-09-16T23:15:17.090Z,1379373317.090 [Reporter](INFO): platform_buoyancy_position 88.359309 cc
2013-09-16T23:15:17.580Z,1379373317.580 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:17.580Z,1379373317.580 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:15:17.580Z,1379373317.580 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:15:19.587Z,1379373319.587 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:19.587Z,1379373319.587 [DVL_micro](INFO): Querying output modes
2013-09-16T23:15:19.588Z,1379373319.588 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:15:21.598Z,1379373321.598 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:21.599Z,1379373321.599 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:15:21.599Z,1379373321.599 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:15:23.606Z,1379373323.606 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:25.617Z,1379373325.617 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:15:25.618Z,1379373325.618 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:15:27.620Z,1379373327.620 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:15:27.621Z,1379373327.621 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:15:29.639Z,1379373329.639 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:29.639Z,1379373329.639 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:15:29.639Z,1379373329.639 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:15:31.646Z,1379373331.646 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:31.646Z,1379373331.646 [DVL_micro](INFO): Querying output modes
2013-09-16T23:15:31.646Z,1379373331.646 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:15:33.653Z,1379373333.653 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:33.653Z,1379373333.653 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:15:33.654Z,1379373333.654 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:15:35.665Z,1379373335.665 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:36.518Z,1379373336.518 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 30.000000 cubic_centimeter
2013-09-16T23:15:37.672Z,1379373337.672 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:15:37.672Z,1379373337.672 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:15:38.122Z,1379373338.122 [Reporter](INFO): platform_buoyancy_position 86.344808 cc
2013-09-16T23:15:38.494Z,1379373338.494 [Reporter](INFO): platform_buoyancy_position 86.210501 cc
2013-09-16T23:15:38.899Z,1379373338.899 [Reporter](INFO): platform_buoyancy_position 86.344808 cc
2013-09-16T23:15:39.675Z,1379373339.675 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:15:39.675Z,1379373339.675 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:15:40.193Z,1379373340.193 [Reporter](INFO): platform_buoyancy_position 83.927407 cc
2013-09-16T23:15:40.341Z,1379373340.341 [Reporter](INFO): platform_buoyancy_position 82.047205 cc
2013-09-16T23:15:41.087Z,1379373341.087 [Reporter](INFO): platform_buoyancy_position 79.764104 cc
2013-09-16T23:15:41.682Z,1379373341.682 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:41.682Z,1379373341.682 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:15:41.682Z,1379373341.682 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:15:41.900Z,1379373341.900 [Reporter](INFO): platform_buoyancy_position 77.749610 cc
2013-09-16T23:15:42.289Z,1379373342.289 [Reporter](INFO): platform_buoyancy_position 75.600808 cc
2013-09-16T23:15:43.094Z,1379373343.094 [Reporter](INFO): platform_buoyancy_position 73.452000 cc
2013-09-16T23:15:43.689Z,1379373343.689 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:43.689Z,1379373343.689 [DVL_micro](INFO): Querying output modes
2013-09-16T23:15:43.689Z,1379373343.689 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:15:43.979Z,1379373343.979 [Reporter](INFO): platform_buoyancy_position 71.168906 cc
2013-09-16T23:15:44.456Z,1379373344.456 [Reporter](INFO): platform_buoyancy_position 69.020105 cc
2013-09-16T23:15:44.888Z,1379373344.888 [Reporter](INFO): platform_buoyancy_position 67.408517 cc
2013-09-16T23:15:45.297Z,1379373345.297 [Reporter](INFO): platform_buoyancy_position 66.871318 cc
2013-09-16T23:15:45.690Z,1379373345.690 [Reporter](INFO): platform_buoyancy_position 64.722510 cc
2013-09-16T23:15:45.696Z,1379373345.696 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:45.696Z,1379373345.696 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:15:45.696Z,1379373345.696 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:15:46.058Z,1379373346.058 [Reporter](INFO): platform_buoyancy_position 64.856802 cc
2013-09-16T23:15:46.455Z,1379373346.455 [Reporter](INFO): platform_buoyancy_position 62.842308 cc
2013-09-16T23:15:46.888Z,1379373346.888 [Reporter](INFO): platform_buoyancy_position 60.693503 cc
2013-09-16T23:15:47.252Z,1379373347.252 [Reporter](INFO): platform_buoyancy_position 60.559210 cc
2013-09-16T23:15:47.707Z,1379373347.707 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:48.194Z,1379373348.194 [Reporter](INFO): platform_buoyancy_position 56.127312 cc
2013-09-16T23:15:48.302Z,1379373348.302 [Reporter](INFO): platform_buoyancy_position 56.261604 cc
2013-09-16T23:15:48.687Z,1379373348.687 [Reporter](INFO): platform_buoyancy_position 56.127312 cc
2013-09-16T23:15:49.092Z,1379373349.092 [Reporter](INFO): platform_buoyancy_position 54.112799 cc
2013-09-16T23:15:49.492Z,1379373349.492 [Reporter](INFO): platform_buoyancy_position 52.769814 cc
2013-09-16T23:15:49.711Z,1379373349.711 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:15:49.711Z,1379373349.711 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:15:49.900Z,1379373349.900 [Reporter](INFO): platform_buoyancy_position 51.829706 cc
2013-09-16T23:15:50.293Z,1379373350.293 [Reporter](INFO): platform_buoyancy_position 49.815208 cc
2013-09-16T23:15:50.690Z,1379373350.690 [Reporter](INFO): platform_buoyancy_position 49.680901 cc
2013-09-16T23:15:51.091Z,1379373351.091 [Reporter](INFO): platform_buoyancy_position 47.800713 cc
2013-09-16T23:15:51.713Z,1379373351.713 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:15:51.714Z,1379373351.714 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:15:51.979Z,1379373351.979 [Reporter](INFO): platform_buoyancy_position 45.383309 cc
2013-09-16T23:15:52.124Z,1379373352.124 [Reporter](INFO): platform_buoyancy_position 43.234504 cc
2013-09-16T23:15:52.460Z,1379373352.460 [Reporter](INFO): platform_buoyancy_position 43.368811 cc
2013-09-16T23:15:52.889Z,1379373352.889 [Reporter](INFO): platform_buoyancy_position 41.220010 cc
2013-09-16T23:15:53.282Z,1379373353.282 [Reporter](INFO): platform_buoyancy_position 41.085699 cc
2013-09-16T23:15:53.686Z,1379373353.686 [Reporter](INFO): platform_buoyancy_position 39.071205 cc
2013-09-16T23:15:53.716Z,1379373353.716 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:53.716Z,1379373353.716 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:15:53.716Z,1379373353.716 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:15:55.719Z,1379373355.719 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:55.719Z,1379373355.719 [DVL_micro](INFO): Querying output modes
2013-09-16T23:15:55.720Z,1379373355.720 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:15:57.722Z,1379373357.722 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:15:57.723Z,1379373357.723 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:15:57.723Z,1379373357.723 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:15:59.734Z,1379373359.734 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:01.741Z,1379373361.741 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:16:01.741Z,1379373361.741 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:16:02.812Z,1379373362.812 [CBIT](INFO): Clearing failed count for component AHRS_sp3003D
2013-09-16T23:16:02.812Z,1379373362.812 [AHRS_sp3003D] No Fault, FailCount= 5
2013-09-16T23:16:03.166Z,1379373363.166 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:16:03.744Z,1379373363.744 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:16:03.744Z,1379373363.744 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:16:04.473Z,1379373364.473 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:16:04.473Z,1379373364.473 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:16:04.473Z,1379373364.473 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2013-09-16T23:16:04.473Z,1379373364.473 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:16:04.524Z,1379373364.524 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:16:04.568Z,1379373364.568 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:16:05.747Z,1379373365.747 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:05.747Z,1379373365.747 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:16:05.747Z,1379373365.747 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:16:05.818Z,1379373365.818 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:16:05.818Z,1379373365.818 [AHRS_sp3003D] No Fault, FailCount= 1
2013-09-16T23:16:06.171Z,1379373366.171 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:16:07.309Z,1379373367.309 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:16:07.309Z,1379373367.309 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:16:07.310Z,1379373367.310 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2013-09-16T23:16:07.310Z,1379373367.310 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:16:07.368Z,1379373367.368 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:16:07.382Z,1379373367.382 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:16:07.758Z,1379373367.758 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:07.758Z,1379373367.758 [DVL_micro](INFO): Querying output modes
2013-09-16T23:16:07.758Z,1379373367.758 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:16:08.883Z,1379373368.883 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:16:08.883Z,1379373368.883 [AHRS_sp3003D] No Fault, FailCount= 2
2013-09-16T23:16:09.227Z,1379373369.227 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:16:09.765Z,1379373369.765 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:09.765Z,1379373369.765 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:16:09.765Z,1379373369.765 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:16:10.366Z,1379373370.366 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:16:10.366Z,1379373370.366 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:16:10.366Z,1379373370.366 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2013-09-16T23:16:10.366Z,1379373370.366 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:16:10.396Z,1379373370.396 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:16:10.425Z,1379373370.425 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:16:11.663Z,1379373371.663 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:16:11.663Z,1379373371.663 [AHRS_sp3003D] No Fault, FailCount= 3
2013-09-16T23:16:11.768Z,1379373371.768 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:11.969Z,1379373371.969 [CommandLine](IMPORTANT): got command quit
2013-09-16T23:16:12.028Z,1379373372.028 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:16:12.994Z,1379373372.994 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-09-16T23:16:12.994Z,1379373372.994 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-09-16T23:16:13.098Z,1379373373.098 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-09-16T23:16:13.335Z,1379373373.335 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:16:13.335Z,1379373373.335 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:16:13.335Z,1379373373.335 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2013-09-16T23:16:13.335Z,1379373373.335 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:16:13.365Z,1379373373.365 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:16:13.394Z,1379373373.394 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:16:13.451Z,1379373373.451 [WetLabsBB2FL](INFO): Powering down
2013-09-16T23:16:13.463Z,1379373373.463 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-09-16T23:16:13.776Z,1379373373.776 [DVL_micro](INFO): NQ1 requested
2013-09-16T23:16:13.776Z,1379373373.776 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T23:16:13.864Z,1379373373.864 [CTD_NeilBrown](INFO): Powering down
2013-09-16T23:16:13.880Z,1379373373.880 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-09-16T23:16:14.621Z,1379373374.621 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T23:16:14.621Z,1379373374.621 [AHRS_sp3003D] No Fault, FailCount= 4
2013-09-16T23:16:14.992Z,1379373374.992 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T23:16:15.779Z,1379373375.779 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T23:16:15.779Z,1379373375.779 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T23:16:16.139Z,1379373376.139 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T23:16:16.139Z,1379373376.139 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T23:16:16.139Z,1379373376.139 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2013-09-16T23:16:16.139Z,1379373376.139 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T23:16:16.192Z,1379373376.192 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:16:16.192Z,1379373376.192 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2013-09-16T23:16:16.206Z,1379373376.206 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:16:17.790Z,1379373377.790 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:17.790Z,1379373377.790 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T23:16:17.790Z,1379373377.790 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T23:16:19.803Z,1379373379.803 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:19.804Z,1379373379.804 [DVL_micro](INFO): Querying output modes
2013-09-16T23:16:19.804Z,1379373379.804 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T23:16:21.812Z,1379373381.812 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:21.812Z,1379373381.812 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T23:16:21.812Z,1379373381.812 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T23:16:23.819Z,1379373383.819 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T23:16:23.820Z,1379373383.820 [DVL_micro](INFO): uninitialize:Powering down
2013-09-16T23:16:24.247Z,1379373384.247 [DVL_micro](INFO): uninitialize:Powering down
2013-09-16T23:16:24.256Z,1379373384.256 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-09-16T23:16:24.468Z,1379373384.468 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-09-16T23:16:24.481Z,1379373384.481 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-09-16T23:16:24.541Z,1379373384.541 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-09-16T23:16:24.542Z,1379373384.542 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-09-16T23:16:24.624Z,1379373384.624 [controlThread](DEBUG): Uninitializing ControlThread
2013-09-16T23:16:24.625Z,1379373384.625 [AHRS_sp3003D](INFO): Powering down
2013-09-16T23:16:24.626Z,1379373384.626 [NAL9602](INFO): Powering down
2013-09-16T23:16:24.627Z,1379373384.627 [DAT](INFO): Powering down
2013-09-16T23:16:24.629Z,1379373384.629 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-09-16T23:16:24.629Z,1379373384.629 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-09-16T23:16:24.630Z,1379373384.630 [Default] Stopped
2013-09-16T23:16:24.631Z,1379373384.631 [Default](INFO): Aggregate::uninitialize Default
2013-09-16T23:16:24.631Z,1379373384.631 [Default:GPS] Stopped
2013-09-16T23:16:24.631Z,1379373384.631 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-09-16T23:16:24.631Z,1379373384.631 [Default:GPS:A.SetSpeed] Stopped
2013-09-16T23:16:24.631Z,1379373384.631 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-09-16T23:16:24.631Z,1379373384.631 [Default:GPS:Read_GPS] Stopped
2013-09-16T23:16:24.631Z,1379373384.631 [Default:Iridium] Stopped
2013-09-16T23:16:24.631Z,1379373384.631 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-09-16T23:16:24.631Z,1379373384.631 [Default:Iridium:A.SetSpeed] Stopped
2013-09-16T23:16:24.631Z,1379373384.631 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-09-16T23:16:24.631Z,1379373384.631 [Default:Iridium:Read_Iridium] Stopped
2013-09-16T23:16:24.631Z,1379373384.631 [Default:CallIridium] Stopped
2013-09-16T23:16:24.632Z,1379373384.632 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-09-16T23:16:24.632Z,1379373384.632 [Default:CallIridium:B] Stopped
2013-09-16T23:16:24.632Z,1379373384.632 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-09-16T23:16:24.632Z,1379373384.632 [Default:D.SetSpeed] Stopped
2013-09-16T23:16:24.632Z,1379373384.632 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-09-16T23:16:24.632Z,1379373384.632 [Default:E.GoToSurface] Stopped
2013-09-16T23:16:24.632Z,1379373384.632 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-09-16T23:16:24.636Z,1379373384.636 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-09-16T23:16:24.637Z,1379373384.637 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-09-16T23:16:24.637Z,1379373384.637 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-09-16T23:16:24.637Z,1379373384.637 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-09-16T23:16:24.638Z,1379373384.638 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T23:16:24.638Z,1379373384.638 [BuoyancyServo](INFO): Powering down
2013-09-16T23:16:24.652Z,1379373384.652 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-09-16T23:16:24.652Z,1379373384.652 [ElevatorServo](INFO): Powering down
2013-09-16T23:16:24.653Z,1379373384.653 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-09-16T23:16:24.653Z,1379373384.653 [MassServo](INFO): Powering down
2013-09-16T23:16:24.654Z,1379373384.654 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-09-16T23:16:24.654Z,1379373384.654 [RudderServo](INFO): Powering down
2013-09-16T23:16:24.655Z,1379373384.655 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T23:16:24.655Z,1379373384.655 [ThrusterServo](INFO): Powering down
2013-09-16T23:16:24.656Z,1379373384.656 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-09-16T23:16:24.656Z,1379373384.656 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-09-16T23:16:24.657Z,1379373384.657 [CBIT](DEBUG): Uninitialize CBIT Component.