2013-09-16T22:19:08.656Z,1379369948.656 [Supervisor](DEBUG): Initializing supervisor.
2013-09-16T22:19:08.661Z,1379369948.661 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-09-16T22:19:08.662Z,1379369948.662 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-09-16T22:19:08.665Z,1379369948.665 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-09-16T22:19:08.668Z,1379369948.668 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-09-16T22:19:08.678Z,1379369948.678 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-09-16T22:19:08.681Z,1379369948.681 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-09-16T22:19:08.682Z,1379369948.682 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-09-16T22:19:08.685Z,1379369948.685 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-09-16T22:19:08.686Z,1379369948.686 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-09-16T22:19:08.690Z,1379369948.690 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-09-16T22:19:09.001Z,1379369949.001 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-09-16T22:19:09.002Z,1379369949.002 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-09-16T22:19:09.218Z,1379369949.218 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-09-16T22:19:09.219Z,1379369949.219 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-09-16T22:19:09.317Z,1379369949.317 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-09-16T22:19:09.320Z,1379369949.320 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-09-16T22:19:09.445Z,1379369949.445 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-09-16T22:19:09.445Z,1379369949.445 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-09-16T22:19:09.603Z,1379369949.603 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-09-16T22:19:09.605Z,1379369949.605 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-09-16T22:19:09.862Z,1379369949.862 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-09-16T22:19:09.863Z,1379369949.863 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-09-16T22:19:10.048Z,1379369950.048 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-09-16T22:19:10.050Z,1379369950.050 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-09-16T22:19:10.341Z,1379369950.341 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-09-16T22:19:10.343Z,1379369950.343 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-09-16T22:19:10.460Z,1379369950.460 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-09-16T22:19:10.461Z,1379369950.461 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-09-16T22:19:10.914Z,1379369950.914 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-09-16T22:19:10.915Z,1379369950.915 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-09-16T22:19:11.033Z,1379369951.033 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-09-16T22:19:11.034Z,1379369951.034 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-09-16T22:19:11.130Z,1379369951.130 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-09-16T22:19:11.134Z,1379369951.134 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-09-16T22:19:11.244Z,1379369951.244 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-09-16T22:19:11.386Z,1379369951.386 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-09-16T22:19:11.493Z,1379369951.493 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-09-16T22:19:11.611Z,1379369951.611 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-09-16T22:19:11.719Z,1379369951.719 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-09-16T22:19:11.848Z,1379369951.848 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-09-16T22:19:11.955Z,1379369951.955 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-09-16T22:19:12.050Z,1379369952.050 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-09-16T22:19:12.058Z,1379369952.058 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-09-16T22:19:12.269Z,1379369952.269 [InternalSim] Loaded
2013-09-16T22:19:12.270Z,1379369952.270 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-09-16T22:19:12.270Z,1379369952.270 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-09-16T22:19:12.271Z,1379369952.271 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-09-16T22:19:12.392Z,1379369952.392 [SBIT](DEBUG): Construct Startup Built In Test.
2013-09-16T22:19:12.425Z,1379369952.425 [SBIT] Loaded
2013-09-16T22:19:12.425Z,1379369952.425 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-09-16T22:19:12.426Z,1379369952.426 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-09-16T22:19:12.455Z,1379369952.455 [IBIT] Loaded
2013-09-16T22:19:12.455Z,1379369952.455 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-09-16T22:19:12.457Z,1379369952.457 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-09-16T22:19:12.584Z,1379369952.584 [CBIT] Loaded
2013-09-16T22:19:12.584Z,1379369952.584 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-09-16T22:19:12.584Z,1379369952.584 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-09-16T22:19:12.585Z,1379369952.585 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-09-16T22:19:12.797Z,1379369952.797 [BuoyancyServo] Loaded
2013-09-16T22:19:12.797Z,1379369952.797 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-09-16T22:19:12.813Z,1379369952.813 [ElevatorServo] Loaded
2013-09-16T22:19:12.814Z,1379369952.814 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-09-16T22:19:12.825Z,1379369952.825 [MassServo] Loaded
2013-09-16T22:19:12.825Z,1379369952.825 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-09-16T22:19:12.837Z,1379369952.837 [RudderServo] Loaded
2013-09-16T22:19:12.837Z,1379369952.837 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-09-16T22:19:12.853Z,1379369952.853 [ThrusterServo] Loaded
2013-09-16T22:19:12.853Z,1379369952.853 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-09-16T22:19:12.853Z,1379369952.853 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-09-16T22:19:12.854Z,1379369952.854 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-09-16T22:19:12.944Z,1379369952.944 [DepthRateCalculator] Loaded
2013-09-16T22:19:12.944Z,1379369952.944 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-09-16T22:19:16.440Z,1379369956.440 [HFRadarModelCalc] Loaded
2013-09-16T22:19:16.440Z,1379369956.440 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-09-16T22:19:16.456Z,1379369956.456 [NavChart] Loaded
2013-09-16T22:19:16.456Z,1379369956.456 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-09-16T22:19:16.462Z,1379369956.462 [PitchRateCalculator] Loaded
2013-09-16T22:19:16.462Z,1379369956.462 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-09-16T22:19:16.477Z,1379369956.477 [SpeedCalculator] Loaded
2013-09-16T22:19:16.477Z,1379369956.477 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-09-16T22:19:16.493Z,1379369956.493 [TempGradientCalculator] Loaded
2013-09-16T22:19:16.493Z,1379369956.493 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-09-16T22:19:16.499Z,1379369956.499 [YawRateCalculator] Loaded
2013-09-16T22:19:16.499Z,1379369956.499 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-09-16T22:19:16.550Z,1379369956.550 [Navigation] Loaded
2013-09-16T22:19:16.550Z,1379369956.550 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-09-16T22:19:16.551Z,1379369956.551 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-09-16T22:19:16.552Z,1379369956.552 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-09-16T22:19:16.854Z,1379369956.854 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-09-16T22:19:16.854Z,1379369956.854 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-09-16T22:19:16.897Z,1379369956.897 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-09-16T22:19:16.897Z,1379369956.897 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-09-16T22:19:16.968Z,1379369956.968 [VerticalControl](DEBUG): Construct VerticalControl.
2013-09-16T22:19:17.069Z,1379369957.069 [VerticalControl] Loaded
2013-09-16T22:19:17.069Z,1379369957.069 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-09-16T22:19:17.074Z,1379369957.074 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-09-16T22:19:17.135Z,1379369957.135 [HorizontalControl] Loaded
2013-09-16T22:19:17.135Z,1379369957.135 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-09-16T22:19:17.136Z,1379369957.136 [SpeedControl](DEBUG): Construct SpeedControl.
2013-09-16T22:19:17.138Z,1379369957.138 [SpeedControl] Loaded
2013-09-16T22:19:17.138Z,1379369957.138 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-09-16T22:19:17.139Z,1379369957.139 [LoopControl](DEBUG): Construct LoopControl.
2013-09-16T22:19:17.139Z,1379369957.139 [LoopControl] Loaded
2013-09-16T22:19:17.140Z,1379369957.140 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-09-16T22:19:17.140Z,1379369957.140 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-09-16T22:19:17.141Z,1379369957.141 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-09-16T22:19:17.149Z,1379369957.149 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-09-16T22:19:17.154Z,1379369957.154 [AsyncPiEstimator] Loaded
2013-09-16T22:19:17.154Z,1379369957.154 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-09-16T22:19:17.158Z,1379369957.158 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-09-16T22:19:17.159Z,1379369957.159 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-09-16T22:19:17.160Z,1379369957.160 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-09-16T22:19:17.421Z,1379369957.421 [AHRS_sp3003D] Loaded
2013-09-16T22:19:17.421Z,1379369957.421 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-09-16T22:19:17.439Z,1379369957.439 [Depth_Keller] Loaded
2013-09-16T22:19:17.439Z,1379369957.439 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-09-16T22:19:17.636Z,1379369957.636 [DVL_micro] Loaded
2013-09-16T22:19:17.637Z,1379369957.637 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-09-16T22:19:17.639Z,1379369957.639 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406CE4E0
2013-09-16T22:19:17.735Z,1379369957.735 [NAL9602] Loaded
2013-09-16T22:19:17.735Z,1379369957.735 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-09-16T22:19:17.782Z,1379369957.782 [Onboard] Loaded
2013-09-16T22:19:17.782Z,1379369957.782 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-09-16T22:19:17.789Z,1379369957.789 [Radio_Freewave] Loaded
2013-09-16T22:19:17.789Z,1379369957.789 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-09-16T22:19:17.946Z,1379369957.946 [DAT] Loaded
2013-09-16T22:19:17.946Z,1379369957.946 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-09-16T22:19:17.956Z,1379369957.956 [SCPI] Loaded
2013-09-16T22:19:17.957Z,1379369957.957 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2013-09-16T22:19:17.957Z,1379369957.957 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-09-16T22:19:17.958Z,1379369957.958 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-09-16T22:19:18.091Z,1379369958.091 [CTD_NeilBrown] Loaded
2013-09-16T22:19:18.091Z,1379369958.091 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-09-16T22:19:18.096Z,1379369958.096 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4072B4E0
2013-09-16T22:19:18.111Z,1379369958.111 [PAR_Licor] Loaded
2013-09-16T22:19:18.111Z,1379369958.111 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2013-09-16T22:19:18.148Z,1379369958.148 [WetLabsBB2FL] Loaded
2013-09-16T22:19:18.148Z,1379369958.148 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-09-16T22:19:18.152Z,1379369958.152 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2013-09-16T22:19:18.152Z,1379369958.152 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-09-16T22:19:18.155Z,1379369958.155 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-09-16T22:19:18.156Z,1379369958.156 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-09-16T22:19:18.168Z,1379369958.168 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-09-16T22:19:18.172Z,1379369958.172 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2013-09-16T22:19:18.176Z,1379369958.176 [Supervisor](DEBUG): Running supervisor.
2013-09-16T22:19:18.177Z,1379369958.177 [CommandLine](INFO): Thread ID is 760
2013-09-16T22:19:18.180Z,1379369958.180 [controlThread](INFO): Thread ID is 759
2013-09-16T22:19:18.181Z,1379369958.181 [controlThread](DEBUG): Initializing ControlThread
2013-09-16T22:19:18.181Z,1379369958.181 [CycleStarter](INFO): Thread ID is 758
2013-09-16T22:19:18.181Z,1379369958.181 [InternalSim](DEBUG):  InternalSim initializing...
2013-09-16T22:19:18.266Z,1379369958.266 [logger](INFO): Thread ID is 761
2013-09-16T22:19:18.313Z,1379369958.313 [AsyncPiEstimator](INFO): Thread ID is 822
2013-09-16T22:19:18.313Z,1379369958.313 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-09-16T22:19:18.327Z,1379369958.327 [DVL_micro](INFO): Thread ID is 823
2013-09-16T22:19:18.345Z,1379369958.345 [DVL_micro](INFO): Initializing
2013-09-16T22:19:18.346Z,1379369958.346 [DVL_micro](INFO): start:Powering up
2013-09-16T22:19:18.347Z,1379369958.347 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:19:18.347Z,1379369958.347 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:19:18.348Z,1379369958.348 [SBIT](INFO): Initialize SBIT Component.
2013-09-16T22:19:18.349Z,1379369958.349 [SBIT](IMPORTANT): Tethys CM Info: 
$Rev:10634
2013-09-16T22:19:18.349Z,1379369958.349 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-09-16T22:19:18.349Z,1379369958.349 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-09-16T22:19:18.350Z,1379369958.350 [IBIT](INFO): Initialize IBIT Component.
2013-09-16T22:19:18.351Z,1379369958.351 [CBIT](DEBUG): Initialize CBIT Component.
2013-09-16T22:19:18.351Z,1379369958.351 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-09-16T22:19:18.353Z,1379369958.353 [CTD_NeilBrown](INFO): Thread ID is 824
2013-09-16T22:19:18.353Z,1379369958.353 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-09-16T22:19:18.356Z,1379369958.356 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-09-16T22:19:18.367Z,1379369958.367 [WetLabsBB2FL](INFO): Thread ID is 825
2013-09-16T22:19:18.367Z,1379369958.367 [WetLabsBB2FL](INFO): Powering down
2013-09-16T22:19:18.385Z,1379369958.385 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-09-16T22:19:18.386Z,1379369958.386 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-09-16T22:19:18.386Z,1379369958.386 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-09-16T22:19:18.387Z,1379369958.387 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-09-16T22:19:18.387Z,1379369958.387 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-09-16T22:19:18.388Z,1379369958.388 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-09-16T22:19:18.388Z,1379369958.388 [Navigation](DEBUG): Initializing Navigation.
2013-09-16T22:19:18.389Z,1379369958.389 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-09-16T22:19:18.390Z,1379369958.390 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-09-16T22:19:18.391Z,1379369958.391 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-09-16T22:19:18.392Z,1379369958.392 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-09-16T22:19:18.403Z,1379369958.403 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-09-16T22:19:18.420Z,1379369958.420 [NavChartDb](INFO): Thread ID is 826
2013-09-16T22:19:18.442Z,1379369958.442 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-09-16T22:19:18.442Z,1379369958.442 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-09-16T22:19:18.443Z,1379369958.443 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-09-16T22:19:18.443Z,1379369958.443 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-09-16T22:19:18.443Z,1379369958.443 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-09-16T22:19:18.443Z,1379369958.443 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-09-16T22:19:18.444Z,1379369958.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-09-16T22:19:18.444Z,1379369958.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-09-16T22:19:18.444Z,1379369958.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-09-16T22:19:18.459Z,1379369958.459 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T22:19:18.484Z,1379369958.484 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2013-09-16T22:19:18.497Z,1379369958.497 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-09-16T22:19:18.621Z,1379369958.621 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-09-16T22:19:18.623Z,1379369958.623 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-09-16T22:19:18.626Z,1379369958.626 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T22:19:18.647Z,1379369958.647 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-09-16T22:19:18.663Z,1379369958.663 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T22:19:18.694Z,1379369958.694 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-09-16T22:19:18.719Z,1379369958.719 [Default:D.SetSpeed](DEBUG): Construct.
2013-09-16T22:19:18.726Z,1379369958.726 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-09-16T22:19:18.731Z,1379369958.731 [Default:F.Wait](DEBUG): Construct Wait.
2013-09-16T22:19:18.734Z,1379369958.734 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS" >

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2013-09-16T22:19:18.752Z,1379369958.752 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,SCPI,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-09-16T22:19:18.832Z,1379369958.832 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T22:19:18.871Z,1379369958.871 [Depth_Keller](ERROR): Pressure reading out of range: 1831.078247 decibar
2013-09-16T22:19:18.945Z,1379369958.945 [Radio_Freewave](INFO): Powering up
2013-09-16T22:19:18.959Z,1379369958.959 [DAT](INFO): Powering up
2013-09-16T22:19:18.959Z,1379369958.959 [DAT](DEBUG): Initializing DAT.
2013-09-16T22:19:19.302Z,1379369959.302 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:19.310Z,1379369959.310 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T22:19:19.324Z,1379369959.324 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:19.334Z,1379369959.334 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-09-16T22:19:19.352Z,1379369959.352 [MassServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:19.358Z,1379369959.358 [MassServo](DEBUG): Initializing MassServo.
2013-09-16T22:19:19.364Z,1379369959.364 [RudderServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:19.390Z,1379369959.390 [RudderServo](DEBUG): Initializing RudderServo.
2013-09-16T22:19:19.407Z,1379369959.407 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:19.410Z,1379369959.410 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:19:19.444Z,1379369959.444 [CBIT](FAULT): Main Battery Failure. Count: 1
2013-09-16T22:19:19.890Z,1379369959.890 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T22:19:19.891Z,1379369959.891 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T22:19:19.891Z,1379369959.891 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2013-09-16T22:19:19.891Z,1379369959.891 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T22:19:20.191Z,1379369960.191 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-09-16T22:19:20.191Z,1379369960.191 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-09-16T22:19:20.191Z,1379369960.191 [BuoyancyServo] Communications Fault, FailCount= 1
2013-09-16T22:19:20.191Z,1379369960.191 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T22:19:20.516Z,1379369960.516 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:19:20.516Z,1379369960.516 [DVL_micro](INFO): Querying output modes
2013-09-16T22:19:20.516Z,1379369960.516 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:19:20.696Z,1379369960.696 [ElevatorServo](ERROR): Elevator initialization uart error I:serial timeout
2013-09-16T22:19:20.696Z,1379369960.696 [ElevatorServo](FAULT): Elevator failed to initialize
2013-09-16T22:19:20.696Z,1379369960.696 [ElevatorServo] Communications Fault, FailCount= 1
2013-09-16T22:19:20.696Z,1379369960.696 [ElevatorServo](ERROR): Communications Fault
2013-09-16T22:19:21.204Z,1379369961.204 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2013-09-16T22:19:21.205Z,1379369961.205 [RudderServo](FAULT): Rudder failed to initialize
2013-09-16T22:19:21.205Z,1379369961.205 [RudderServo] Communications Fault, FailCount= 1
2013-09-16T22:19:21.205Z,1379369961.205 [RudderServo](ERROR): Communications Fault
2013-09-16T22:19:21.725Z,1379369961.725 [ThrusterServo](ERROR): Thruster halt for initialization uart error serial timeout
2013-09-16T22:19:21.751Z,1379369961.751 [ThrusterServo](FAULT): Thruster failed to initialize
2013-09-16T22:19:21.751Z,1379369961.751 [ThrusterServo] Communications Fault, FailCount= 1
2013-09-16T22:19:21.752Z,1379369961.752 [ThrusterServo](ERROR): Communications Fault
2013-09-16T22:19:21.768Z,1379369961.768 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T22:19:21.785Z,1379369961.785 [CBIT](ERROR): Communications Fault in component: ElevatorServo
2013-09-16T22:19:21.786Z,1379369961.786 [CBIT](ERROR): Communications Fault in component: RudderServo
2013-09-16T22:19:21.786Z,1379369961.786 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2013-09-16T22:19:21.786Z,1379369961.786 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T22:19:21.912Z,1379369961.912 [AHRS_sp3003D](INFO): Powering down
2013-09-16T22:19:22.067Z,1379369962.067 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T22:19:22.068Z,1379369962.068 [BuoyancyServo](INFO): Powering down
2013-09-16T22:19:22.154Z,1379369962.154 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-09-16T22:19:22.155Z,1379369962.155 [ElevatorServo](INFO): Powering down
2013-09-16T22:19:22.218Z,1379369962.218 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-09-16T22:19:22.218Z,1379369962.218 [RudderServo](INFO): Powering down
2013-09-16T22:19:22.262Z,1379369962.262 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T22:19:22.262Z,1379369962.262 [ThrusterServo](INFO): Powering down
2013-09-16T22:19:22.526Z,1379369962.526 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:22.527Z,1379369962.527 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:19:22.527Z,1379369962.527 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:19:22.711Z,1379369962.711 [MassServo](FAULT): Mass initialization uart error:serial timeout
2013-09-16T22:19:22.711Z,1379369962.711 [MassServo] Communications Fault, FailCount= 1
2013-09-16T22:19:22.711Z,1379369962.711 [MassServo](ERROR): Communications Fault
2013-09-16T22:19:22.714Z,1379369962.714 [CBIT](ERROR): Communications Fault in component: MassServo
2013-09-16T22:19:22.756Z,1379369962.756 [NAL9602](INFO): Powering up NAL9602
2013-09-16T22:19:22.840Z,1379369962.840 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:22.986Z,1379369962.986 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-09-16T22:19:22.987Z,1379369962.987 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-09-16T22:19:22.987Z,1379369962.987 [MassServo](INFO): Powering down
2013-09-16T22:19:23.029Z,1379369963.029 [RudderServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:23.160Z,1379369963.160 [RudderServo](DEBUG): Initializing RudderServo.
2013-09-16T22:19:23.278Z,1379369963.278 [CBIT](INFO): Clearing failed state for component ElevatorServo
2013-09-16T22:19:23.278Z,1379369963.278 [ElevatorServo] No Fault, FailCount= 1
2013-09-16T22:19:23.278Z,1379369963.278 [CBIT](INFO): Clearing failed state for component RudderServo
2013-09-16T22:19:23.278Z,1379369963.278 [RudderServo] No Fault, FailCount= 1
2013-09-16T22:19:23.279Z,1379369963.279 [CBIT](INFO): Clearing failed state for component ThrusterServo
2013-09-16T22:19:23.279Z,1379369963.279 [ThrusterServo] No Fault, FailCount= 1
2013-09-16T22:19:23.423Z,1379369963.423 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:23.428Z,1379369963.428 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:19:23.431Z,1379369963.431 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T22:19:23.431Z,1379369963.431 [AHRS_sp3003D] No Fault, FailCount= 1
2013-09-16T22:19:23.696Z,1379369963.696 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T22:19:24.265Z,1379369964.265 [ElevatorServo](ERROR): Elevator initialization uart error I:serial timeout
2013-09-16T22:19:24.265Z,1379369964.265 [ElevatorServo](FAULT): Elevator failed to initialize
2013-09-16T22:19:24.266Z,1379369964.266 [ElevatorServo] Communications Fault, FailCount= 2
2013-09-16T22:19:24.266Z,1379369964.266 [ElevatorServo](ERROR): Communications Fault
2013-09-16T22:19:24.538Z,1379369964.538 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:24.543Z,1379369964.543 [DVL_micro](INFO): pause:Powering down
2013-09-16T22:19:24.890Z,1379369964.890 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2013-09-16T22:19:24.890Z,1379369964.890 [RudderServo](FAULT): Rudder failed to initialize
2013-09-16T22:19:24.890Z,1379369964.890 [RudderServo] Communications Fault, FailCount= 2
2013-09-16T22:19:24.890Z,1379369964.890 [RudderServo](ERROR): Communications Fault
2013-09-16T22:19:25.407Z,1379369965.407 [ThrusterServo](ERROR): Thruster halt for initialization uart error serial timeout
2013-09-16T22:19:25.436Z,1379369965.436 [ThrusterServo](FAULT): Thruster failed to initialize
2013-09-16T22:19:25.437Z,1379369965.437 [ThrusterServo] Communications Fault, FailCount= 2
2013-09-16T22:19:25.437Z,1379369965.437 [ThrusterServo](ERROR): Communications Fault
2013-09-16T22:19:25.461Z,1379369965.461 [CBIT](ERROR): Communications Fault in component: ElevatorServo
2013-09-16T22:19:25.461Z,1379369965.461 [CBIT](INFO): Clearing failed state for component MassServo
2013-09-16T22:19:25.461Z,1379369965.461 [MassServo] No Fault, FailCount= 1
2013-09-16T22:19:25.462Z,1379369965.462 [CBIT](ERROR): Communications Fault in component: RudderServo
2013-09-16T22:19:25.462Z,1379369965.462 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2013-09-16T22:19:25.932Z,1379369965.932 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T22:19:25.932Z,1379369965.932 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T22:19:25.932Z,1379369965.932 [AHRS_sp3003D] Hardware Fault, FailCount= 2
2013-09-16T22:19:25.932Z,1379369965.932 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T22:19:26.047Z,1379369966.047 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-09-16T22:19:26.047Z,1379369966.047 [ElevatorServo](INFO): Powering down
2013-09-16T22:19:26.048Z,1379369966.048 [MassServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:26.056Z,1379369966.056 [MassServo](DEBUG): Initializing MassServo.
2013-09-16T22:19:26.057Z,1379369966.057 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-09-16T22:19:26.057Z,1379369966.057 [RudderServo](INFO): Powering down
2013-09-16T22:19:26.058Z,1379369966.058 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T22:19:26.058Z,1379369966.058 [ThrusterServo](INFO): Powering down
2013-09-16T22:19:26.061Z,1379369966.061 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T22:19:26.062Z,1379369966.062 [BuoyancyServo] No Fault, FailCount= 1
2013-09-16T22:19:26.062Z,1379369966.062 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T22:19:26.104Z,1379369966.104 [AHRS_sp3003D](INFO): Powering down
2013-09-16T22:19:26.149Z,1379369966.149 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:19:26.149Z,1379369966.149 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:19:26.149Z,1379369966.149 [DVL_micro](INFO): resume:Powering up
2013-09-16T22:19:26.150Z,1379369966.150 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:19:26.256Z,1379369966.256 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:28.156Z,1379369968.156 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:19:28.156Z,1379369968.156 [DVL_micro](INFO): Querying output modes
2013-09-16T22:19:28.156Z,1379369968.156 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:19:30.162Z,1379369970.162 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:30.162Z,1379369970.162 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:19:30.163Z,1379369970.163 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:19:32.165Z,1379369972.165 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:32.167Z,1379369972.167 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:19:32.167Z,1379369972.167 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:19:34.173Z,1379369974.173 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:19:34.173Z,1379369974.173 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:19:36.176Z,1379369976.176 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:36.176Z,1379369976.176 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:19:36.176Z,1379369976.176 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:19:38.187Z,1379369978.187 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:38.187Z,1379369978.187 [DVL_micro](INFO): Querying output modes
2013-09-16T22:19:38.187Z,1379369978.187 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:19:40.198Z,1379369980.198 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:40.198Z,1379369980.198 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:19:40.198Z,1379369980.198 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:19:42.205Z,1379369982.205 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:44.217Z,1379369984.217 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:19:44.217Z,1379369984.217 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:19:46.220Z,1379369986.220 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:19:46.220Z,1379369986.220 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:19:48.223Z,1379369988.223 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:48.223Z,1379369988.223 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:19:48.223Z,1379369988.223 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:19:50.261Z,1379369990.261 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:50.262Z,1379369990.262 [DVL_micro](INFO): Querying output modes
2013-09-16T22:19:50.262Z,1379369990.262 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:19:52.273Z,1379369992.273 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:52.273Z,1379369992.273 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:19:52.273Z,1379369992.273 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:19:54.276Z,1379369994.276 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:19:56.283Z,1379369996.283 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:19:56.284Z,1379369996.284 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:19:56.427Z,1379369996.427 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T22:19:56.663Z,1379369996.663 [DAT](INFO): Init failed - response: sec

2013-09-16T22:19:56.664Z,1379369996.664 [DAT](FAULT): DAT failed to initialize
2013-09-16T22:19:56.664Z,1379369996.664 [DAT] Communications Fault, FailCount= 1
2013-09-16T22:19:56.664Z,1379369996.664 [DAT](ERROR): Communications Fault
2013-09-16T22:19:56.687Z,1379369996.687 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:56.809Z,1379369996.809 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-09-16T22:19:56.810Z,1379369996.810 [RudderServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:56.929Z,1379369996.929 [RudderServo](DEBUG): Initializing RudderServo.
2013-09-16T22:19:57.049Z,1379369997.049 [SBIT](IMPORTANT): Beginning Startup BIT
2013-09-16T22:19:57.052Z,1379369997.052 [CBIT](INFO): Clearing failed state for component ElevatorServo
2013-09-16T22:19:57.052Z,1379369997.052 [ElevatorServo] No Fault, FailCount= 2
2013-09-16T22:19:57.053Z,1379369997.053 [CBIT](INFO): Clearing failed state for component RudderServo
2013-09-16T22:19:57.053Z,1379369997.053 [RudderServo] No Fault, FailCount= 2
2013-09-16T22:19:57.053Z,1379369997.053 [CBIT](INFO): Clearing failed state for component ThrusterServo
2013-09-16T22:19:57.053Z,1379369997.053 [ThrusterServo] No Fault, FailCount= 2
2013-09-16T22:19:57.053Z,1379369997.053 [CBIT](ERROR): Communications Fault in component: DAT
2013-09-16T22:19:57.054Z,1379369997.054 [CBIT](IMPORTANT): Beginning GF scan
2013-09-16T22:19:57.105Z,1379369997.105 [NAL9602](INFO): NAL9602 initialized
2013-09-16T22:19:57.151Z,1379369997.151 [DAT](INFO): Powering down
2013-09-16T22:19:57.845Z,1379369997.845 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-09-16T22:19:57.845Z,1379369997.845 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-09-16T22:19:57.845Z,1379369997.845 [BuoyancyServo] Communications Fault, FailCount= 2
2013-09-16T22:19:57.845Z,1379369997.845 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T22:19:57.941Z,1379369997.941 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:19:57.943Z,1379369997.943 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:19:57.946Z,1379369997.946 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T22:19:57.946Z,1379369997.946 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T22:19:57.946Z,1379369997.946 [AHRS_sp3003D] No Fault, FailCount= 2
2013-09-16T22:19:57.970Z,1379369997.970 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T22:19:58.041Z,1379369998.041 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T22:19:58.041Z,1379369998.041 [BuoyancyServo](INFO): Powering down
2013-09-16T22:19:58.286Z,1379369998.286 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:19:58.287Z,1379369998.287 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:19:58.318Z,1379369998.318 [MassServo](FAULT): Mass initialization uart error:serial timeout
2013-09-16T22:19:58.318Z,1379369998.318 [MassServo] Communications Fault, FailCount= 2
2013-09-16T22:19:58.318Z,1379369998.318 [MassServo](ERROR): Communications Fault
2013-09-16T22:19:58.322Z,1379369998.322 [CBIT](ERROR): Communications Fault in component: MassServo
2013-09-16T22:19:58.425Z,1379369998.425 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-09-16T22:19:58.425Z,1379369998.425 [MassServo](INFO): Powering down
2013-09-16T22:19:58.433Z,1379369998.433 [CBIT](INFO): Clearing failed state for component DAT
2013-09-16T22:19:58.433Z,1379369998.433 [DAT] No Fault, FailCount= 1
2013-09-16T22:19:59.107Z,1379369999.107 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T22:19:59.107Z,1379369999.107 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T22:19:59.107Z,1379369999.107 [AHRS_sp3003D] Hardware Fault, FailCount= 3
2013-09-16T22:19:59.107Z,1379369999.107 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T22:19:59.676Z,1379369999.676 [ThrusterServo](ERROR): Thruster halt for initialization uart error serial timeout
2013-09-16T22:19:59.693Z,1379369999.693 [ThrusterServo](FAULT): Thruster failed to initialize
2013-09-16T22:19:59.694Z,1379369999.694 [ThrusterServo] Communications Fault, FailCount= 3
2013-09-16T22:19:59.694Z,1379369999.694 [ThrusterServo](ERROR): Communications Fault
2013-09-16T22:19:59.734Z,1379369999.734 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2013-09-16T22:19:59.735Z,1379369999.735 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T22:19:59.762Z,1379369999.762 [AHRS_sp3003D](INFO): Powering down
2013-09-16T22:19:59.886Z,1379369999.886 [BuoyancyServo](FAULT): LCB fault: LCB Watchdog Reset. Invalid Command. Hardware Overcurrent Shutdown. Software Overcurrent. Current Limiter Activated.
2013-09-16T22:19:59.886Z,1379369999.886 [BuoyancyServo] Hardware Fault, FailCount= 2
2013-09-16T22:19:59.886Z,1379369999.886 [BuoyancyServo](ERROR): Hardware Fault
2013-09-16T22:20:00.297Z,1379370000.297 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:00.297Z,1379370000.297 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:20:00.297Z,1379370000.297 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:20:00.393Z,1379370000.393 [ElevatorServo](FAULT): Elevator initialization uart error:serial timeout
2013-09-16T22:20:00.393Z,1379370000.393 [ElevatorServo] Communications Fault, FailCount= 3
2013-09-16T22:20:00.393Z,1379370000.393 [ElevatorServo](ERROR): Communications Fault
2013-09-16T22:20:00.394Z,1379370000.394 [MassServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:00.510Z,1379370000.510 [MassServo](DEBUG): Initializing MassServo.
2013-09-16T22:20:01.018Z,1379370001.018 [RudderServo](FAULT): Rudder initialization uart error:serial timeout
2013-09-16T22:20:01.018Z,1379370001.018 [RudderServo] Communications Fault, FailCount= 3
2013-09-16T22:20:01.018Z,1379370001.018 [RudderServo](ERROR): Communications Fault
2013-09-16T22:20:01.019Z,1379370001.019 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T22:20:01.019Z,1379370001.019 [ThrusterServo](INFO): Powering down
2013-09-16T22:20:01.023Z,1379370001.023 [CBIT](ERROR): Communications Fault in component: ElevatorServo
2013-09-16T22:20:01.023Z,1379370001.023 [CBIT](CRITICAL): Communications Fault in component: ElevatorServo
2013-09-16T22:20:01.023Z,1379370001.023 [CBIT](INFO): Clearing failed state for component MassServo
2013-09-16T22:20:01.023Z,1379370001.023 [MassServo] No Fault, FailCount= 2
2013-09-16T22:20:01.024Z,1379370001.024 [CBIT](ERROR): Communications Fault in component: RudderServo
2013-09-16T22:20:01.024Z,1379370001.024 [CBIT](CRITICAL): Communications Fault in component: RudderServo
2013-09-16T22:20:01.060Z,1379370001.060 [DAT](INFO): Powering up
2013-09-16T22:20:01.060Z,1379370001.060 [DAT](DEBUG): Initializing DAT.
2013-09-16T22:20:01.088Z,1379370001.088 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-09-16T22:20:01.088Z,1379370001.088 [ElevatorServo](INFO): Powering down
2013-09-16T22:20:01.095Z,1379370001.095 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-09-16T22:20:01.095Z,1379370001.095 [RudderServo](INFO): Powering down
2013-09-16T22:20:01.132Z,1379370001.132 [CommandLine](FAULT): Scheduling is paused
2013-09-16T22:20:01.133Z,1379370001.133 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T22:20:01.133Z,1379370001.133 [BuoyancyServo] No Fault, FailCount= 2
2013-09-16T22:20:01.486Z,1379370001.486 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:02.300Z,1379370002.300 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:02.300Z,1379370002.300 [DVL_micro](INFO): Querying output modes
2013-09-16T22:20:02.301Z,1379370002.301 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:20:04.311Z,1379370004.311 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:04.311Z,1379370004.311 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:20:04.312Z,1379370004.312 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:20:06.322Z,1379370006.322 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:08.330Z,1379370008.330 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:20:08.330Z,1379370008.330 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:20:10.333Z,1379370010.333 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:20:10.333Z,1379370010.333 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:20:12.340Z,1379370012.340 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:12.340Z,1379370012.340 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:20:12.340Z,1379370012.340 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:20:14.347Z,1379370014.347 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:14.347Z,1379370014.347 [DVL_micro](INFO): Querying output modes
2013-09-16T22:20:14.347Z,1379370014.347 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:20:16.358Z,1379370016.358 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:16.358Z,1379370016.358 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:20:16.358Z,1379370016.358 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:20:18.369Z,1379370018.369 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:20.377Z,1379370020.377 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:20:20.377Z,1379370020.377 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:20:22.380Z,1379370022.380 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:20:22.380Z,1379370022.380 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:20:24.386Z,1379370024.386 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:24.386Z,1379370024.386 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:20:24.387Z,1379370024.387 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:20:26.393Z,1379370026.393 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:26.394Z,1379370026.394 [DVL_micro](INFO): Querying output modes
2013-09-16T22:20:26.394Z,1379370026.394 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:20:28.405Z,1379370028.405 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:28.405Z,1379370028.405 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:20:28.405Z,1379370028.405 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:20:30.406Z,1379370030.406 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:31.653Z,1379370031.653 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T22:20:32.162Z,1379370032.162 [MassServo](FAULT): Mass shifter EEPROM initialization uart error serial timeout
2013-09-16T22:20:32.162Z,1379370032.162 [MassServo] Communications Fault, FailCount= 3
2013-09-16T22:20:32.163Z,1379370032.163 [MassServo](ERROR): Communications Fault
2013-09-16T22:20:32.284Z,1379370032.284 [SBIT](FAULT): Mass: EXPECTED:0.005600 ACTUAL:0.003060
2013-09-16T22:20:32.287Z,1379370032.287 [CBIT](CRITICAL): Environmental Failure. Press:14.451184 PSI. Humidity:40%. Temp:22 C. ABORTING MISSION
2013-09-16T22:20:32.288Z,1379370032.288 [CBIT](ERROR): Communications Fault in component: MassServo
2013-09-16T22:20:32.288Z,1379370032.288 [CBIT](INFO): Clearing failed state for component ThrusterServo
2013-09-16T22:20:32.288Z,1379370032.288 [ThrusterServo] No Fault, FailCount= 3
2013-09-16T22:20:32.288Z,1379370032.288 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T22:20:32.288Z,1379370032.288 [AHRS_sp3003D] No Fault, FailCount= 3
2013-09-16T22:20:32.410Z,1379370032.410 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T22:20:32.413Z,1379370032.413 [DVL_micro](INFO): pause:Powering down
2013-09-16T22:20:32.747Z,1379370032.747 [DAT](INFO): Init failed - response: 
2013-09-16T22:20:32.747Z,1379370032.747 [DAT](FAULT): DAT failed to initialize
2013-09-16T22:20:32.748Z,1379370032.748 [DAT] Communications Fault, FailCount= 2
2013-09-16T22:20:32.748Z,1379370032.748 [DAT](ERROR): Communications Fault
2013-09-16T22:20:32.860Z,1379370032.860 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial buffer full
2013-09-16T22:20:32.861Z,1379370032.861 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-09-16T22:20:32.861Z,1379370032.861 [BuoyancyServo] Communications Fault, FailCount= 3
2013-09-16T22:20:32.862Z,1379370032.862 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T22:20:33.391Z,1379370033.391 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:33.526Z,1379370033.526 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-09-16T22:20:33.527Z,1379370033.527 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-09-16T22:20:33.527Z,1379370033.527 [MassServo](INFO): Powering down
2013-09-16T22:20:33.529Z,1379370033.529 [RudderServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:33.654Z,1379370033.654 [RudderServo](DEBUG): Initializing RudderServo.
2013-09-16T22:20:33.655Z,1379370033.655 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:33.656Z,1379370033.656 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:20:33.659Z,1379370033.659 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T22:20:33.660Z,1379370033.660 [CBIT](ERROR): Communications Fault in component: DAT
2013-09-16T22:20:34.033Z,1379370034.033 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T22:20:34.033Z,1379370034.033 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T22:20:34.034Z,1379370034.034 [AHRS_sp3003D] Hardware Fault, FailCount= 4
2013-09-16T22:20:34.034Z,1379370034.034 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T22:20:34.069Z,1379370034.069 [DAT](INFO): Powering down
2013-09-16T22:20:34.217Z,1379370034.217 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T22:20:34.219Z,1379370034.219 [BuoyancyServo](INFO): Powering down
2013-09-16T22:20:34.431Z,1379370034.431 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:20:34.431Z,1379370034.431 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:20:34.431Z,1379370034.431 [DVL_micro](INFO): resume:Powering up
2013-09-16T22:20:34.432Z,1379370034.432 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:20:35.135Z,1379370035.135 [ThrusterServo](ERROR): Thruster halt for initialization uart error serial timeout
2013-09-16T22:20:35.153Z,1379370035.153 [ThrusterServo](FAULT): Thruster failed to initialize
2013-09-16T22:20:35.153Z,1379370035.153 [ThrusterServo] Communications Fault, FailCount= 4
2013-09-16T22:20:35.154Z,1379370035.154 [ThrusterServo](ERROR): Communications Fault
2013-09-16T22:20:35.171Z,1379370035.171 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2013-09-16T22:20:35.173Z,1379370035.173 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T22:20:35.238Z,1379370035.238 [AHRS_sp3003D](INFO): Powering down
2013-09-16T22:20:35.369Z,1379370035.369 [MassServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:35.484Z,1379370035.484 [MassServo](DEBUG): Initializing MassServo.
2013-09-16T22:20:35.485Z,1379370035.485 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T22:20:35.486Z,1379370035.486 [ThrusterServo](INFO): Powering down
2013-09-16T22:20:35.489Z,1379370035.489 [CBIT](INFO): Clearing failed state for component MassServo
2013-09-16T22:20:35.489Z,1379370035.489 [MassServo] No Fault, FailCount= 3
2013-09-16T22:20:35.634Z,1379370035.634 [CBIT](INFO): Clearing failed state for component DAT
2013-09-16T22:20:35.634Z,1379370035.634 [DAT] No Fault, FailCount= 2
2013-09-16T22:20:36.160Z,1379370036.160 [CBIT](INFO): Clearing failed state for component ThrusterServo
2013-09-16T22:20:36.160Z,1379370036.160 [ThrusterServo] No Fault, FailCount= 4
2013-09-16T22:20:36.433Z,1379370036.433 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:36.434Z,1379370036.434 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:20:36.438Z,1379370036.438 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:20:36.438Z,1379370036.438 [DVL_micro](INFO): Querying output modes
2013-09-16T22:20:36.438Z,1379370036.438 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:20:36.439Z,1379370036.439 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2013-09-16T22:20:36.439Z,1379370036.439 [AHRS_sp3003D] No Fault, FailCount= 4
2013-09-16T22:20:36.793Z,1379370036.793 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-09-16T22:20:36.835Z,1379370036.835 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T22:20:36.836Z,1379370036.836 [BuoyancyServo] No Fault, FailCount= 3
2013-09-16T22:20:37.216Z,1379370037.216 [DAT](INFO): Powering up
2013-09-16T22:20:37.216Z,1379370037.216 [DAT](DEBUG): Initializing DAT.
2013-09-16T22:20:37.251Z,1379370037.251 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:20:38.444Z,1379370038.444 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:38.444Z,1379370038.444 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:20:38.445Z,1379370038.445 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:20:40.455Z,1379370040.455 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:20:40.458Z,1379370040.458 [DVL_micro](INFO): pause:Powering down
2013-09-16T22:21:07.418Z,1379370067.418 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T22:21:07.926Z,1379370067.926 [MassServo](FAULT): Mass shifter EEPROM initialization uart error serial timeout
2013-09-16T22:21:07.926Z,1379370067.926 [MassServo] Communications Fault, FailCount= 4
2013-09-16T22:21:07.926Z,1379370067.926 [MassServo](ERROR): Communications Fault
2013-09-16T22:21:08.028Z,1379370068.028 [SBIT](FAULT): Elevator: EXPECTED:-15.000000 ACTUAL:-11.404951
2013-09-16T22:21:08.028Z,1379370068.028 [SBIT](FAULT): Mass: EXPECTED:-0.006000 ACTUAL:0.002176
2013-09-16T22:21:08.029Z,1379370068.029 [SBIT](FAULT): Rudder: EXPECTED:-15.000000 ACTUAL:-11.404951
2013-09-16T22:21:08.029Z,1379370068.029 [SBIT](FAULT): Control surface position failure.
2013-09-16T22:21:08.031Z,1379370068.031 [CBIT](ERROR): Communications Fault in component: MassServo
2013-09-16T22:21:08.487Z,1379370068.487 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-09-16T22:21:08.487Z,1379370068.487 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-09-16T22:21:08.487Z,1379370068.487 [AHRS_sp3003D] Hardware Fault, FailCount= 5
2013-09-16T22:21:08.487Z,1379370068.487 [AHRS_sp3003D](ERROR): Hardware Fault
2013-09-16T22:21:08.511Z,1379370068.511 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:21:08.512Z,1379370068.512 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:21:08.512Z,1379370068.512 [DVL_micro](INFO): resume:Powering up
2013-09-16T22:21:08.512Z,1379370068.512 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:21:08.591Z,1379370068.591 [DAT](INFO): Init failed - response: sec

2013-09-16T22:21:08.591Z,1379370068.591 [DAT](FAULT): DAT failed to initialize
2013-09-16T22:21:08.591Z,1379370068.591 [DAT] Communications Fault, FailCount= 3
2013-09-16T22:21:08.591Z,1379370068.591 [DAT](ERROR): Communications Fault
2013-09-16T22:21:08.711Z,1379370068.711 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-09-16T22:21:08.711Z,1379370068.711 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-09-16T22:21:08.711Z,1379370068.711 [BuoyancyServo] Communications Fault, FailCount= 4
2013-09-16T22:21:08.711Z,1379370068.711 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T22:21:08.712Z,1379370068.712 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-09-16T22:21:08.712Z,1379370068.712 [MassServo](INFO): Powering down
2013-09-16T22:21:08.716Z,1379370068.716 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T22:21:08.717Z,1379370068.717 [CBIT](ERROR): Hardware Fault in component: AHRS_sp3003D
2013-09-16T22:21:08.717Z,1379370068.717 [CBIT](CRITICAL): Hardware Fault in component: AHRS_sp3003D
2013-09-16T22:21:08.717Z,1379370068.717 [CBIT](ERROR): Communications Fault in component: DAT
2013-09-16T22:21:08.718Z,1379370068.718 [CBIT](CRITICAL): Communications Fault in component: DAT
2013-09-16T22:21:08.733Z,1379370068.733 [AHRS_sp3003D](INFO): Powering down
2013-09-16T22:21:08.851Z,1379370068.851 [DAT](INFO): Powering down
2013-09-16T22:21:08.991Z,1379370068.991 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T22:21:08.992Z,1379370068.992 [BuoyancyServo](INFO): Powering down
2013-09-16T22:21:09.291Z,1379370069.291 [CBIT](INFO): Clearing failed state for component MassServo
2013-09-16T22:21:09.291Z,1379370069.291 [MassServo] No Fault, FailCount= 4
2013-09-16T22:21:09.554Z,1379370069.554 [MassServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:21:09.555Z,1379370069.555 [MassServo](DEBUG): Initializing MassServo.
2013-09-16T22:21:10.065Z,1379370070.065 [ThrusterServo](FAULT): Thruster initialization uart error:serial timeout
2013-09-16T22:21:10.065Z,1379370070.065 [ThrusterServo] Communications Fault, FailCount= 5
2013-09-16T22:21:10.065Z,1379370070.065 [ThrusterServo](ERROR): Communications Fault
2013-09-16T22:21:10.068Z,1379370070.068 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2013-09-16T22:21:10.069Z,1379370070.069 [CBIT](CRITICAL): Communications Fault in component: ThrusterServo
2013-09-16T22:21:10.153Z,1379370070.153 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T22:21:10.153Z,1379370070.153 [ThrusterServo](INFO): Powering down
2013-09-16T22:21:10.518Z,1379370070.518 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:21:10.519Z,1379370070.519 [DVL_micro](INFO): Querying output modes
2013-09-16T22:21:10.519Z,1379370070.519 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:21:11.057Z,1379370071.057 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-09-16T22:21:11.058Z,1379370071.058 [BuoyancyServo] No Fault, FailCount= 4
2013-09-16T22:21:11.341Z,1379370071.341 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:21:12.529Z,1379370072.529 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:12.529Z,1379370072.529 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:21:12.529Z,1379370072.529 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:21:14.540Z,1379370074.540 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:14.542Z,1379370074.542 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:21:14.542Z,1379370074.542 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:21:16.548Z,1379370076.548 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:21:16.548Z,1379370076.548 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:21:18.558Z,1379370078.558 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:18.558Z,1379370078.558 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:21:18.559Z,1379370078.559 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:21:20.561Z,1379370080.561 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:20.562Z,1379370080.562 [DVL_micro](INFO): Querying output modes
2013-09-16T22:21:20.562Z,1379370080.562 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:21:22.573Z,1379370082.573 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:22.573Z,1379370082.573 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:21:22.573Z,1379370082.573 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:21:24.584Z,1379370084.584 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:26.591Z,1379370086.591 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:21:26.591Z,1379370086.591 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:21:28.594Z,1379370088.594 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:21:28.595Z,1379370088.595 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:21:30.601Z,1379370090.601 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:30.601Z,1379370090.601 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:21:30.601Z,1379370090.601 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:21:32.608Z,1379370092.608 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:32.608Z,1379370092.608 [DVL_micro](INFO): Querying output modes
2013-09-16T22:21:32.608Z,1379370092.608 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:21:34.611Z,1379370094.611 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:34.611Z,1379370094.611 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:21:34.612Z,1379370094.612 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:21:36.622Z,1379370096.622 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:38.634Z,1379370098.634 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:21:38.634Z,1379370098.634 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:21:40.637Z,1379370100.637 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:21:40.637Z,1379370100.637 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:21:41.507Z,1379370101.507 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T22:21:42.015Z,1379370102.015 [MassServo](FAULT): Mass shifter EEPROM initialization uart error serial timeout
2013-09-16T22:21:42.015Z,1379370102.015 [MassServo] Communications Fault, FailCount= 5
2013-09-16T22:21:42.015Z,1379370102.015 [MassServo](ERROR): Communications Fault
2013-09-16T22:21:42.018Z,1379370102.018 [CBIT](ERROR): Communications Fault in component: MassServo
2013-09-16T22:21:42.018Z,1379370102.018 [CBIT](CRITICAL): Communications Fault in component: MassServo
2013-09-16T22:21:42.019Z,1379370102.019 [CBIT](INFO): Clearing failed count for component ThrusterServo
2013-09-16T22:21:42.019Z,1379370102.019 [ThrusterServo] No Fault, FailCount= 5
2013-09-16T22:21:42.247Z,1379370102.247 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-09-16T22:21:42.247Z,1379370102.247 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-09-16T22:21:42.247Z,1379370102.247 [BuoyancyServo] Communications Fault, FailCount= 5
2013-09-16T22:21:42.247Z,1379370102.247 [BuoyancyServo](ERROR): Communications Fault
2013-09-16T22:21:42.248Z,1379370102.248 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-09-16T22:21:42.248Z,1379370102.248 [MassServo](INFO): Powering down
2013-09-16T22:21:42.249Z,1379370102.249 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:21:42.250Z,1379370102.250 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:21:42.252Z,1379370102.252 [SBIT](CRITICAL): SBIT FAILED
2013-09-16T22:21:42.253Z,1379370102.253 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-09-16T22:21:42.254Z,1379370102.254 [CBIT](CRITICAL): Communications Fault in component: BuoyancyServo
2013-09-16T22:21:42.453Z,1379370102.453 [MissionManager](IMPORTANT): Started mission Startup
2013-09-16T22:21:42.453Z,1379370102.453 [Startup] Running Loop=1
2013-09-16T22:21:42.453Z,1379370102.453 [Startup](INFO): Aggregate::initialize Startup
2013-09-16T22:21:42.453Z,1379370102.453 [Startup:A.GoToSurface] Running Loop=1
2013-09-16T22:21:42.453Z,1379370102.453 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T22:21:42.460Z,1379370102.460 [Startup:StartupSatComms] Running Loop=1
2013-09-16T22:21:42.461Z,1379370102.461 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-09-16T22:21:42.461Z,1379370102.461 [Startup:StartupSatComms:A] Running Loop=1
2013-09-16T22:21:42.466Z,1379370102.466 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-09-16T22:21:42.466Z,1379370102.466 [BuoyancyServo](INFO): Powering down
2013-09-16T22:21:42.644Z,1379370102.644 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:42.644Z,1379370102.644 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:21:42.644Z,1379370102.644 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:21:42.857Z,1379370102.857 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-09-16T22:21:44.081Z,1379370104.081 [BuoyancyServo](FAULT): LCB fault: LCB Watchdog Reset. Invalid Command. Hardware Overcurrent Shutdown. Software Overcurrent. Current Limiter Activated.
2013-09-16T22:21:44.081Z,1379370104.081 [BuoyancyServo] Hardware Fault, FailCount= 5
2013-09-16T22:21:44.081Z,1379370104.081 [BuoyancyServo](ERROR): Hardware Fault
2013-09-16T22:21:44.651Z,1379370104.651 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:44.651Z,1379370104.651 [DVL_micro](INFO): Querying output modes
2013-09-16T22:21:44.651Z,1379370104.651 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:21:45.368Z,1379370105.368 [ThrusterServo](FAULT): Thruster initialization uart error:serial timeout
2013-09-16T22:21:45.368Z,1379370105.368 [ThrusterServo] Communications Fault, FailCount= 1
2013-09-16T22:21:45.368Z,1379370105.368 [ThrusterServo](ERROR): Communications Fault
2013-09-16T22:21:45.371Z,1379370105.371 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2013-09-16T22:21:45.446Z,1379370105.446 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T22:21:45.446Z,1379370105.446 [ThrusterServo](INFO): Powering down
2013-09-16T22:21:46.352Z,1379370106.352 [CBIT](INFO): Clearing failed state for component ThrusterServo
2013-09-16T22:21:46.352Z,1379370106.352 [ThrusterServo] No Fault, FailCount= 1
2013-09-16T22:21:46.633Z,1379370106.633 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:21:46.634Z,1379370106.634 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:21:46.658Z,1379370106.658 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:46.658Z,1379370106.658 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:21:46.658Z,1379370106.658 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:21:48.665Z,1379370108.665 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:50.332Z,1379370110.332 [ThrusterServo](ERROR): Thruster uart error: serial timeout
2013-09-16T22:21:50.332Z,1379370110.332 [ThrusterServo] Communications Fault, FailCount= 2
2013-09-16T22:21:50.332Z,1379370110.332 [ThrusterServo](ERROR): Communications Fault
2013-09-16T22:21:50.335Z,1379370110.335 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2013-09-16T22:21:50.395Z,1379370110.395 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-09-16T22:21:50.395Z,1379370110.395 [ThrusterServo](INFO): Powering down
2013-09-16T22:21:50.677Z,1379370110.677 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:21:50.677Z,1379370110.677 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:21:51.296Z,1379370111.296 [CBIT](INFO): Clearing failed state for component ThrusterServo
2013-09-16T22:21:51.296Z,1379370111.296 [ThrusterServo] No Fault, FailCount= 2
2013-09-16T22:21:51.575Z,1379370111.575 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:21:51.576Z,1379370111.576 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-09-16T22:21:52.680Z,1379370112.680 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:21:52.680Z,1379370112.680 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:21:52.791Z,1379370112.791 [CBIT](IMPORTANT): No ground fault detected
2013-09-16T22:21:54.690Z,1379370114.690 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:54.690Z,1379370114.690 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:21:54.691Z,1379370114.691 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:21:56.697Z,1379370116.697 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:56.698Z,1379370116.698 [DVL_micro](INFO): Querying output modes
2013-09-16T22:21:56.698Z,1379370116.698 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:21:58.701Z,1379370118.701 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:21:58.701Z,1379370118.701 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:21:58.701Z,1379370118.701 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:22:00.716Z,1379370120.716 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:02.723Z,1379370122.723 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:22:02.724Z,1379370122.724 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:22:04.726Z,1379370124.726 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:22:04.727Z,1379370124.727 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:22:06.733Z,1379370126.733 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:06.733Z,1379370126.733 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:22:06.733Z,1379370126.733 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:22:08.736Z,1379370128.736 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:08.736Z,1379370128.736 [DVL_micro](INFO): Querying output modes
2013-09-16T22:22:08.736Z,1379370128.736 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:22:10.747Z,1379370130.747 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:10.748Z,1379370130.748 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:22:10.748Z,1379370130.748 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:22:12.750Z,1379370132.750 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:14.766Z,1379370134.766 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:22:14.766Z,1379370134.766 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:22:16.769Z,1379370136.769 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:22:16.769Z,1379370136.769 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:22:18.780Z,1379370138.780 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:18.780Z,1379370138.780 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:22:18.780Z,1379370138.780 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:22:20.787Z,1379370140.787 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:20.787Z,1379370140.787 [DVL_micro](INFO): Querying output modes
2013-09-16T22:22:20.787Z,1379370140.787 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:22:22.798Z,1379370142.798 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:22.798Z,1379370142.798 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:22:22.798Z,1379370142.798 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:22:24.821Z,1379370144.821 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:26.825Z,1379370146.825 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:22:26.825Z,1379370146.825 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:22:28.828Z,1379370148.828 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:22:28.828Z,1379370148.828 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:22:30.831Z,1379370150.831 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:30.831Z,1379370150.831 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:22:30.831Z,1379370150.831 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:22:32.834Z,1379370152.834 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:32.834Z,1379370152.834 [DVL_micro](INFO): Querying output modes
2013-09-16T22:22:32.834Z,1379370152.834 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:22:34.837Z,1379370154.837 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:34.837Z,1379370154.837 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:22:34.837Z,1379370154.837 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:22:36.848Z,1379370156.848 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:38.852Z,1379370158.852 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:22:38.852Z,1379370158.852 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:22:40.854Z,1379370160.854 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:22:40.855Z,1379370160.855 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:22:42.769Z,1379370162.769 [Startup:StartupSatComms:A](INFO): Timed out from 2013-09-16T22:21:42.5Z
2013-09-16T22:22:42.769Z,1379370162.769 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-09-16T22:22:42.770Z,1379370162.770 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-09-16T22:22:42.770Z,1379370162.770 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-09-16T22:22:42.770Z,1379370162.770 [Startup:StartupSatComms:A] Stopped
2013-09-16T22:22:42.770Z,1379370162.770 [Startup:StartupSatComms:B] Running Loop=1
2013-09-16T22:22:42.865Z,1379370162.865 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:42.865Z,1379370162.865 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:22:42.865Z,1379370162.865 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:22:43.166Z,1379370163.166 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-09-16T22:22:44.876Z,1379370164.876 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:44.876Z,1379370164.876 [DVL_micro](INFO): Querying output modes
2013-09-16T22:22:44.876Z,1379370164.876 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:22:46.883Z,1379370166.883 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:46.884Z,1379370166.884 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:22:46.884Z,1379370166.884 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:22:48.890Z,1379370168.890 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:50.903Z,1379370170.903 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:22:50.903Z,1379370170.903 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:22:52.909Z,1379370172.909 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:22:52.909Z,1379370172.909 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:22:54.916Z,1379370174.916 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:54.916Z,1379370174.916 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:22:54.916Z,1379370174.916 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:22:56.923Z,1379370176.923 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:56.923Z,1379370176.923 [DVL_micro](INFO): Querying output modes
2013-09-16T22:22:56.923Z,1379370176.923 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:22:58.934Z,1379370178.934 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:22:58.934Z,1379370178.934 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:22:58.934Z,1379370178.934 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:23:00.937Z,1379370180.937 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:02.949Z,1379370182.949 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:23:02.949Z,1379370182.949 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:23:04.952Z,1379370184.952 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:23:04.952Z,1379370184.952 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:23:06.954Z,1379370186.954 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:06.954Z,1379370186.954 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:23:06.955Z,1379370186.955 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:23:08.966Z,1379370188.966 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:08.966Z,1379370188.966 [DVL_micro](INFO): Querying output modes
2013-09-16T22:23:08.966Z,1379370188.966 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:23:10.977Z,1379370190.977 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:10.977Z,1379370190.977 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:23:10.977Z,1379370190.977 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:23:12.988Z,1379370192.988 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:14.995Z,1379370194.995 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:23:14.996Z,1379370194.996 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:23:16.998Z,1379370196.998 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:23:16.999Z,1379370196.999 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:23:19.013Z,1379370199.013 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:19.013Z,1379370199.013 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:23:19.013Z,1379370199.013 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:23:21.020Z,1379370201.020 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:21.020Z,1379370201.020 [DVL_micro](INFO): Querying output modes
2013-09-16T22:23:21.020Z,1379370201.020 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:23:23.027Z,1379370203.027 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:23.027Z,1379370203.027 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:23:23.028Z,1379370203.028 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:23:25.031Z,1379370205.031 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:27.042Z,1379370207.042 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:23:27.042Z,1379370207.042 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:23:29.045Z,1379370209.045 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:23:29.045Z,1379370209.045 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:23:31.048Z,1379370211.048 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:31.048Z,1379370211.048 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:23:31.048Z,1379370211.048 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:23:33.055Z,1379370213.055 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:33.055Z,1379370213.055 [DVL_micro](INFO): Querying output modes
2013-09-16T22:23:33.055Z,1379370213.055 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:23:35.058Z,1379370215.058 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:35.058Z,1379370215.058 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:23:35.058Z,1379370215.058 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:23:37.069Z,1379370217.069 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:39.081Z,1379370219.081 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:23:39.081Z,1379370219.081 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:23:41.084Z,1379370221.084 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:23:41.084Z,1379370221.084 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:23:42.630Z,1379370222.630 [CBIT](INFO): Clearing failed count for component BuoyancyServo
2013-09-16T22:23:42.631Z,1379370222.631 [BuoyancyServo] No Fault, FailCount= 5
2013-09-16T22:23:43.024Z,1379370223.024 [Startup:StartupSatComms:B](INFO): Timed out from 2013-09-16T22:22:42.8Z
2013-09-16T22:23:43.024Z,1379370223.024 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-09-16T22:23:43.024Z,1379370223.024 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-09-16T22:23:43.024Z,1379370223.024 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-09-16T22:23:43.024Z,1379370223.024 [Startup:StartupSatComms:B] Stopped
2013-09-16T22:23:43.025Z,1379370223.025 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-09-16T22:23:43.025Z,1379370223.025 [Startup:StartupSatComms] Stopped
2013-09-16T22:23:43.025Z,1379370223.025 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-09-16T22:23:43.026Z,1379370223.026 [Startup](INFO): Completed Startup
2013-09-16T22:23:43.026Z,1379370223.026 [Startup] Stopped
2013-09-16T22:23:43.026Z,1379370223.026 [Startup](INFO): Aggregate::uninitialize Startup
2013-09-16T22:23:43.026Z,1379370223.026 [Startup:A.GoToSurface] Stopped
2013-09-16T22:23:43.026Z,1379370223.026 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-09-16T22:23:43.032Z,1379370223.032 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-09-16T22:23:43.090Z,1379370223.090 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:43.091Z,1379370223.091 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:23:43.091Z,1379370223.091 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:23:45.098Z,1379370225.098 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:45.098Z,1379370225.098 [DVL_micro](INFO): Querying output modes
2013-09-16T22:23:45.098Z,1379370225.098 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:23:47.105Z,1379370227.105 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:47.105Z,1379370227.105 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:23:47.105Z,1379370227.105 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:23:49.116Z,1379370229.116 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:51.120Z,1379370231.120 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:23:51.120Z,1379370231.120 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:23:53.122Z,1379370233.122 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:23:53.123Z,1379370233.123 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:23:55.129Z,1379370235.129 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:55.129Z,1379370235.129 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:23:55.129Z,1379370235.129 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:23:57.132Z,1379370237.132 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:57.132Z,1379370237.132 [DVL_micro](INFO): Querying output modes
2013-09-16T22:23:57.132Z,1379370237.132 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:23:59.135Z,1379370239.135 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:23:59.135Z,1379370239.135 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:23:59.136Z,1379370239.136 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:24:01.142Z,1379370241.142 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:24:03.150Z,1379370243.150 [DVL_micro](INFO): NQ1 requested
2013-09-16T22:24:03.150Z,1379370243.150 [DVL_micro](INFO): Cycling power to configure device.
2013-09-16T22:24:05.153Z,1379370245.153 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-09-16T22:24:05.153Z,1379370245.153 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD1616 00 0

2013-09-16T22:24:07.164Z,1379370247.164 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:24:07.164Z,1379370247.164 [DVL_micro](INFO): Enabling NQ1 output
2013-09-16T22:24:07.164Z,1379370247.164 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0505 01 1

2013-09-16T22:24:09.171Z,1379370249.171 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:24:09.171Z,1379370249.171 [DVL_micro](INFO): Querying output modes
2013-09-16T22:24:09.171Z,1379370249.171 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-09-16T22:24:09.960Z,1379370249.960 [CommandLine](IMPORTANT): got command quit
2013-09-16T22:24:11.062Z,1379370251.062 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-09-16T22:24:11.062Z,1379370251.062 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-09-16T22:24:11.178Z,1379370251.178 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:24:11.178Z,1379370251.178 [DVL_micro](INFO): Output Modes: No Response
2013-09-16T22:24:11.178Z,1379370251.178 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-09-16T22:24:11.342Z,1379370251.342 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-09-16T22:24:11.555Z,1379370251.555 [WetLabsBB2FL](INFO): Powering down
2013-09-16T22:24:11.563Z,1379370251.563 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-09-16T22:24:11.591Z,1379370251.591 [CTD_NeilBrown](INFO): Powering down
2013-09-16T22:24:11.603Z,1379370251.603 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-09-16T22:24:13.189Z,1379370253.189 [DVL_micro](DEBUG): cmdResponse: 
2013-09-16T22:24:13.190Z,1379370253.190 [DVL_micro](INFO): uninitialize:Powering down
2013-09-16T22:24:13.201Z,1379370253.201 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-09-16T22:24:13.330Z,1379370253.330 [MissionManager](IMPORTANT): Started mission Default
2013-09-16T22:24:13.330Z,1379370253.330 [Default] Running Loop=1
2013-09-16T22:24:13.330Z,1379370253.330 [Default](INFO): Aggregate::initialize Default
2013-09-16T22:24:13.330Z,1379370253.330 [Default:D.SetSpeed] Running Loop=1
2013-09-16T22:24:13.330Z,1379370253.330 [Default:D.SetSpeed](DEBUG): Initialize.
2013-09-16T22:24:13.330Z,1379370253.330 [Default:E.GoToSurface] Running Loop=1
2013-09-16T22:24:13.330Z,1379370253.330 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T22:24:13.331Z,1379370253.331 [Default:Iridium] Running Loop=1
2013-09-16T22:24:13.331Z,1379370253.331 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-09-16T22:24:13.331Z,1379370253.331 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-09-16T22:24:13.331Z,1379370253.331 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-09-16T22:24:13.331Z,1379370253.331 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-09-16T22:24:13.331Z,1379370253.331 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-09-16T22:24:13.332Z,1379370253.332 [Default:E.GoToSurface] Running Loop=1
2013-09-16T22:24:13.337Z,1379370253.337 [Default:D.SetSpeed] Running Loop=1
2013-09-16T22:24:13.342Z,1379370253.342 [Default:CallIridium] Running Loop=1
2013-09-16T22:24:13.342Z,1379370253.342 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-09-16T22:24:13.342Z,1379370253.342 [Default:CallIridium:A] Running Loop=1
2013-09-16T22:24:13.344Z,1379370253.344 [Default:CallIridium:A] Stopped
2013-09-16T22:24:13.344Z,1379370253.344 [Default:CallIridium:B] Running Loop=1
2013-09-16T22:24:13.345Z,1379370253.345 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-09-16T22:24:13.350Z,1379370253.350 [Default:Iridium:B.GoToSurface] Stopped
2013-09-16T22:24:13.350Z,1379370253.350 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-09-16T22:24:13.350Z,1379370253.350 [Default:Iridium:Read_Iridium] Running Loop=1
2013-09-16T22:24:13.350Z,1379370253.350 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-09-16T22:24:13.355Z,1379370253.355 [Default:GPS] Running Loop=1
2013-09-16T22:24:13.356Z,1379370253.356 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-09-16T22:24:13.356Z,1379370253.356 [Default:GPS:A.SetSpeed] Running Loop=1
2013-09-16T22:24:13.356Z,1379370253.356 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-09-16T22:24:13.356Z,1379370253.356 [Default:GPS:B.GoToSurface] Running Loop=1
2013-09-16T22:24:13.356Z,1379370253.356 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.