2012-09-19T18:21:12.355Z,1348078872.355 [Supervisor](DEBUG): Initializing supervisor.
2012-09-19T18:21:12.357Z,1348078872.357 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-09-19T18:21:12.358Z,1348078872.358 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-09-19T18:21:12.362Z,1348078872.362 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-09-19T18:21:12.365Z,1348078872.365 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-09-19T18:21:12.376Z,1348078872.376 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-09-19T18:21:12.378Z,1348078872.378 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-09-19T18:21:12.379Z,1348078872.379 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-09-19T18:21:12.380Z,1348078872.380 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-09-19T18:21:12.382Z,1348078872.382 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-09-19T18:21:12.703Z,1348078872.703 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-09-19T18:21:12.706Z,1348078872.706 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-09-19T18:21:12.911Z,1348078872.911 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-09-19T18:21:12.912Z,1348078872.912 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-09-19T18:21:13.010Z,1348078873.010 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-09-19T18:21:13.012Z,1348078873.012 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-09-19T18:21:13.240Z,1348078873.240 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-09-19T18:21:13.240Z,1348078873.240 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-09-19T18:21:13.395Z,1348078873.395 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-09-19T18:21:13.397Z,1348078873.397 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-09-19T18:21:13.668Z,1348078873.668 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-09-19T18:21:13.668Z,1348078873.668 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-09-19T18:21:13.922Z,1348078873.922 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-09-19T18:21:13.925Z,1348078873.925 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-09-19T18:21:14.344Z,1348078874.344 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-09-19T18:21:14.346Z,1348078874.346 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-09-19T18:21:14.483Z,1348078874.483 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-09-19T18:21:14.484Z,1348078874.484 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-09-19T18:21:15.080Z,1348078875.080 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-09-19T18:21:15.081Z,1348078875.081 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-09-19T18:21:15.211Z,1348078875.211 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-09-19T18:21:15.212Z,1348078875.212 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-09-19T18:21:15.360Z,1348078875.360 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-09-19T18:21:15.365Z,1348078875.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-09-19T18:21:15.558Z,1348078875.558 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-09-19T18:21:15.708Z,1348078875.708 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-09-19T18:21:15.806Z,1348078875.806 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-09-19T18:21:15.923Z,1348078875.923 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-09-19T18:21:16.092Z,1348078876.092 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-09-19T18:21:16.250Z,1348078876.250 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-09-19T18:21:16.354Z,1348078876.354 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-09-19T18:21:16.504Z,1348078876.504 [Supervisor](FAULT): Ignoring configuration overrides from Data/config.db
2012-09-19T18:21:16.541Z,1348078876.541 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-09-19T18:21:16.726Z,1348078876.726 [InternalSim] Loaded
2012-09-19T18:21:16.726Z,1348078876.726 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-09-19T18:21:16.727Z,1348078876.727 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-09-19T18:21:16.728Z,1348078876.728 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-09-19T18:21:16.811Z,1348078876.811 [SBIT](DEBUG): Construct Startup Built In Test.
2012-09-19T18:21:16.828Z,1348078876.829 [SBIT] Loaded
2012-09-19T18:21:16.829Z,1348078876.829 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-09-19T18:21:16.830Z,1348078876.830 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-09-19T18:21:16.858Z,1348078876.858 [IBIT] Loaded
2012-09-19T18:21:16.858Z,1348078876.858 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-09-19T18:21:16.861Z,1348078876.861 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-09-19T18:21:16.994Z,1348078876.994 [CBIT] Loaded
2012-09-19T18:21:16.994Z,1348078876.994 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-09-19T18:21:16.995Z,1348078876.995 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-09-19T18:21:16.995Z,1348078876.995 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-09-19T18:21:17.165Z,1348078877.165 [BuoyancyServo] Loaded
2012-09-19T18:21:17.165Z,1348078877.165 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-09-19T18:21:17.175Z,1348078877.175 [ElevatorServo] Loaded
2012-09-19T18:21:17.175Z,1348078877.175 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-09-19T18:21:17.187Z,1348078877.187 [MassServo] Loaded
2012-09-19T18:21:17.187Z,1348078877.187 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-09-19T18:21:17.204Z,1348078877.204 [RudderServo] Loaded
2012-09-19T18:21:17.204Z,1348078877.204 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-09-19T18:21:17.215Z,1348078877.215 [ThrusterServo] Loaded
2012-09-19T18:21:17.215Z,1348078877.215 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-09-19T18:21:17.216Z,1348078877.216 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-09-19T18:21:17.217Z,1348078877.217 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-09-19T18:21:17.249Z,1348078877.249 [DepthRateCalculator] Loaded
2012-09-19T18:21:17.250Z,1348078877.250 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-09-19T18:21:20.490Z,1348078880.490 [HFRadarModelCalc] Loaded
2012-09-19T18:21:20.491Z,1348078880.491 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-09-19T18:21:20.506Z,1348078880.506 [NavChart] Loaded
2012-09-19T18:21:20.507Z,1348078880.507 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-09-19T18:21:20.513Z,1348078880.513 [PitchRateCalculator] Loaded
2012-09-19T18:21:20.513Z,1348078880.513 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-09-19T18:21:20.519Z,1348078880.519 [SpeedCalculator] Loaded
2012-09-19T18:21:20.520Z,1348078880.520 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-09-19T18:21:20.535Z,1348078880.535 [TempGradientCalculator] Loaded
2012-09-19T18:21:20.535Z,1348078880.535 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-09-19T18:21:20.541Z,1348078880.541 [YawRateCalculator] Loaded
2012-09-19T18:21:20.541Z,1348078880.541 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-09-19T18:21:20.561Z,1348078880.561 [Navigation] Loaded
2012-09-19T18:21:20.561Z,1348078880.561 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-09-19T18:21:20.562Z,1348078880.562 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-09-19T18:21:20.562Z,1348078880.562 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-09-19T18:21:20.844Z,1348078880.844 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-09-19T18:21:20.845Z,1348078880.845 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-09-19T18:21:20.889Z,1348078880.889 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-09-19T18:21:20.890Z,1348078880.890 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-09-19T18:21:20.952Z,1348078880.952 [VerticalControl](DEBUG): Construct VerticalControl.
2012-09-19T18:21:21.003Z,1348078881.003 [VerticalControl] Loaded
2012-09-19T18:21:21.004Z,1348078881.004 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-09-19T18:21:21.005Z,1348078881.005 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-09-19T18:21:21.030Z,1348078881.030 [HorizontalControl] Loaded
2012-09-19T18:21:21.030Z,1348078881.030 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-09-19T18:21:21.031Z,1348078881.031 [SpeedControl](DEBUG): Construct SpeedControl.
2012-09-19T18:21:21.033Z,1348078881.033 [SpeedControl] Loaded
2012-09-19T18:21:21.033Z,1348078881.033 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-09-19T18:21:21.034Z,1348078881.034 [LoopControl](DEBUG): Construct LoopControl.
2012-09-19T18:21:21.035Z,1348078881.035 [LoopControl] Loaded
2012-09-19T18:21:21.035Z,1348078881.035 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-09-19T18:21:21.035Z,1348078881.035 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-09-19T18:21:21.036Z,1348078881.036 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-09-19T18:21:21.044Z,1348078881.044 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-09-19T18:21:21.053Z,1348078881.053 [AsyncPiEstimator] Loaded
2012-09-19T18:21:21.053Z,1348078881.053 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-09-19T18:21:21.055Z,1348078881.055 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4060A4E0
2012-09-19T18:21:21.055Z,1348078881.055 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-09-19T18:21:21.056Z,1348078881.056 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-09-19T18:21:21.663Z,1348078881.663 [AHRS_sp3003D] Loaded
2012-09-19T18:21:21.664Z,1348078881.664 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-09-19T18:21:21.690Z,1348078881.690 [Depth_Keller] Loaded
2012-09-19T18:21:21.690Z,1348078881.690 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-09-19T18:21:21.712Z,1348078881.712 [DropWeight] Loaded
2012-09-19T18:21:21.712Z,1348078881.712 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-09-19T18:21:21.885Z,1348078881.885 [DVL_micro] Loaded
2012-09-19T18:21:21.886Z,1348078881.886 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-09-19T18:21:21.890Z,1348078881.890 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4068A4E0
2012-09-19T18:21:21.983Z,1348078881.983 [NAL9602] Loaded
2012-09-19T18:21:21.984Z,1348078881.984 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-09-19T18:21:22.038Z,1348078882.038 [Onboard] Loaded
2012-09-19T18:21:22.038Z,1348078882.038 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-09-19T18:21:22.049Z,1348078882.049 [Radio_Freewave] Loaded
2012-09-19T18:21:22.050Z,1348078882.050 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-09-19T18:21:22.051Z,1348078882.050 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-09-19T18:21:22.051Z,1348078882.051 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-09-19T18:21:22.155Z,1348078882.155 [CTD_NeilBrown] Loaded
2012-09-19T18:21:22.155Z,1348078882.155 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-09-19T18:21:22.158Z,1348078882.158 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E24E0
2012-09-19T18:21:22.169Z,1348078882.169 [PAR_Licor] Loaded
2012-09-19T18:21:22.169Z,1348078882.169 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-09-19T18:21:22.190Z,1348078882.190 [Turbulence_NPS] Loaded
2012-09-19T18:21:22.191Z,1348078882.191 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-09-19T18:21:22.194Z,1348078882.194 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407124E0
2012-09-19T18:21:22.230Z,1348078882.230 [WetLabsBB2FL] Loaded
2012-09-19T18:21:22.230Z,1348078882.230 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-09-19T18:21:22.234Z,1348078882.234 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407424E0
2012-09-19T18:21:22.235Z,1348078882.235 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-09-19T18:21:22.237Z,1348078882.237 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-09-19T18:21:22.238Z,1348078882.238 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-09-19T18:21:22.244Z,1348078882.244 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-09-19T18:21:22.247Z,1348078882.247 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407724E0
2012-09-19T18:21:22.251Z,1348078882.251 [Supervisor](DEBUG): Running supervisor.
2012-09-19T18:21:22.255Z,1348078882.255 [controlThread](DEBUG): Initializing ControlThread
2012-09-19T18:21:22.256Z,1348078882.256 [InternalSim](DEBUG):  InternalSim initializing...
2012-09-19T18:21:22.367Z,1348078882.367 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-09-19T18:21:22.530Z,1348078882.530 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-09-19T18:21:22.579Z,1348078882.579 [DVL_micro](INFO): Initializing
2012-09-19T18:21:22.579Z,1348078882.579 [DVL_micro](INFO): start:Powering up
2012-09-19T18:21:22.591Z,1348078882.591 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-09-19T18:21:22.601Z,1348078882.602 [SBIT](INFO): Initialize SBIT Component.
2012-09-19T18:21:22.602Z,1348078882.602 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9842
2012-09-19T18:21:22.608Z,1348078882.608 [WetLabsBB2FL](INFO): Powering down
2012-09-19T18:21:22.636Z,1348078882.635 [IBIT](INFO): Initialize IBIT Component.
2012-09-19T18:21:22.636Z,1348078882.636 [CBIT](DEBUG): Initialize CBIT Component.
2012-09-19T18:21:22.637Z,1348078882.637 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2012-09-19T18:21:22.637Z,1348078882.637 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-09-19T18:21:22.760Z,1348078882.760 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-19T18:21:22.760Z,1348078882.760 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-09-19T18:21:22.761Z,1348078882.761 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-09-19T18:21:22.761Z,1348078882.761 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-09-19T18:21:22.761Z,1348078882.761 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-09-19T18:21:22.763Z,1348078882.763 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-09-19T18:21:22.763Z,1348078882.763 [Navigation](DEBUG): Initializing Navigation.
2012-09-19T18:21:22.764Z,1348078882.764 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-09-19T18:21:22.766Z,1348078882.766 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-09-19T18:21:22.766Z,1348078882.766 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-09-19T18:21:22.767Z,1348078882.767 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-09-19T18:21:22.795Z,1348078882.795 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-09-19T18:21:22.866Z,1348078882.866 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-19T18:21:22.876Z,1348078882.876 [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>


2012-09-19T18:21:22.877Z,1348078882.877 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-09-19T18:21:22.989Z,1348078882.989 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-09-19T18:21:22.991Z,1348078882.991 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-09-19T18:21:22.994Z,1348078882.994 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-19T18:21:23.002Z,1348078883.002 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-09-19T18:21:23.005Z,1348078883.005 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-19T18:21:23.016Z,1348078883.016 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-09-19T18:21:23.024Z,1348078883.024 [Default:D.SetSpeed](DEBUG): Construct.
2012-09-19T18:21:23.032Z,1348078883.032 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-19T18:21:23.037Z,1348078883.037 [Default:F.Wait](DEBUG): Construct Wait.
2012-09-19T18:21:23.044Z,1348078883.044 [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>


2012-09-19T18:21:23.050Z,1348078883.050 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-09-19T18:21:23.070Z,1348078883.070 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:21:23.215Z,1348078883.215 [Depth_Keller](INFO): A/D timeout, 2 tries over 134 ms

2012-09-19T18:21:23.215Z,1348078883.215 [Depth_Keller] Data Fault, FailCount= 1
2012-09-19T18:21:23.215Z,1348078883.215 [Depth_Keller](ERROR): Data Fault
2012-09-19T18:21:23.243Z,1348078883.243 [Radio_Freewave](INFO): Powering up
2012-09-19T18:21:23.479Z,1348078883.479 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-09-19T18:21:23.483Z,1348078883.483 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-09-19T18:21:23.490Z,1348078883.490 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-19T18:21:23.491Z,1348078883.491 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-19T18:21:23.497Z,1348078883.497 [MassServo](DEBUG): Initializing MassServo.
2012-09-19T18:21:23.507Z,1348078883.507 [RudderServo](DEBUG): Initializing EZServoServo.
2012-09-19T18:21:23.511Z,1348078883.511 [RudderServo](DEBUG): Initializing RudderServo.
2012-09-19T18:21:23.517Z,1348078883.517 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-09-19T18:21:23.518Z,1348078883.518 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-09-19T18:21:23.541Z,1348078883.541 [CBIT](ERROR): Data Fault in component: Depth_Keller
2012-09-19T18:21:23.541Z,1348078883.541 [CBIT](INFO): Clearing failed state for component Depth_Keller
2012-09-19T18:21:23.541Z,1348078883.541 [Depth_Keller] No Fault, FailCount= 1
2012-09-19T18:21:24.143Z,1348078884.143 [DVL_micro](INFO): Querying output modes
2012-09-19T18:21:24.143Z,1348078884.143 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:21:24.147Z,1348078884.147 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-09-19T18:21:24.147Z,1348078884.147 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:21:24.147Z,1348078884.147 [DVL_micro](INFO): RSSI output enabled
2012-09-19T18:21:24.147Z,1348078884.147 [DVL_micro](INFO): ADCP output enabled
2012-09-19T18:21:24.147Z,1348078884.147 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:21:24.155Z,1348078884.155 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:21:24.160Z,1348078884.159 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:21:27.157Z,1348078887.157 [NAL9602](INFO): Powering up NAL9602
2012-09-19T18:21:28.701Z,1348078888.701 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-09-19T18:21:28.722Z,1348078888.722 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-09-19T18:21:28.762Z,1348078888.762 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-09-19T18:21:28.811Z,1348078888.811 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-09-19T18:21:28.827Z,1348078888.827 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-09-19T18:21:28.828Z,1348078888.828 [NavChartDb](INFO): Creating index for Soundings
2012-09-19T18:21:28.843Z,1348078888.843 [NavChartDb](INFO): Creating index for Contour 0p0
2012-09-19T18:21:28.845Z,1348078888.845 [NavChartDb](INFO): Creating index for Contour 1p8
2012-09-19T18:21:28.859Z,1348078888.859 [NavChartDb](INFO): Creating index for Contour 3p6
2012-09-19T18:21:28.861Z,1348078888.861 [NavChartDb](INFO): Creating index for Contour 5p4
2012-09-19T18:21:28.963Z,1348078888.963 [NavChartDb](INFO): Creating index for Contour 9p1
2012-09-19T18:21:28.965Z,1348078888.965 [NavChartDb](INFO): Creating index for Contour 10p9
2012-09-19T18:21:29.235Z,1348078889.236 [NavChartDb](INFO): Creating index for Contour 18p2
2012-09-19T18:21:29.237Z,1348078889.237 [NavChartDb](INFO): Creating index for Contour 36p5
2012-09-19T18:21:29.492Z,1348078889.492 [NavChartDb](INFO): Creating index for Contour 54p8
2012-09-19T18:21:29.494Z,1348078889.494 [NavChartDb](INFO): Creating index for Contour 73p1
2012-09-19T18:21:29.756Z,1348078889.756 [NavChartDb](INFO): Creating index for Contour 91p4
2012-09-19T18:21:29.758Z,1348078889.758 [NavChartDb](INFO): Creating index for Contour 182p8
2012-09-19T18:21:29.877Z,1348078889.877 [NavChartDb](INFO): Creating index for Contour 365p7
2012-09-19T18:21:30.208Z,1348078890.208 [NavChartDb](INFO): Creating index for Contour 548p6
2012-09-19T18:21:30.210Z,1348078890.210 [NavChartDb](INFO): Creating index for Contour 731p5
2012-09-19T18:21:30.269Z,1348078890.269 [NavChartDb](INFO): Creating index for Contour 914p4
2012-09-19T18:21:30.516Z,1348078890.516 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-09-19T18:21:30.517Z,1348078890.517 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-09-19T18:21:30.744Z,1348078890.744 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-09-19T18:21:30.746Z,1348078890.746 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-09-19T18:21:31.061Z,1348078891.061 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-09-19T18:21:31.232Z,1348078891.232 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-09-19T18:21:31.319Z,1348078891.319 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-09-19T18:21:31.321Z,1348078891.321 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-09-19T18:21:31.332Z,1348078891.332 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-09-19T18:21:31.542Z,1348078891.542 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-09-19T18:21:31.544Z,1348078891.545 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-09-19T18:21:31.546Z,1348078891.546 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-09-19T18:21:31.548Z,1348078891.548 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-09-19T18:21:31.786Z,1348078891.786 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-09-19T18:21:31.788Z,1348078891.788 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-09-19T18:21:37.887Z,1348078897.887 [NAL9602](INFO): NAL9602 initialized
2012-09-19T18:21:38.303Z,1348078898.303 [SBIT](IMPORTANT): Beginning Startup BIT
2012-09-19T18:21:38.306Z,1348078898.306 [CBIT](IMPORTANT): Beginning GF scan
2012-09-19T18:21:40.319Z,1348078900.319 [ElevatorServo](FAULT): Overload Error
2012-09-19T18:21:40.319Z,1348078900.319 [ElevatorServo] Hardware Fault, FailCount= 1
2012-09-19T18:21:40.319Z,1348078900.319 [ElevatorServo](ERROR): Hardware Fault
2012-09-19T18:21:40.370Z,1348078900.370 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-19T18:21:40.740Z,1348078900.740 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-19T18:21:40.740Z,1348078900.740 [ElevatorServo](INFO): Powering down
2012-09-19T18:21:40.793Z,1348078900.793 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-19T18:21:40.794Z,1348078900.793 [ElevatorServo] No Fault, FailCount= 1
2012-09-19T18:21:41.496Z,1348078901.496 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-19T18:21:41.619Z,1348078901.619 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-19T18:21:41.619Z,1348078901.619 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-19T18:21:43.862Z,1348078903.862 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-09-19T18:21:43.863Z,1348078903.862 [DropWeight] Hardware Fault, FailCount= 1
2012-09-19T18:21:43.863Z,1348078903.863 [DropWeight](ERROR): Hardware Fault
2012-09-19T18:21:43.947Z,1348078903.947 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-09-19T18:21:43.948Z,1348078903.948 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-09-19T18:21:46.290Z,1348078906.290 [ElevatorServo](FAULT): Overload Error
2012-09-19T18:21:46.290Z,1348078906.290 [ElevatorServo] Hardware Fault, FailCount= 2
2012-09-19T18:21:46.291Z,1348078906.291 [ElevatorServo](ERROR): Hardware Fault
2012-09-19T18:21:46.319Z,1348078906.319 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-19T18:21:46.668Z,1348078906.668 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-19T18:21:46.668Z,1348078906.668 [ElevatorServo](INFO): Powering down
2012-09-19T18:21:46.673Z,1348078906.673 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-09-19T18:21:46.673Z,1348078906.673 [ElevatorServo] No Fault, FailCount= 2
2012-09-19T18:21:47.468Z,1348078907.468 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-09-19T18:21:47.587Z,1348078907.587 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-19T18:21:47.588Z,1348078907.588 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-19T18:21:51.494Z,1348078911.494 [SBIT](FAULT): Elevator: EXPECTED:15.000000 ACTUAL:-0.195748
2012-09-19T18:21:52.290Z,1348078912.290 [ElevatorServo](FAULT): Overload Error
2012-09-19T18:21:52.290Z,1348078912.290 [ElevatorServo] Hardware Fault, FailCount= 3
2012-09-19T18:21:52.291Z,1348078912.291 [ElevatorServo](ERROR): Hardware Fault
2012-09-19T18:21:52.319Z,1348078912.319 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-09-19T18:21:52.319Z,1348078912.319 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-09-19T18:21:52.668Z,1348078912.668 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-19T18:21:52.668Z,1348078912.668 [ElevatorServo](INFO): Powering down
2012-09-19T18:22:04.675Z,1348078924.675 [CBIT](IMPORTANT): No ground fault detected
2012-09-19T18:22:32.269Z,1348078952.269 [SBIT](CRITICAL): SBIT FAILED
2012-09-19T18:22:32.663Z,1348078952.663 [MissionManager](IMPORTANT): Started mission Startup
2012-09-19T18:22:32.663Z,1348078952.663 [Startup] Running Loop=1
2012-09-19T18:22:32.663Z,1348078952.663 [Startup](INFO): Aggregate::initialize Startup
2012-09-19T18:22:32.663Z,1348078952.663 [Startup:A.GoToSurface] Running Loop=1
2012-09-19T18:22:32.663Z,1348078952.663 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-19T18:22:32.669Z,1348078952.669 [Startup:StartupSatComms] Running Loop=1
2012-09-19T18:22:32.669Z,1348078952.669 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-09-19T18:22:32.669Z,1348078952.669 [Startup:StartupSatComms:A] Running Loop=1
2012-09-19T18:22:33.069Z,1348078953.069 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-19T18:23:29.359Z,1348079009.359 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2012-09-19T18:23:29.360Z,1348079009.360 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.779999 degree
2012-09-19T18:23:29.502Z,1348079009.502 [Startup:StartupSatComms:A] Stopped
2012-09-19T18:23:29.506Z,1348079009.506 [Startup:StartupSatComms:B] Running Loop=1
2012-09-19T18:23:29.622Z,1348079009.622 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2012-09-19T18:23:29.831Z,1348079009.831 [NavChartDb](INFO): Charting Soundings
2012-09-19T18:23:29.940Z,1348079009.940 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-09-19T18:23:29.941Z,1348079009.941 [Startup:StartupSatComms:B] Stopped
2012-09-19T18:23:29.941Z,1348079009.941 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-09-19T18:23:29.941Z,1348079009.941 [Startup:StartupSatComms] Stopped
2012-09-19T18:23:29.942Z,1348079009.941 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-09-19T18:23:29.942Z,1348079009.943 [Startup](INFO): Completed Startup
2012-09-19T18:23:29.943Z,1348079009.943 [Startup] Stopped
2012-09-19T18:23:29.943Z,1348079009.943 [Startup](INFO): Aggregate::uninitialize Startup
2012-09-19T18:23:29.943Z,1348079009.943 [Startup:A.GoToSurface] Stopped
2012-09-19T18:23:29.943Z,1348079009.943 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-19T18:23:30.316Z,1348079010.316 [MissionManager](IMPORTANT): Started mission Default
2012-09-19T18:23:30.316Z,1348079010.316 [Default] Running Loop=1
2012-09-19T18:23:30.316Z,1348079010.316 [Default](INFO): Aggregate::initialize Default
2012-09-19T18:23:30.316Z,1348079010.316 [Default:D.SetSpeed] Running Loop=1
2012-09-19T18:23:30.316Z,1348079010.316 [Default:D.SetSpeed](DEBUG): Initialize.
2012-09-19T18:23:30.316Z,1348079010.316 [Default:E.GoToSurface] Running Loop=1
2012-09-19T18:23:30.317Z,1348079010.316 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-19T18:23:30.317Z,1348079010.317 [Default:Iridium] Running Loop=1
2012-09-19T18:23:30.317Z,1348079010.317 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-19T18:23:30.317Z,1348079010.317 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-19T18:23:30.317Z,1348079010.317 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-19T18:23:30.317Z,1348079010.317 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-19T18:23:30.317Z,1348079010.317 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-19T18:23:30.318Z,1348079010.318 [Default:E.GoToSurface] Running Loop=1
2012-09-19T18:23:30.323Z,1348079010.323 [Default:D.SetSpeed] Running Loop=1
2012-09-19T18:23:30.333Z,1348079010.333 [Default:Iridium:B.GoToSurface] Stopped
2012-09-19T18:23:30.333Z,1348079010.333 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-19T18:23:30.333Z,1348079010.333 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-19T18:23:30.334Z,1348079010.334 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-19T18:23:30.338Z,1348079010.338 [Default:GPS] Running Loop=1
2012-09-19T18:23:30.338Z,1348079010.339 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-19T18:23:30.339Z,1348079010.339 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-19T18:23:30.339Z,1348079010.339 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-19T18:23:30.339Z,1348079010.339 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-19T18:23:30.339Z,1348079010.339 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-19T18:23:30.344Z,1348079010.344 [Default:GPS:B.GoToSurface] Stopped
2012-09-19T18:23:30.344Z,1348079010.344 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-19T18:23:30.344Z,1348079010.344 [Default:GPS:Read_GPS] Running Loop=1
2012-09-19T18:23:30.344Z,1348079010.344 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-19T18:23:31.026Z,1348079011.026 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-09-19T18:23:31.028Z,1348079011.028 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-19T18:23:32.075Z,1348079012.075 [NavChartDb](INFO): Charting 0p0
2012-09-19T18:23:33.918Z,1348079013.918 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:23:33.918Z,1348079013.918 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:23:33.918Z,1348079013.918 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:23:34.045Z,1348079014.045 [NavChartDb](INFO): Charting 1p8
2012-09-19T18:23:34.247Z,1348079014.247 [DVL_micro](INFO): RSSI unrequested
2012-09-19T18:23:34.247Z,1348079014.247 [DVL_micro](INFO): ADCP unrequested
2012-09-19T18:23:34.247Z,1348079014.247 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:23:34.455Z,1348079014.455 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:23:34.521Z,1348079014.520 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:23:34.697Z,1348079014.697 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:23:34.697Z,1348079014.697 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:23:35.717Z,1348079015.717 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:23:35.754Z,1348079015.754 [DVL_micro](INFO): Querying output modes
2012-09-19T18:23:35.755Z,1348079015.755 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:23:35.759Z,1348079015.759 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-09-19T18:23:35.759Z,1348079015.759 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:23:35.759Z,1348079015.759 [DVL_micro](INFO): RSSI output enabled
2012-09-19T18:23:35.759Z,1348079015.759 [DVL_micro](INFO): ADCP output enabled
2012-09-19T18:23:35.759Z,1348079015.759 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:23:35.767Z,1348079015.767 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:23:35.769Z,1348079015.769 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:23:37.363Z,1348079017.363 [NavChartDb](INFO): Charting 3p6
2012-09-19T18:23:39.265Z,1348079019.265 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:23:39.265Z,1348079019.265 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:23:39.265Z,1348079019.265 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:23:39.271Z,1348079019.271 [DVL_micro](INFO): RSSI unrequested
2012-09-19T18:23:39.271Z,1348079019.271 [DVL_micro](INFO): ADCP unrequested
2012-09-19T18:23:39.271Z,1348079019.272 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:23:40.592Z,1348079020.592 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:23:40.663Z,1348079020.663 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:23:41.029Z,1348079021.029 [DVL_micro](INFO): Querying output modes
2012-09-19T18:23:41.029Z,1348079021.029 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:23:41.037Z,1348079021.037 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-09-19T18:23:41.037Z,1348079021.037 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:23:41.037Z,1348079021.037 [DVL_micro](INFO): RSSI output enabled
2012-09-19T18:23:41.037Z,1348079021.037 [DVL_micro](INFO): ADCP output enabled
2012-09-19T18:23:41.038Z,1348079021.038 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:23:41.043Z,1348079021.043 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:23:41.044Z,1348079021.044 [DVL_micro](INFO): RSSI unrequested
2012-09-19T18:23:41.044Z,1348079021.044 [DVL_micro](INFO): ADCP unrequested
2012-09-19T18:23:41.287Z,1348079021.287 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:23:41.287Z,1348079021.287 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:23:42.144Z,1348079022.144 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:23:42.552Z,1348079022.552 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-09-19T18:23:42.591Z,1348079022.591 [NavChartDb](INFO): Charting 5p4
2012-09-19T18:23:42.766Z,1348079022.766 [DVL_micro](DEBUG): cmdResponse: 00
2012-09-19T18:23:42.767Z,1348079022.767 [DVL_micro](INFO): Enabling NQ1 output
2012-09-19T18:23:42.767Z,1348079022.767 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-09-19T18:23:42.983Z,1348079022.983 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:23:42.983Z,1348079022.983 [DVL_micro](INFO): Querying output modes
2012-09-19T18:23:42.983Z,1348079022.983 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:23:42.987Z,1348079022.987 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:23:42.987Z,1348079022.987 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:23:42.987Z,1348079022.987 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:23:42.995Z,1348079022.995 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:23:43.060Z,1348079023.060 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:23:47.351Z,1348079027.351 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:23:47.351Z,1348079027.351 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:23:47.352Z,1348079027.352 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:23:47.696Z,1348079027.695 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:23:47.777Z,1348079027.777 [NavChartDb](INFO): Charting 9p1
2012-09-19T18:23:47.814Z,1348079027.814 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:23:47.876Z,1348079027.875 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:23:47.997Z,1348079027.997 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:23:47.997Z,1348079027.997 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:23:49.072Z,1348079029.072 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:23:49.202Z,1348079029.202 [DVL_micro](INFO): Querying output modes
2012-09-19T18:23:49.203Z,1348079029.203 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:23:49.210Z,1348079029.210 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:23:49.211Z,1348079029.211 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:23:49.211Z,1348079029.211 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:23:49.219Z,1348079029.218 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:23:49.221Z,1348079029.221 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:23:49.379Z,1348079029.378 [NavChartDb](INFO): Charting 10p9
2012-09-19T18:23:51.407Z,1348079031.407 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:23:51.407Z,1348079031.407 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:23:51.407Z,1348079031.407 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:23:51.784Z,1348079031.784 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:23:51.939Z,1348079031.939 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:23:51.989Z,1348079031.989 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:23:52.111Z,1348079032.111 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:23:52.111Z,1348079032.111 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:23:52.627Z,1348079032.626 [NavChartDb](INFO): Charting 18p2
2012-09-19T18:23:53.427Z,1348079033.427 [DVL_micro](INFO): Querying output modes
2012-09-19T18:23:53.427Z,1348079033.427 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:23:53.502Z,1348079033.502 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:23:53.503Z,1348079033.503 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:23:53.503Z,1348079033.503 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:23:53.507Z,1348079033.507 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:23:53.509Z,1348079033.509 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:23:53.581Z,1348079033.580 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:23:55.227Z,1348079035.227 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:23:55.227Z,1348079035.227 [AHRS_sp3003D] Communications Fault, FailCount= 2
2012-09-19T18:23:55.227Z,1348079035.227 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:23:55.531Z,1348079035.531 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:23:55.669Z,1348079035.669 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:23:55.731Z,1348079035.731 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:23:55.853Z,1348079035.852 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:23:55.853Z,1348079035.853 [AHRS_sp3003D] No Fault, FailCount= 2
2012-09-19T18:23:57.182Z,1348079037.182 [DVL_micro](INFO): Querying output modes
2012-09-19T18:23:57.183Z,1348079037.183 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:23:57.279Z,1348079037.279 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:23:57.279Z,1348079037.279 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:23:57.279Z,1348079037.279 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:23:57.283Z,1348079037.283 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:23:57.285Z,1348079037.285 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:23:58.261Z,1348079038.260 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:23:59.767Z,1348079039.767 [NavChartDb](INFO): Charting 36p5
2012-09-19T18:24:03.023Z,1348079043.023 [NavChartDb](INFO): Charting 54p8
2012-09-19T18:24:04.375Z,1348079044.375 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-19T18:24:04.375Z,1348079044.375 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:04.375Z,1348079044.375 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:04.491Z,1348079044.490 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:04.534Z,1348079044.534 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:04.855Z,1348079044.855 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:05.038Z,1348079045.038 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:05.038Z,1348079045.038 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:06.234Z,1348079046.234 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:06.650Z,1348079046.651 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:06.651Z,1348079046.651 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:06.655Z,1348079046.655 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:06.655Z,1348079046.655 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:06.655Z,1348079046.655 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:06.659Z,1348079046.659 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:06.661Z,1348079046.661 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:13.471Z,1348079053.471 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:24:13.472Z,1348079053.471 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:13.472Z,1348079053.472 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:13.767Z,1348079053.767 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:13.943Z,1348079053.944 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:14.002Z,1348079054.002 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:14.539Z,1348079054.539 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:14.539Z,1348079054.539 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:15.306Z,1348079055.306 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:15.307Z,1348079055.307 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:15.422Z,1348079055.422 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:15.423Z,1348079055.422 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:15.423Z,1348079055.423 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:15.431Z,1348079055.431 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:15.433Z,1348079055.433 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:15.973Z,1348079055.973 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:17.798Z,1348079057.798 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:24:17.798Z,1348079057.798 [AHRS_sp3003D] Communications Fault, FailCount= 2
2012-09-19T18:24:17.798Z,1348079057.798 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:17.845Z,1348079057.845 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:17.888Z,1348079057.888 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:18.215Z,1348079058.215 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:18.604Z,1348079058.604 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:18.604Z,1348079058.604 [AHRS_sp3003D] No Fault, FailCount= 2
2012-09-19T18:24:19.213Z,1348079059.214 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:19.862Z,1348079059.862 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:19.863Z,1348079059.863 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:19.938Z,1348079059.938 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:19.938Z,1348079059.938 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:19.939Z,1348079059.939 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:19.943Z,1348079059.943 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:19.945Z,1348079059.945 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:22.767Z,1348079062.767 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-19T18:24:22.767Z,1348079062.767 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:22.767Z,1348079062.767 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:22.775Z,1348079062.775 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:22.903Z,1348079062.903 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:22.947Z,1348079062.947 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:23.395Z,1348079063.395 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:23.395Z,1348079063.395 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:24.237Z,1348079064.237 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:24.282Z,1348079064.283 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:24.283Z,1348079064.283 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:24.287Z,1348079064.287 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:24.287Z,1348079064.287 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:24.287Z,1348079064.287 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:24.291Z,1348079064.291 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:24.293Z,1348079064.293 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:27.531Z,1348079067.531 [NavChartDb](INFO): Charting 73p1
2012-09-19T18:24:29.531Z,1348079069.531 [NavChartDb](INFO): Charting 91p4
2012-09-19T18:24:30.083Z,1348079070.083 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-19T18:24:30.083Z,1348079070.083 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:30.083Z,1348079070.083 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:30.451Z,1348079070.451 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:30.611Z,1348079070.611 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:30.665Z,1348079070.665 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:30.789Z,1348079070.789 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:30.789Z,1348079070.789 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:31.861Z,1348079071.861 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:31.958Z,1348079071.958 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:31.959Z,1348079071.959 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:31.966Z,1348079071.966 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:31.966Z,1348079071.967 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:31.967Z,1348079071.967 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:31.975Z,1348079071.975 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:31.977Z,1348079071.977 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:32.371Z,1348079072.371 [NavChartDb](INFO): Charting 182p8
2012-09-19T18:24:34.194Z,1348079074.194 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:24:34.194Z,1348079074.194 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:34.195Z,1348079074.195 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:34.326Z,1348079074.326 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:34.368Z,1348079074.368 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:34.515Z,1348079074.515 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:35.376Z,1348079075.376 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:35.376Z,1348079075.376 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:35.825Z,1348079075.825 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:36.110Z,1348079076.110 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:36.111Z,1348079076.111 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:36.182Z,1348079076.182 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:36.183Z,1348079076.183 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:36.183Z,1348079076.183 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:36.187Z,1348079076.187 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:36.189Z,1348079076.189 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:46.735Z,1348079086.735 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-19T18:24:46.735Z,1348079086.735 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:46.735Z,1348079086.735 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:47.139Z,1348079087.139 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:47.668Z,1348079087.668 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:47.730Z,1348079087.730 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:47.885Z,1348079087.885 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:47.885Z,1348079087.885 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:48.754Z,1348079088.754 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:48.754Z,1348079088.754 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:48.830Z,1348079088.830 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:48.831Z,1348079088.831 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:48.831Z,1348079088.831 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:48.835Z,1348079088.835 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:48.837Z,1348079088.837 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:49.309Z,1348079089.309 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:52.199Z,1348079092.199 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:24:52.199Z,1348079092.199 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:52.199Z,1348079092.199 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:52.531Z,1348079092.531 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:52.772Z,1348079092.772 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:52.921Z,1348079092.921 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:53.730Z,1348079093.730 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:53.734Z,1348079093.734 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:54.110Z,1348079094.110 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:54.111Z,1348079094.111 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:54.210Z,1348079094.210 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:54.211Z,1348079094.211 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:54.211Z,1348079094.211 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:54.215Z,1348079094.215 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:54.217Z,1348079094.217 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:54.678Z,1348079094.678 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:24:57.599Z,1348079097.599 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-19T18:24:57.599Z,1348079097.599 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:24:57.599Z,1348079097.599 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:24:57.619Z,1348079097.619 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:24:58.332Z,1348079098.332 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:24:58.395Z,1348079098.395 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:24:59.227Z,1348079099.227 [DVL_micro](INFO): Querying output modes
2012-09-19T18:24:59.227Z,1348079099.227 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:24:59.258Z,1348079099.258 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:24:59.259Z,1348079099.259 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:24:59.259Z,1348079099.259 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:24:59.263Z,1348079099.263 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:24:59.289Z,1348079099.289 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:24:59.289Z,1348079099.289 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:24:59.353Z,1348079099.353 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:24:59.912Z,1348079099.912 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:02.163Z,1348079102.163 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:25:02.163Z,1348079102.163 [AHRS_sp3003D] Communications Fault, FailCount= 2
2012-09-19T18:25:02.163Z,1348079102.164 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:02.184Z,1348079102.184 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:02.219Z,1348079102.219 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:02.342Z,1348079102.342 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:02.474Z,1348079102.474 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:02.474Z,1348079102.474 [AHRS_sp3003D] No Fault, FailCount= 2
2012-09-19T18:25:03.199Z,1348079103.199 [NavChartDb](INFO): Charting 365p7
2012-09-19T18:25:03.529Z,1348079103.529 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:03.690Z,1348079103.690 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:03.691Z,1348079103.691 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:03.758Z,1348079103.758 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:03.759Z,1348079103.759 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:03.759Z,1348079103.759 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:03.763Z,1348079103.763 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:03.765Z,1348079103.765 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:05.223Z,1348079105.223 [CommandLine](IMPORTANT): got command get depth
2012-09-19T18:25:05.223Z,1348079105.223 [CommandLine](IMPORTANT): depth -0.016420 meter
2012-09-19T18:25:06.623Z,1348079106.623 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:25:06.623Z,1348079106.623 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:25:06.623Z,1348079106.623 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:06.671Z,1348079106.671 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:06.715Z,1348079106.715 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:06.837Z,1348079106.837 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:06.837Z,1348079106.837 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:25:08.836Z,1348079108.836 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:11.683Z,1348079111.683 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-19T18:25:11.683Z,1348079111.683 [AHRS_sp3003D] Communications Fault, FailCount= 2
2012-09-19T18:25:11.683Z,1348079111.683 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:11.723Z,1348079111.723 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:11.858Z,1348079111.858 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:11.979Z,1348079111.980 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:12.096Z,1348079112.096 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:12.096Z,1348079112.096 [AHRS_sp3003D] No Fault, FailCount= 2
2012-09-19T18:25:12.426Z,1348079112.427 [NavChartDb](INFO): Charting 548p6
2012-09-19T18:25:13.153Z,1348079113.153 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:13.230Z,1348079113.230 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:13.231Z,1348079113.231 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:13.235Z,1348079113.234 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:13.235Z,1348079113.235 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:13.235Z,1348079113.235 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:13.239Z,1348079113.239 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:13.241Z,1348079113.241 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:14.167Z,1348079114.167 [CommandLine](IMPORTANT): got command show state
2012-09-19T18:25:14.167Z,1348079114.167 [CommandLine](INFO): Mission State:

2012-09-19T18:25:14.167Z,1348079114.167 [CommandLine](INFO): Default->Default:Iridium/0
2012-09-19T18:25:14.168Z,1348079114.168 [CommandLine](INFO): Default:GPS->Default:GPS:Read_GPS/0
2012-09-19T18:25:14.168Z,1348079114.168 [CommandLine](INFO): Default:Iridium->Default:Iridium:Read_Iridium/0
2012-09-19T18:25:14.168Z,1348079114.168 [CommandLine](INFO): Startup->/0
2012-09-19T18:25:14.169Z,1348079114.169 [CommandLine](INFO): Startup:StartupSatComms->/0
2012-09-19T18:25:15.627Z,1348079115.627 [NavChartDb](INFO): Charting 731p5
2012-09-19T18:25:21.743Z,1348079121.743 [NavChartDb](INFO): Charting 914p4
2012-09-19T18:25:26.264Z,1348079126.264 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:25:26.264Z,1348079126.264 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:25:26.264Z,1348079126.264 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:26.599Z,1348079126.599 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:26.681Z,1348079126.681 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:26.735Z,1348079126.735 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:27.279Z,1348079127.279 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:27.280Z,1348079127.280 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:25:28.406Z,1348079128.406 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:28.407Z,1348079128.407 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:28.434Z,1348079128.434 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:28.435Z,1348079128.434 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:28.435Z,1348079128.435 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:28.439Z,1348079128.439 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:28.441Z,1348079128.441 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:28.539Z,1348079128.539 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:36.491Z,1348079136.491 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:25:36.491Z,1348079136.491 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:25:36.491Z,1348079136.491 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:36.815Z,1348079136.815 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:37.026Z,1348079137.026 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:37.091Z,1348079137.091 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:37.911Z,1348079137.911 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:37.911Z,1348079137.911 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:25:38.598Z,1348079138.598 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:38.599Z,1348079138.599 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:38.626Z,1348079138.626 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:38.627Z,1348079138.626 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:38.627Z,1348079138.627 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:38.631Z,1348079138.631 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:38.669Z,1348079138.669 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:38.715Z,1348079138.715 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:41.411Z,1348079141.411 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:25:41.412Z,1348079141.411 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:25:41.412Z,1348079141.412 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:41.467Z,1348079141.467 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:41.509Z,1348079141.509 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:41.791Z,1348079141.791 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:42.046Z,1348079142.046 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:42.046Z,1348079142.046 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:25:43.299Z,1348079143.299 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:43.299Z,1348079143.299 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:43.330Z,1348079143.330 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:43.331Z,1348079143.331 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:43.331Z,1348079143.331 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:43.335Z,1348079143.335 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:43.337Z,1348079143.337 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:43.454Z,1348079143.454 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:46.839Z,1348079146.839 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:25:46.839Z,1348079146.839 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:25:46.839Z,1348079146.839 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:46.878Z,1348079146.878 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:46.923Z,1348079146.923 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:47.287Z,1348079147.287 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:47.783Z,1348079147.783 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:47.783Z,1348079147.783 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:25:48.228Z,1348079148.228 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:49.154Z,1348079149.154 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:49.154Z,1348079149.155 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:49.227Z,1348079149.227 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:49.227Z,1348079149.227 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:49.227Z,1348079149.227 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:49.231Z,1348079149.231 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:49.233Z,1348079149.233 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:52.667Z,1348079152.667 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:25:52.668Z,1348079152.668 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:25:52.668Z,1348079152.668 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:52.963Z,1348079152.963 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:53.169Z,1348079153.169 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:53.254Z,1348079153.254 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:54.058Z,1348079154.058 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:54.058Z,1348079154.058 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:25:54.470Z,1348079154.470 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:54.471Z,1348079154.471 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:54.475Z,1348079154.474 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:54.475Z,1348079154.475 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:54.475Z,1348079154.475 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:54.479Z,1348079154.479 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:54.481Z,1348079154.481 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:54.505Z,1348079154.505 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:25:56.355Z,1348079156.355 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-19T18:25:56.355Z,1348079156.355 [AHRS_sp3003D] Communications Fault, FailCount= 2
2012-09-19T18:25:56.355Z,1348079156.355 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:25:56.383Z,1348079156.383 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:25:56.467Z,1348079156.467 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:25:56.587Z,1348079156.587 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:25:57.407Z,1348079157.407 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:25:57.407Z,1348079157.407 [AHRS_sp3003D] No Fault, FailCount= 2
2012-09-19T18:25:57.891Z,1348079157.891 [DVL_micro](INFO): Querying output modes
2012-09-19T18:25:57.891Z,1348079157.891 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:25:57.895Z,1348079157.895 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:25:57.895Z,1348079157.895 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:25:57.895Z,1348079157.895 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:25:57.899Z,1348079157.899 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:25:57.901Z,1348079157.901 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:25:59.052Z,1348079159.052 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:26:00.692Z,1348079160.692 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:26:00.692Z,1348079160.692 [AHRS_sp3003D] Communications Fault, FailCount= 3
2012-09-19T18:26:00.692Z,1348079160.692 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:26:00.752Z,1348079160.751 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:26:00.796Z,1348079160.796 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:26:00.955Z,1348079160.955 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:26:00.955Z,1348079160.955 [AHRS_sp3003D] No Fault, FailCount= 3
2012-09-19T18:26:02.454Z,1348079162.454 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:26:06.591Z,1348079166.591 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:26:06.591Z,1348079166.591 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:26:06.591Z,1348079166.591 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:26:06.891Z,1348079166.891 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:26:07.051Z,1348079167.051 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:26:07.105Z,1348079167.105 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:26:07.639Z,1348079167.639 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:26:07.639Z,1348079167.639 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:26:08.410Z,1348079168.411 [DVL_micro](INFO): Querying output modes
2012-09-19T18:26:08.411Z,1348079168.411 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:26:08.418Z,1348079168.418 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:26:08.419Z,1348079168.419 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:26:08.419Z,1348079168.419 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:26:08.427Z,1348079168.427 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:26:08.429Z,1348079168.429 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:26:09.450Z,1348079169.450 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:26:16.845Z,1348079176.845 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:26:16.845Z,1348079176.845 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:26:16.845Z,1348079176.845 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:26:16.899Z,1348079176.899 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:26:16.945Z,1348079176.944 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:26:17.095Z,1348079177.095 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:26:17.095Z,1348079177.095 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:26:18.308Z,1348079178.308 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:26:21.307Z,1348079181.307 [AHRS_sp3003D](FAULT): Read Acceleration Vector Failure.
2012-09-19T18:26:21.307Z,1348079181.307 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:26:21.307Z,1348079181.307 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:26:21.347Z,1348079181.347 [DVL_micro](INFO): resume:Powering up
2012-09-19T18:26:21.369Z,1348079181.369 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:26:21.422Z,1348079181.422 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:26:21.537Z,1348079181.537 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:26:21.538Z,1348079181.537 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:26:22.828Z,1348079182.828 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:26:22.854Z,1348079182.855 [DVL_micro](INFO): Querying output modes
2012-09-19T18:26:22.855Z,1348079182.855 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-19T18:26:22.859Z,1348079182.859 [DVL_micro](DEBUG): cmdResponse: 01
2012-09-19T18:26:22.859Z,1348079182.859 [DVL_micro](INFO): NQ1 output enabled
2012-09-19T18:26:22.859Z,1348079182.859 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-19T18:26:22.863Z,1348079182.863 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-19T18:26:22.865Z,1348079182.865 [DVL_micro](INFO): pause:Powering down
2012-09-19T18:26:27.732Z,1348079187.732 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-19T18:26:27.732Z,1348079187.732 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-19T18:26:27.732Z,1348079187.732 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-19T18:26:27.801Z,1348079187.801 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-19T18:26:27.846Z,1348079187.846 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:26:27.875Z,1348079187.875 [CommandLine](IMPORTANT): got command quit
2012-09-19T18:26:27.970Z,1348079187.970 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-19T18:26:27.970Z,1348079187.970 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-19T18:26:28.979Z,1348079188.979 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-09-19T18:26:28.979Z,1348079188.979 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-09-19T18:26:30.255Z,1348079190.255 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-19T18:26:31.818Z,1348079191.819 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2012-09-19T18:26:32.075Z,1348079192.075 [WetLabsBB2FL](INFO): Powering down
2012-09-19T18:26:32.094Z,1348079192.094 [ComponentRegistry](INFO): Shutting down Turbulence_NPS ThreadHandler
2012-09-19T18:26:32.175Z,1348079192.175 [Turbulence_NPS](INFO): Powering down
2012-09-19T18:26:32.194Z,1348079192.194 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-09-19T18:26:32.439Z,1348079192.439 [CTD_NeilBrown](INFO): Powering down
2012-09-19T18:26:32.454Z,1348079192.454 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2012-09-19T18:26:32.803Z,1348079192.803 [DVL_micro](INFO): uninitialize:Powering down
2012-09-19T18:26:32.815Z,1348079192.815 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-09-19T18:26:33.035Z,1348079193.035 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-09-19T18:26:33.055Z,1348079193.055 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-09-19T18:26:33.057Z,1348079193.057 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-09-19T18:26:33.371Z,1348079193.371 [controlThread](DEBUG): Uninitializing ControlThread
2012-09-19T18:26:33.371Z,1348079193.371 [AHRS_sp3003D](INFO): Powering down
2012-09-19T18:26:33.459Z,1348079193.459 [NAL9602](INFO): Powering down
2012-09-19T18:26:33.461Z,1348079193.461 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-19T18:26:33.461Z,1348079193.461 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-09-19T18:26:33.463Z,1348079193.463 [Default] Stopped
2012-09-19T18:26:33.463Z,1348079193.463 [Default](INFO): Aggregate::uninitialize Default
2012-09-19T18:26:33.463Z,1348079193.463 [Default:GPS] Stopped
2012-09-19T18:26:33.463Z,1348079193.463 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-19T18:26:33.463Z,1348079193.463 [Default:GPS:A.SetSpeed] Stopped
2012-09-19T18:26:33.463Z,1348079193.464 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-19T18:26:33.464Z,1348079193.464 [Default:GPS:Read_GPS] Stopped
2012-09-19T18:26:33.464Z,1348079193.464 [Default:Iridium] Stopped
2012-09-19T18:26:33.464Z,1348079193.464 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-19T18:26:33.464Z,1348079193.464 [Default:Iridium:A.SetSpeed] Stopped
2012-09-19T18:26:33.464Z,1348079193.464 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-19T18:26:33.464Z,1348079193.464 [Default:Iridium:Read_Iridium] Stopped
2012-09-19T18:26:33.464Z,1348079193.464 [Default:D.SetSpeed] Stopped
2012-09-19T18:26:33.464Z,1348079193.464 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-09-19T18:26:33.464Z,1348079193.464 [Default:E.GoToSurface] Stopped
2012-09-19T18:26:33.464Z,1348079193.464 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-19T18:26:33.468Z,1348079193.468 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-09-19T18:26:33.469Z,1348079193.469 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-09-19T18:26:33.469Z,1348079193.469 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-09-19T18:26:33.470Z,1348079193.470 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-09-19T18:26:33.470Z,1348079193.470 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-09-19T18:26:33.470Z,1348079193.470 [BuoyancyServo](INFO): Powering down
2012-09-19T18:26:33.471Z,1348079193.471 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-19T18:26:33.471Z,1348079193.471 [ElevatorServo](INFO): Powering down
2012-09-19T18:26:33.472Z,1348079193.472 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-19T18:26:33.472Z,1348079193.472 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-09-19T18:26:33.472Z,1348079193.472 [RudderServo](INFO): Powering down
2012-09-19T18:26:33.473Z,1348079193.473 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-09-19T18:26:33.473Z,1348079193.473 [ThrusterServo](INFO): Powering down
2012-09-19T18:26:33.474Z,1348079193.474 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-09-19T18:26:33.475Z,1348079193.475 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-09-19T18:26:33.475Z,1348079193.475 [CBIT](DEBUG): Uninitialize CBIT Component.