2012-10-03T16:08:13.464Z,1349280493.464 [Supervisor](DEBUG): Initializing supervisor.
2012-10-03T16:08:13.477Z,1349280493.477 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-10-03T16:08:13.478Z,1349280493.478 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-10-03T16:08:13.489Z,1349280493.489 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-10-03T16:08:13.494Z,1349280493.494 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-10-03T16:08:13.517Z,1349280493.517 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-10-03T16:08:13.529Z,1349280493.529 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-10-03T16:08:13.530Z,1349280493.530 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-10-03T16:08:13.531Z,1349280493.531 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-10-03T16:08:13.532Z,1349280493.532 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-10-03T16:08:14.072Z,1349280494.072 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-10-03T16:08:14.073Z,1349280494.073 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-10-03T16:08:14.450Z,1349280494.450 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-10-03T16:08:14.450Z,1349280494.450 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-10-03T16:08:14.600Z,1349280494.600 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-10-03T16:08:14.601Z,1349280494.601 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-10-03T16:08:14.975Z,1349280494.975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-10-03T16:08:14.975Z,1349280494.975 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-10-03T16:08:15.224Z,1349280495.224 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-10-03T16:08:15.225Z,1349280495.224 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-10-03T16:08:15.662Z,1349280495.662 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-10-03T16:08:15.662Z,1349280495.662 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-10-03T16:08:15.931Z,1349280495.931 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-10-03T16:08:15.932Z,1349280495.932 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-10-03T16:08:16.175Z,1349280496.175 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-10-03T16:08:16.176Z,1349280496.175 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-10-03T16:08:16.272Z,1349280496.272 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-10-03T16:08:16.272Z,1349280496.272 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-10-03T16:08:16.654Z,1349280496.654 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-10-03T16:08:16.654Z,1349280496.654 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-10-03T16:08:16.766Z,1349280496.766 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-10-03T16:08:16.767Z,1349280496.767 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-10-03T16:08:16.850Z,1349280496.850 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-10-03T16:08:16.851Z,1349280496.851 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-10-03T16:08:16.951Z,1349280496.951 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-10-03T16:08:17.075Z,1349280497.075 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-10-03T16:08:17.160Z,1349280497.160 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-10-03T16:08:17.259Z,1349280497.259 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-10-03T16:08:17.357Z,1349280497.357 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-10-03T16:08:17.471Z,1349280497.471 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-10-03T16:08:17.559Z,1349280497.559 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-10-03T16:08:17.644Z,1349280497.644 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2012-10-03T16:08:17.672Z,1349280497.672 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-10-03T16:08:17.814Z,1349280497.814 [InternalSim] Loaded
2012-10-03T16:08:17.814Z,1349280497.814 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-10-03T16:08:17.815Z,1349280497.815 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-10-03T16:08:17.815Z,1349280497.815 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-10-03T16:08:17.874Z,1349280497.874 [SBIT](DEBUG): Construct Startup Built In Test.
2012-10-03T16:08:17.887Z,1349280497.886 [SBIT] Loaded
2012-10-03T16:08:17.887Z,1349280497.887 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-10-03T16:08:17.888Z,1349280497.888 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-10-03T16:08:17.915Z,1349280497.915 [IBIT] Loaded
2012-10-03T16:08:17.915Z,1349280497.915 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-10-03T16:08:17.919Z,1349280497.919 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-10-03T16:08:18.033Z,1349280498.033 [CBIT] Loaded
2012-10-03T16:08:18.033Z,1349280498.033 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-10-03T16:08:18.034Z,1349280498.034 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-10-03T16:08:18.034Z,1349280498.034 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-10-03T16:08:18.179Z,1349280498.179 [BuoyancyServo] Loaded
2012-10-03T16:08:18.179Z,1349280498.179 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-10-03T16:08:18.188Z,1349280498.188 [ElevatorServo] Loaded
2012-10-03T16:08:18.189Z,1349280498.189 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-10-03T16:08:18.200Z,1349280498.200 [MassServo] Loaded
2012-10-03T16:08:18.200Z,1349280498.200 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-10-03T16:08:18.212Z,1349280498.212 [RudderServo] Loaded
2012-10-03T16:08:18.212Z,1349280498.212 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-10-03T16:08:18.224Z,1349280498.224 [ThrusterServo] Loaded
2012-10-03T16:08:18.224Z,1349280498.224 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-10-03T16:08:18.225Z,1349280498.224 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-10-03T16:08:18.225Z,1349280498.225 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-10-03T16:08:18.243Z,1349280498.243 [DepthRateCalculator] Loaded
2012-10-03T16:08:18.243Z,1349280498.243 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-10-03T16:08:23.020Z,1349280503.020 [HFRadarModelCalc] Loaded
2012-10-03T16:08:23.020Z,1349280503.020 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-10-03T16:08:23.036Z,1349280503.036 [NavChart] Loaded
2012-10-03T16:08:23.036Z,1349280503.036 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-10-03T16:08:23.041Z,1349280503.042 [PitchRateCalculator] Loaded
2012-10-03T16:08:23.042Z,1349280503.042 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-10-03T16:08:23.048Z,1349280503.048 [SpeedCalculator] Loaded
2012-10-03T16:08:23.048Z,1349280503.048 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-10-03T16:08:23.062Z,1349280503.062 [TempGradientCalculator] Loaded
2012-10-03T16:08:23.063Z,1349280503.063 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-10-03T16:08:23.068Z,1349280503.068 [YawRateCalculator] Loaded
2012-10-03T16:08:23.068Z,1349280503.069 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-10-03T16:08:23.087Z,1349280503.087 [Navigation] Loaded
2012-10-03T16:08:23.088Z,1349280503.088 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-10-03T16:08:23.088Z,1349280503.088 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-10-03T16:08:23.089Z,1349280503.089 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-10-03T16:08:23.312Z,1349280503.312 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-10-03T16:08:23.313Z,1349280503.313 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-10-03T16:08:23.336Z,1349280503.336 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-10-03T16:08:23.337Z,1349280503.337 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-10-03T16:08:23.378Z,1349280503.378 [VerticalControl](DEBUG): Construct VerticalControl.
2012-10-03T16:08:23.421Z,1349280503.421 [VerticalControl] Loaded
2012-10-03T16:08:23.421Z,1349280503.421 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-10-03T16:08:23.422Z,1349280503.422 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-10-03T16:08:23.442Z,1349280503.442 [HorizontalControl] Loaded
2012-10-03T16:08:23.442Z,1349280503.442 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-10-03T16:08:23.443Z,1349280503.443 [SpeedControl](DEBUG): Construct SpeedControl.
2012-10-03T16:08:23.445Z,1349280503.445 [SpeedControl] Loaded
2012-10-03T16:08:23.445Z,1349280503.445 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-10-03T16:08:23.446Z,1349280503.446 [LoopControl](DEBUG): Construct LoopControl.
2012-10-03T16:08:23.447Z,1349280503.447 [LoopControl] Loaded
2012-10-03T16:08:23.447Z,1349280503.447 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-10-03T16:08:23.447Z,1349280503.447 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-10-03T16:08:23.448Z,1349280503.448 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-10-03T16:08:23.453Z,1349280503.453 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-10-03T16:08:23.458Z,1349280503.458 [AsyncPiEstimator] Loaded
2012-10-03T16:08:23.458Z,1349280503.458 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-10-03T16:08:23.459Z,1349280503.459 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406714E0
2012-10-03T16:08:23.460Z,1349280503.460 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-10-03T16:08:23.461Z,1349280503.461 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-10-03T16:08:23.587Z,1349280503.587 [AHRS_sp3003D] Loaded
2012-10-03T16:08:23.587Z,1349280503.587 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-10-03T16:08:23.601Z,1349280503.601 [Depth_Keller] Loaded
2012-10-03T16:08:23.601Z,1349280503.601 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-10-03T16:08:23.607Z,1349280503.606 [DropWeight] Loaded
2012-10-03T16:08:23.607Z,1349280503.607 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-10-03T16:08:23.719Z,1349280503.719 [DVL_micro] Loaded
2012-10-03T16:08:23.719Z,1349280503.719 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-10-03T16:08:23.720Z,1349280503.720 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406F14E0
2012-10-03T16:08:23.801Z,1349280503.801 [NAL9602] Loaded
2012-10-03T16:08:23.801Z,1349280503.801 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-10-03T16:08:23.850Z,1349280503.850 [Onboard] Loaded
2012-10-03T16:08:23.851Z,1349280503.851 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-10-03T16:08:23.857Z,1349280503.857 [Radio_Freewave] Loaded
2012-10-03T16:08:23.858Z,1349280503.858 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-10-03T16:08:23.859Z,1349280503.859 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-10-03T16:08:23.859Z,1349280503.859 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-10-03T16:08:23.931Z,1349280503.931 [CTD_NeilBrown] Loaded
2012-10-03T16:08:23.931Z,1349280503.931 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-10-03T16:08:23.932Z,1349280503.932 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407494E0
2012-10-03T16:08:23.942Z,1349280503.942 [PAR_Licor] Loaded
2012-10-03T16:08:23.943Z,1349280503.943 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-10-03T16:08:23.959Z,1349280503.959 [Turbulence_NPS] Loaded
2012-10-03T16:08:23.959Z,1349280503.959 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-10-03T16:08:23.960Z,1349280503.960 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407794E0
2012-10-03T16:08:23.989Z,1349280503.989 [WetLabsBB2FL] Loaded
2012-10-03T16:08:23.989Z,1349280503.989 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-10-03T16:08:23.990Z,1349280503.990 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407A94E0
2012-10-03T16:08:23.991Z,1349280503.991 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-10-03T16:08:23.993Z,1349280503.993 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-10-03T16:08:23.994Z,1349280503.994 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-10-03T16:08:24.001Z,1349280504.001 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-10-03T16:08:24.002Z,1349280504.002 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407D94E0
2012-10-03T16:08:24.007Z,1349280504.007 [Supervisor](DEBUG): Running supervisor.
2012-10-03T16:08:24.008Z,1349280504.008 [CommandLine](INFO): Thread ID is 1763
2012-10-03T16:08:24.010Z,1349280504.010 [controlThread](INFO): Thread ID is 1762
2012-10-03T16:08:24.011Z,1349280504.011 [controlThread](DEBUG): Initializing ControlThread
2012-10-03T16:08:24.011Z,1349280504.011 [CycleStarter](INFO): Thread ID is 1761
2012-10-03T16:08:24.012Z,1349280504.012 [InternalSim](DEBUG):  InternalSim initializing...
2012-10-03T16:08:24.112Z,1349280504.112 [AsyncPiEstimator](INFO): Thread ID is 1826
2012-10-03T16:08:24.112Z,1349280504.112 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-10-03T16:08:24.174Z,1349280504.174 [DVL_micro](INFO): Thread ID is 1827
2012-10-03T16:08:24.249Z,1349280504.249 [CTD_NeilBrown](INFO): Thread ID is 1828
2012-10-03T16:08:24.250Z,1349280504.250 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-10-03T16:08:24.258Z,1349280504.258 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-10-03T16:08:24.288Z,1349280504.288 [Turbulence_NPS](INFO): Thread ID is 1829
2012-10-03T16:08:24.289Z,1349280504.289 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-10-03T16:08:24.290Z,1349280504.290 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1
2012-10-03T16:08:24.297Z,1349280504.297 [DVL_micro](INFO): Initializing
2012-10-03T16:08:24.298Z,1349280504.298 [DVL_micro](INFO): start:Powering up
2012-10-03T16:08:24.298Z,1349280504.298 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:08:24.299Z,1349280504.299 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:08:24.303Z,1349280504.303 [WetLabsBB2FL](INFO): Thread ID is 1830
2012-10-03T16:08:24.303Z,1349280504.303 [WetLabsBB2FL](INFO): Powering down
2012-10-03T16:08:24.324Z,1349280504.325 [SBIT](INFO): Initialize SBIT Component.
2012-10-03T16:08:24.331Z,1349280504.331 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9922
2012-10-03T16:08:24.332Z,1349280504.332 [IBIT](INFO): Initialize IBIT Component.
2012-10-03T16:08:24.333Z,1349280504.333 [CBIT](DEBUG): Initialize CBIT Component.
2012-10-03T16:08:24.333Z,1349280504.333 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2012-10-03T16:08:24.338Z,1349280504.338 [NavChartDb](INFO): Thread ID is 1831
2012-10-03T16:08:24.340Z,1349280504.339 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-10-03T16:08:24.355Z,1349280504.355 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-10-03T16:08:24.356Z,1349280504.356 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-10-03T16:08:24.356Z,1349280504.356 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-10-03T16:08:24.356Z,1349280504.356 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-10-03T16:08:24.357Z,1349280504.357 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-10-03T16:08:24.366Z,1349280504.366 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-10-03T16:08:24.367Z,1349280504.367 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-10-03T16:08:24.367Z,1349280504.367 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-10-03T16:08:24.368Z,1349280504.368 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-10-03T16:08:24.368Z,1349280504.368 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-10-03T16:08:24.369Z,1349280504.369 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-10-03T16:08:24.370Z,1349280504.370 [Navigation](DEBUG): Initializing Navigation.
2012-10-03T16:08:24.370Z,1349280504.370 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-10-03T16:08:24.372Z,1349280504.372 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-10-03T16:08:24.372Z,1349280504.372 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-10-03T16:08:24.373Z,1349280504.373 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-10-03T16:08:24.398Z,1349280504.398 [Turbulence_NPS](INFO): Pause powering down
2012-10-03T16:08:24.410Z,1349280504.410 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-10-03T16:08:24.438Z,1349280504.438 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-03T16:08:24.448Z,1349280504.448 [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-10-03T16:08:24.449Z,1349280504.449 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-10-03T16:08:24.477Z,1349280504.477 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-10-03T16:08:24.479Z,1349280504.479 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-10-03T16:08:24.482Z,1349280504.482 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-03T16:08:24.490Z,1349280504.490 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-10-03T16:08:24.493Z,1349280504.493 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-03T16:08:24.500Z,1349280504.500 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-10-03T16:08:24.509Z,1349280504.509 [Default:D.SetSpeed](DEBUG): Construct.
2012-10-03T16:08:24.512Z,1349280504.512 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-03T16:08:24.517Z,1349280504.517 [Default:F.Wait](DEBUG): Construct Wait.
2012-10-03T16:08:24.521Z,1349280504.520 [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-10-03T16:08:24.525Z,1349280504.525 [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-10-03T16:08:24.546Z,1349280504.546 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-10-03T16:08:24.686Z,1349280504.685 [Depth_Keller](INFO): A/D timeout, 5 tries over 129 ms

2012-10-03T16:08:24.686Z,1349280504.686 [Depth_Keller] Data Fault, FailCount= 1
2012-10-03T16:08:24.686Z,1349280504.686 [Depth_Keller](ERROR): Data Fault
2012-10-03T16:08:25.221Z,1349280505.221 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-10-03T16:08:25.263Z,1349280505.263 [Radio_Freewave](INFO): Powering up
2012-10-03T16:08:25.433Z,1349280505.434 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-10-03T16:08:25.438Z,1349280505.438 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-10-03T16:08:25.444Z,1349280505.444 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-10-03T16:08:25.446Z,1349280505.446 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-10-03T16:08:25.455Z,1349280505.455 [MassServo](DEBUG): Initializing EZServoServo.
2012-10-03T16:08:25.458Z,1349280505.458 [MassServo](DEBUG): Initializing MassServo.
2012-10-03T16:08:25.464Z,1349280505.464 [RudderServo](DEBUG): Initializing RudderServo.
2012-10-03T16:08:25.470Z,1349280505.470 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-10-03T16:08:25.470Z,1349280505.470 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-10-03T16:08:25.493Z,1349280505.493 [CBIT](ERROR): Data Fault in component: Depth_Keller
2012-10-03T16:08:25.493Z,1349280505.493 [CBIT](INFO): Clearing failed state for component Depth_Keller
2012-10-03T16:08:25.493Z,1349280505.493 [Depth_Keller] No Fault, FailCount= 1
2012-10-03T16:08:26.362Z,1349280506.362 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:08:26.362Z,1349280506.362 [DVL_micro](INFO): Querying output modes
2012-10-03T16:08:26.362Z,1349280506.362 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:08:27.365Z,1349280507.365 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2012-10-03T16:08:27.366Z,1349280507.366 [AHRS_sp3003D](ERROR): readHeadingMagBin got 0x00
2012-10-03T16:08:27.366Z,1349280507.366 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2012-10-03T16:08:27.366Z,1349280507.366 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2012-10-03T16:08:27.366Z,1349280507.366 [AHRS_sp3003D](ERROR): Hardware Fault
2012-10-03T16:08:28.231Z,1349280508.231 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2012-10-03T16:08:28.286Z,1349280508.286 [AHRS_sp3003D](INFO): Powering down
2012-10-03T16:08:28.365Z,1349280508.365 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:28.365Z,1349280508.365 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:08:28.366Z,1349280508.366 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:08:29.036Z,1349280509.036 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-10-03T16:08:29.036Z,1349280509.036 [AHRS_sp3003D] No Fault, FailCount= 1
2012-10-03T16:08:29.108Z,1349280509.108 [NAL9602](INFO): Powering up NAL9602
2012-10-03T16:08:29.476Z,1349280509.476 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-10-03T16:08:30.369Z,1349280510.369 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:30.375Z,1349280510.375 [DVL_micro](INFO): pause:Powering down
2012-10-03T16:08:30.729Z,1349280510.729 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2012-10-03T16:08:30.729Z,1349280510.729 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2012-10-03T16:08:30.729Z,1349280510.730 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2012-10-03T16:08:30.729Z,1349280510.730 [AHRS_sp3003D](ERROR): Hardware Fault
2012-10-03T16:08:31.010Z,1349280511.010 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:08:31.010Z,1349280511.010 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:08:31.010Z,1349280511.010 [DVL_micro](INFO): resume:Powering up
2012-10-03T16:08:31.011Z,1349280511.011 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:08:31.240Z,1349280511.240 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2012-10-03T16:08:31.306Z,1349280511.306 [AHRS_sp3003D](INFO): Powering down
2012-10-03T16:08:31.628Z,1349280511.628 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-10-03T16:08:31.628Z,1349280511.628 [AHRS_sp3003D] No Fault, FailCount= 2
2012-10-03T16:08:32.716Z,1349280512.716 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-10-03T16:08:33.066Z,1349280513.066 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:08:33.066Z,1349280513.066 [DVL_micro](INFO): Querying output modes
2012-10-03T16:08:33.066Z,1349280513.066 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:08:34.197Z,1349280514.197 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2012-10-03T16:08:34.197Z,1349280514.197 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2012-10-03T16:08:34.198Z,1349280514.197 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2012-10-03T16:08:34.198Z,1349280514.197 [AHRS_sp3003D](ERROR): Hardware Fault
2012-10-03T16:08:34.285Z,1349280514.285 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2012-10-03T16:08:34.325Z,1349280514.325 [AHRS_sp3003D](INFO): Powering down
2012-10-03T16:08:34.793Z,1349280514.793 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-10-03T16:08:34.793Z,1349280514.793 [AHRS_sp3003D] No Fault, FailCount= 3
2012-10-03T16:08:35.137Z,1349280515.137 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:35.137Z,1349280515.137 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:08:35.138Z,1349280515.138 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:08:35.996Z,1349280515.996 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-10-03T16:08:37.061Z,1349280517.061 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2012-10-03T16:08:37.061Z,1349280517.061 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2012-10-03T16:08:37.062Z,1349280517.062 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2012-10-03T16:08:37.062Z,1349280517.062 [AHRS_sp3003D](ERROR): Hardware Fault
2012-10-03T16:08:37.325Z,1349280517.325 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:37.327Z,1349280517.327 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:08:37.327Z,1349280517.327 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:08:38.113Z,1349280518.113 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2012-10-03T16:08:38.179Z,1349280518.180 [AHRS_sp3003D](INFO): Powering down
2012-10-03T16:08:39.216Z,1349280519.217 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-10-03T16:08:39.216Z,1349280519.217 [AHRS_sp3003D] No Fault, FailCount= 4
2012-10-03T16:08:39.410Z,1349280519.410 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:08:39.410Z,1349280519.410 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:08:39.660Z,1349280519.660 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-10-03T16:08:39.694Z,1349280519.694 [NAL9602](INFO): NAL9602 initialized
2012-10-03T16:08:40.713Z,1349280520.713 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2012-10-03T16:08:40.713Z,1349280520.713 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2012-10-03T16:08:40.714Z,1349280520.714 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2012-10-03T16:08:40.714Z,1349280520.714 [AHRS_sp3003D](ERROR): Hardware Fault
2012-10-03T16:08:41.105Z,1349280521.105 [SBIT](IMPORTANT): Beginning Startup BIT
2012-10-03T16:08:41.108Z,1349280521.108 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2012-10-03T16:08:41.108Z,1349280521.108 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2012-10-03T16:08:41.108Z,1349280521.109 [CBIT](IMPORTANT): Beginning GF scan
2012-10-03T16:08:41.450Z,1349280521.450 [AHRS_sp3003D](INFO): Powering down
2012-10-03T16:08:41.451Z,1349280521.451 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:41.451Z,1349280521.451 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:08:41.451Z,1349280521.451 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:08:43.709Z,1349280523.709 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:43.709Z,1349280523.709 [DVL_micro](INFO): Querying output modes
2012-10-03T16:08:43.710Z,1349280523.710 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:08:43.802Z,1349280523.802 [ElevatorServo](FAULT): Overload Error
2012-10-03T16:08:43.802Z,1349280523.802 [ElevatorServo] Hardware Fault, FailCount= 1
2012-10-03T16:08:43.802Z,1349280523.802 [ElevatorServo](ERROR): Hardware Fault
2012-10-03T16:08:43.861Z,1349280523.861 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-10-03T16:08:43.974Z,1349280523.974 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-10-03T16:08:43.975Z,1349280523.975 [ElevatorServo](INFO): Powering down
2012-10-03T16:08:44.553Z,1349280524.553 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-10-03T16:08:44.553Z,1349280524.553 [ElevatorServo] No Fault, FailCount= 1
2012-10-03T16:08:45.667Z,1349280525.667 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-10-03T16:08:45.713Z,1349280525.713 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:45.714Z,1349280525.714 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:08:45.714Z,1349280525.714 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:08:45.786Z,1349280525.786 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-10-03T16:08:45.787Z,1349280525.787 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-10-03T16:08:47.758Z,1349280527.758 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:49.834Z,1349280529.834 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:08:49.834Z,1349280529.834 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:08:51.867Z,1349280531.867 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:08:51.867Z,1349280531.867 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:08:51.886Z,1349280531.886 [ElevatorServo](FAULT): Overload Error
2012-10-03T16:08:51.886Z,1349280531.886 [ElevatorServo] Hardware Fault, FailCount= 2
2012-10-03T16:08:51.886Z,1349280531.886 [ElevatorServo](ERROR): Hardware Fault
2012-10-03T16:08:52.037Z,1349280532.037 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-10-03T16:08:52.158Z,1349280532.158 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-10-03T16:08:52.158Z,1349280532.158 [ElevatorServo](INFO): Powering down
2012-10-03T16:08:52.166Z,1349280532.166 [CBIT](INFO): Clearing failed state for component ElevatorServo
2012-10-03T16:08:52.166Z,1349280532.166 [ElevatorServo] No Fault, FailCount= 2
2012-10-03T16:08:54.125Z,1349280534.125 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:54.125Z,1349280534.125 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:08:54.126Z,1349280534.126 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:08:54.486Z,1349280534.486 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-10-03T16:08:54.607Z,1349280534.606 [ElevatorServo](DEBUG): Initialization error opening port: port not yet opened
2012-10-03T16:08:54.607Z,1349280534.607 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-10-03T16:08:56.150Z,1349280536.150 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:56.150Z,1349280536.150 [DVL_micro](INFO): Querying output modes
2012-10-03T16:08:56.150Z,1349280536.150 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:08:58.245Z,1349280538.245 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:08:58.245Z,1349280538.245 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:08:58.246Z,1349280538.246 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:09:00.250Z,1349280540.250 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:01.930Z,1349280541.930 [ElevatorServo](FAULT): Overload Error
2012-10-03T16:09:01.930Z,1349280541.930 [ElevatorServo] Hardware Fault, FailCount= 3
2012-10-03T16:09:01.930Z,1349280541.930 [ElevatorServo](ERROR): Hardware Fault
2012-10-03T16:09:01.986Z,1349280541.986 [CBIT](ERROR): Hardware Fault in component: ElevatorServo
2012-10-03T16:09:01.986Z,1349280541.986 [CBIT](CRITICAL): Hardware Fault in component: ElevatorServo
2012-10-03T16:09:02.098Z,1349280542.098 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-10-03T16:09:02.098Z,1349280542.099 [ElevatorServo](INFO): Powering down
2012-10-03T16:09:02.254Z,1349280542.254 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:09:02.254Z,1349280542.254 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:09:04.262Z,1349280544.262 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:09:04.262Z,1349280544.262 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:09:06.369Z,1349280546.369 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:06.369Z,1349280546.369 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:09:06.370Z,1349280546.370 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:09:08.373Z,1349280548.373 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:08.373Z,1349280548.374 [DVL_micro](INFO): Querying output modes
2012-10-03T16:09:08.374Z,1349280548.374 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:09:10.381Z,1349280550.381 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:10.382Z,1349280550.382 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:09:10.382Z,1349280550.382 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:09:10.384Z,1349280550.384 [CBIT](IMPORTANT): No ground fault detected
2012-10-03T16:09:12.385Z,1349280552.385 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:14.542Z,1349280554.542 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:09:14.542Z,1349280554.542 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:09:16.550Z,1349280556.550 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:09:16.550Z,1349280556.550 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:09:18.553Z,1349280558.553 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:18.553Z,1349280558.553 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:09:18.554Z,1349280558.554 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:09:20.765Z,1349280560.765 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:20.765Z,1349280560.765 [DVL_micro](INFO): Querying output modes
2012-10-03T16:09:20.766Z,1349280560.766 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:09:22.917Z,1349280562.917 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:22.917Z,1349280562.917 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:09:22.918Z,1349280562.918 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:09:24.922Z,1349280564.922 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:26.926Z,1349280566.926 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:09:26.926Z,1349280566.926 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:09:28.998Z,1349280568.998 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:09:28.998Z,1349280568.998 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:09:31.001Z,1349280571.001 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:31.001Z,1349280571.001 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:09:31.002Z,1349280571.002 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:09:33.005Z,1349280573.006 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:33.006Z,1349280573.006 [DVL_micro](INFO): Querying output modes
2012-10-03T16:09:33.006Z,1349280573.006 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:09:34.675Z,1349280574.675 [SBIT](IMPORTANT): SBIT PASSED
2012-10-03T16:09:35.009Z,1349280575.009 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:35.009Z,1349280575.009 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:09:35.010Z,1349280575.010 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:09:35.044Z,1349280575.044 [MissionManager](IMPORTANT): Started mission Startup
2012-10-03T16:09:35.045Z,1349280575.045 [Startup] Running Loop=1
2012-10-03T16:09:35.045Z,1349280575.045 [Startup](INFO): Aggregate::initialize Startup
2012-10-03T16:09:35.045Z,1349280575.045 [Startup:A.GoToSurface] Running Loop=1
2012-10-03T16:09:35.045Z,1349280575.045 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-03T16:09:35.051Z,1349280575.051 [Startup:StartupSatComms] Running Loop=1
2012-10-03T16:09:35.051Z,1349280575.051 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-10-03T16:09:35.052Z,1349280575.052 [Startup:StartupSatComms:A] Running Loop=1
2012-10-03T16:09:35.448Z,1349280575.448 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-10-03T16:09:37.013Z,1349280577.013 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:39.020Z,1349280579.020 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:09:39.020Z,1349280579.020 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:09:41.026Z,1349280581.026 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:09:41.026Z,1349280581.026 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:09:43.027Z,1349280583.027 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:43.027Z,1349280583.027 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:09:43.028Z,1349280583.028 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:09:45.029Z,1349280585.029 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:45.029Z,1349280585.029 [DVL_micro](INFO): Querying output modes
2012-10-03T16:09:45.030Z,1349280585.030 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:09:47.033Z,1349280587.033 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:47.033Z,1349280587.033 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:09:47.034Z,1349280587.034 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:09:49.037Z,1349280589.037 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:51.042Z,1349280591.042 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:09:51.042Z,1349280591.042 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:09:53.050Z,1349280593.050 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:09:53.050Z,1349280593.050 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:09:55.053Z,1349280595.053 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:55.054Z,1349280595.053 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:09:55.054Z,1349280595.054 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:09:57.057Z,1349280597.057 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:57.058Z,1349280597.057 [DVL_micro](INFO): Querying output modes
2012-10-03T16:09:57.058Z,1349280597.058 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:09:59.062Z,1349280599.062 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:09:59.062Z,1349280599.062 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:09:59.062Z,1349280599.062 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:10:01.065Z,1349280601.065 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:10:03.070Z,1349280603.070 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:10:03.070Z,1349280603.070 [DVL_micro](INFO): Cycling power to configure device.
2012-10-03T16:10:05.078Z,1349280605.078 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-03T16:10:05.078Z,1349280605.078 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2012-10-03T16:10:07.081Z,1349280607.081 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:10:07.081Z,1349280607.081 [DVL_micro](INFO): Enabling NQ1 output
2012-10-03T16:10:07.082Z,1349280607.082 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2012-10-03T16:10:09.085Z,1349280609.085 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:10:09.085Z,1349280609.085 [DVL_micro](INFO): Querying output modes
2012-10-03T16:10:09.086Z,1349280609.086 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-03T16:10:11.089Z,1349280611.089 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:10:11.089Z,1349280611.089 [DVL_micro](INFO): Output Modes: No Response
2012-10-03T16:10:11.090Z,1349280611.090 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-03T16:10:13.094Z,1349280613.093 [DVL_micro](DEBUG): cmdResponse: 
2012-10-03T16:10:15.098Z,1349280615.098 [DVL_micro](INFO): NQ1 requested
2012-10-03T16:10:15.098Z,1349280615.098 [DVL_micro](INFO): Cycling power to configure device.