2013-05-22T15:00:09.695Z,1369234809.694 [Supervisor](DEBUG): Initializing supervisor.
2013-05-22T15:00:09.701Z,1369234809.701 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-05-22T15:00:09.701Z,1369234809.701 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-05-22T15:00:09.705Z,1369234809.705 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-05-22T15:00:09.709Z,1369234809.708 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-05-22T15:00:09.719Z,1369234809.719 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-05-22T15:00:09.721Z,1369234809.721 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-05-22T15:00:09.722Z,1369234809.722 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-05-22T15:00:09.725Z,1369234809.725 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-05-22T15:00:09.725Z,1369234809.726 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-05-22T15:00:09.730Z,1369234809.730 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-05-22T15:00:10.062Z,1369234810.062 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-05-22T15:00:10.062Z,1369234810.062 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-05-22T15:00:10.282Z,1369234810.282 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-05-22T15:00:10.282Z,1369234810.282 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-05-22T15:00:10.380Z,1369234810.380 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-05-22T15:00:10.382Z,1369234810.382 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-05-22T15:00:10.626Z,1369234810.626 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-05-22T15:00:10.626Z,1369234810.626 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-05-22T15:00:10.781Z,1369234810.781 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-05-22T15:00:10.783Z,1369234810.783 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-05-22T15:00:11.054Z,1369234811.054 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-05-22T15:00:11.054Z,1369234811.054 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-05-22T15:00:11.248Z,1369234811.248 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-05-22T15:00:11.250Z,1369234811.250 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-05-22T15:00:11.540Z,1369234811.540 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-05-22T15:00:11.542Z,1369234811.542 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-05-22T15:00:11.652Z,1369234811.652 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-05-22T15:00:11.653Z,1369234811.653 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-05-22T15:00:12.126Z,1369234812.126 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-05-22T15:00:12.127Z,1369234812.127 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-05-22T15:00:12.257Z,1369234812.257 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-05-22T15:00:12.258Z,1369234812.258 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-05-22T15:00:12.354Z,1369234812.354 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-05-22T15:00:12.358Z,1369234812.358 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-05-22T15:00:12.475Z,1369234812.475 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-05-22T15:00:12.625Z,1369234812.625 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-05-22T15:00:12.798Z,1369234812.798 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-05-22T15:00:12.914Z,1369234812.914 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-05-22T15:00:13.029Z,1369234813.029 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-05-22T15:00:14.436Z,1369234814.436 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-05-22T15:00:14.546Z,1369234814.546 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-05-22T15:00:15.243Z,1369234815.243 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-05-22T15:00:15.276Z,1369234815.276 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-05-22T15:00:15.463Z,1369234815.463 [InternalSim] Loaded
2013-05-22T15:00:15.463Z,1369234815.463 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-05-22T15:00:15.464Z,1369234815.464 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-05-22T15:00:15.465Z,1369234815.465 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-05-22T15:00:15.546Z,1369234815.546 [SBIT](DEBUG): Construct Startup Built In Test.
2013-05-22T15:00:15.575Z,1369234815.575 [SBIT] Loaded
2013-05-22T15:00:15.575Z,1369234815.575 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-05-22T15:00:15.576Z,1369234815.576 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-05-22T15:00:15.606Z,1369234815.606 [IBIT] Loaded
2013-05-22T15:00:15.606Z,1369234815.606 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-05-22T15:00:15.609Z,1369234815.609 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-05-22T15:00:15.732Z,1369234815.732 [CBIT] Loaded
2013-05-22T15:00:15.732Z,1369234815.732 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-05-22T15:00:15.733Z,1369234815.733 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-05-22T15:00:15.733Z,1369234815.733 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-05-22T15:00:15.907Z,1369234815.907 [BuoyancyServo] Loaded
2013-05-22T15:00:15.907Z,1369234815.907 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-05-22T15:00:15.919Z,1369234815.920 [ElevatorServo] Loaded
2013-05-22T15:00:15.920Z,1369234815.920 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-05-22T15:00:15.932Z,1369234815.932 [MassServo] Loaded
2013-05-22T15:00:15.932Z,1369234815.932 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-05-22T15:00:15.944Z,1369234815.944 [RudderServo] Loaded
2013-05-22T15:00:15.944Z,1369234815.944 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-05-22T15:00:15.956Z,1369234815.956 [ThrusterServo] Loaded
2013-05-22T15:00:15.957Z,1369234815.957 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-05-22T15:00:15.957Z,1369234815.957 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-05-22T15:00:15.958Z,1369234815.958 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-05-22T15:00:15.991Z,1369234815.991 [DepthRateCalculator] Loaded
2013-05-22T15:00:15.991Z,1369234815.991 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-05-22T15:00:18.969Z,1369234818.969 [HFRadarModelCalc] Loaded
2013-05-22T15:00:18.970Z,1369234818.970 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-05-22T15:00:18.986Z,1369234818.986 [NavChart] Loaded
2013-05-22T15:00:18.986Z,1369234818.986 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-05-22T15:00:18.992Z,1369234818.992 [PitchRateCalculator] Loaded
2013-05-22T15:00:18.992Z,1369234818.992 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-05-22T15:00:19.004Z,1369234819.004 [SpeedCalculator] Loaded
2013-05-22T15:00:19.004Z,1369234819.004 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-05-22T15:00:19.020Z,1369234819.020 [TempGradientCalculator] Loaded
2013-05-22T15:00:19.020Z,1369234819.020 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-05-22T15:00:19.026Z,1369234819.026 [YawRateCalculator] Loaded
2013-05-22T15:00:19.026Z,1369234819.026 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-05-22T15:00:19.074Z,1369234819.074 [Navigation] Loaded
2013-05-22T15:00:19.074Z,1369234819.074 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-05-22T15:00:19.075Z,1369234819.075 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-05-22T15:00:19.075Z,1369234819.075 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-05-22T15:00:19.331Z,1369234819.331 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-05-22T15:00:19.332Z,1369234819.332 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-05-22T15:00:19.370Z,1369234819.371 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-05-22T15:00:19.371Z,1369234819.371 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-05-22T15:00:19.430Z,1369234819.430 [VerticalControl](DEBUG): Construct VerticalControl.
2013-05-22T15:00:19.524Z,1369234819.524 [VerticalControl] Loaded
2013-05-22T15:00:19.525Z,1369234819.524 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-05-22T15:00:19.526Z,1369234819.526 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-05-22T15:00:19.582Z,1369234819.582 [HorizontalControl] Loaded
2013-05-22T15:00:19.582Z,1369234819.582 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-05-22T15:00:19.583Z,1369234819.583 [SpeedControl](DEBUG): Construct SpeedControl.
2013-05-22T15:00:19.585Z,1369234819.585 [SpeedControl] Loaded
2013-05-22T15:00:19.586Z,1369234819.586 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-05-22T15:00:19.586Z,1369234819.586 [LoopControl](DEBUG): Construct LoopControl.
2013-05-22T15:00:19.587Z,1369234819.587 [LoopControl] Loaded
2013-05-22T15:00:19.587Z,1369234819.587 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-05-22T15:00:19.588Z,1369234819.588 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-05-22T15:00:19.588Z,1369234819.588 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-05-22T15:00:19.596Z,1369234819.596 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-05-22T15:00:19.601Z,1369234819.602 [AsyncPiEstimator] Loaded
2013-05-22T15:00:19.602Z,1369234819.602 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-05-22T15:00:19.603Z,1369234819.603 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4063B4E0
2013-05-22T15:00:19.604Z,1369234819.604 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-05-22T15:00:19.604Z,1369234819.604 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-05-22T15:00:19.774Z,1369234819.774 [AHRS_sp3003D] Loaded
2013-05-22T15:00:19.774Z,1369234819.774 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-05-22T15:00:20.054Z,1369234820.055 [Batt_Ocean_Server] Loaded
2013-05-22T15:00:20.055Z,1369234820.055 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2013-05-22T15:00:20.069Z,1369234820.069 [Depth_Keller] Loaded
2013-05-22T15:00:20.069Z,1369234820.069 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-05-22T15:00:20.075Z,1369234820.075 [DropWeight] Loaded
2013-05-22T15:00:20.075Z,1369234820.075 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-05-22T15:00:20.257Z,1369234820.257 [DVL_micro] Loaded
2013-05-22T15:00:20.257Z,1369234820.257 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-05-22T15:00:20.259Z,1369234820.259 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406B64E0
2013-05-22T15:00:20.348Z,1369234820.348 [NAL9602] Loaded
2013-05-22T15:00:20.348Z,1369234820.348 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-05-22T15:00:20.402Z,1369234820.402 [Onboard] Loaded
2013-05-22T15:00:20.403Z,1369234820.403 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-05-22T15:00:20.410Z,1369234820.410 [Radio_Freewave] Loaded
2013-05-22T15:00:20.410Z,1369234820.410 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-05-22T15:00:20.584Z,1369234820.584 [DAT] Loaded
2013-05-22T15:00:20.584Z,1369234820.584 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-05-22T15:00:20.585Z,1369234820.585 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-05-22T15:00:20.585Z,1369234820.585 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-05-22T15:00:20.682Z,1369234820.682 [CTD_NeilBrown] Loaded
2013-05-22T15:00:20.683Z,1369234820.683 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-05-22T15:00:20.684Z,1369234820.684 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407084E0
2013-05-22T15:00:20.718Z,1369234820.718 [WetLabsBB2FL] Loaded
2013-05-22T15:00:20.718Z,1369234820.718 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-05-22T15:00:20.719Z,1369234820.719 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407384E0
2013-05-22T15:00:20.720Z,1369234820.720 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-05-22T15:00:20.722Z,1369234820.722 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-05-22T15:00:20.723Z,1369234820.723 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-05-22T15:00:20.733Z,1369234820.733 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-05-22T15:00:20.734Z,1369234820.734 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407684E0
2013-05-22T15:00:20.739Z,1369234820.739 [Supervisor](DEBUG): Running supervisor.
2013-05-22T15:00:20.740Z,1369234820.740 [CommandLine](INFO): Thread ID is 747
2013-05-22T15:00:20.742Z,1369234820.742 [controlThread](INFO): Thread ID is 746
2013-05-22T15:00:20.743Z,1369234820.743 [controlThread](DEBUG): Initializing ControlThread
2013-05-22T15:00:20.743Z,1369234820.743 [CycleStarter](INFO): Thread ID is 745
2013-05-22T15:00:20.743Z,1369234820.743 [InternalSim](DEBUG):  InternalSim initializing...
2013-05-22T15:00:20.842Z,1369234820.842 [logger](INFO): Thread ID is 748
2013-05-22T15:00:20.930Z,1369234820.930 [AsyncPiEstimator](INFO): Thread ID is 809
2013-05-22T15:00:20.930Z,1369234820.930 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-05-22T15:00:20.939Z,1369234820.939 [DVL_micro](INFO): Thread ID is 810
2013-05-22T15:00:21.036Z,1369234821.036 [CTD_NeilBrown](INFO): Thread ID is 811
2013-05-22T15:00:21.036Z,1369234821.036 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-05-22T15:00:21.039Z,1369234821.039 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-05-22T15:00:21.091Z,1369234821.091 [DVL_micro](INFO): Initializing
2013-05-22T15:00:21.091Z,1369234821.091 [DVL_micro](INFO): start:Powering up
2013-05-22T15:00:21.092Z,1369234821.092 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-05-22T15:00:21.092Z,1369234821.092 [DVL_micro](INFO): Cycling power to configure device.
2013-05-22T15:00:21.093Z,1369234821.093 [WetLabsBB2FL](INFO): Thread ID is 812
2013-05-22T15:00:21.094Z,1369234821.094 [WetLabsBB2FL](INFO): Powering down
2013-05-22T15:00:21.114Z,1369234821.114 [NavChartDb](INFO): Thread ID is 813
2013-05-22T15:00:21.123Z,1369234821.122 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-05-22T15:00:21.123Z,1369234821.123 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-05-22T15:00:21.124Z,1369234821.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-05-22T15:00:21.124Z,1369234821.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-05-22T15:00:21.124Z,1369234821.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-05-22T15:00:21.124Z,1369234821.124 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-05-22T15:00:21.125Z,1369234821.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-05-22T15:00:21.125Z,1369234821.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-05-22T15:00:21.125Z,1369234821.125 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-05-22T15:00:21.165Z,1369234821.165 [SBIT](INFO): Initialize SBIT Component.
2013-05-22T15:00:21.166Z,1369234821.166 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:10376
2013-05-22T15:00:21.166Z,1369234821.166 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-05-22T15:00:21.166Z,1369234821.166 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-05-22T15:00:21.167Z,1369234821.167 [IBIT](INFO): Initialize IBIT Component.
2013-05-22T15:00:21.168Z,1369234821.168 [CBIT](DEBUG): Initialize CBIT Component.
2013-05-22T15:00:21.168Z,1369234821.168 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-05-22T15:00:21.194Z,1369234821.194 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-05-22T15:00:21.195Z,1369234821.195 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-05-22T15:00:21.196Z,1369234821.195 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-05-22T15:00:21.196Z,1369234821.196 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-05-22T15:00:21.196Z,1369234821.196 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-05-22T15:00:21.204Z,1369234821.204 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-05-22T15:00:21.205Z,1369234821.205 [Navigation](DEBUG): Initializing Navigation.
2013-05-22T15:00:21.213Z,1369234821.213 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-05-22T15:00:21.215Z,1369234821.215 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-05-22T15:00:21.216Z,1369234821.216 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-05-22T15:00:21.216Z,1369234821.216 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-05-22T15:00:23.002Z,1369234823.001 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2013-05-22T15:00:23.031Z,1369234823.031 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-05-22T15:00:23.082Z,1369234823.082 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-22T15:00:23.108Z,1369234823.108 [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-05-22T15:00:23.109Z,1369234823.109 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-05-22T15:00:23.172Z,1369234823.172 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-05-22T15:00:23.175Z,1369234823.174 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-05-22T15:00:23.194Z,1369234823.194 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-22T15:00:23.214Z,1369234823.214 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-05-22T15:00:23.217Z,1369234823.217 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-22T15:00:23.223Z,1369234823.223 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-05-22T15:00:23.241Z,1369234823.241 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-05-22T15:00:23.242Z,1369234823.242 [DVL_micro](INFO): Querying output modes
2013-05-22T15:00:23.242Z,1369234823.242 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-05-22T15:00:23.253Z,1369234823.253 [DVL_micro](DEBUG): cmdResponse: 01
2013-05-22T15:00:23.253Z,1369234823.253 [DVL_micro](INFO): NQ1 output enabled
2013-05-22T15:00:23.254Z,1369234823.254 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-05-22T15:00:23.264Z,1369234823.264 [Default:D.SetSpeed](DEBUG): Construct.
2013-05-22T15:00:23.268Z,1369234823.268 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-05-22T15:00:23.273Z,1369234823.273 [DVL_micro](INFO): pause:Powering down
2013-05-22T15:00:23.284Z,1369234823.284 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-05-22T15:00:23.288Z,1369234823.288 [Default:F.Wait](DEBUG): Construct Wait.
2013-05-22T15:00:23.304Z,1369234823.304 [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-05-22T15:00:23.308Z,1369234823.308 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-05-22T15:00:23.345Z,1369234823.345 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-05-22T15:00:23.571Z,1369234823.571 [Radio_Freewave](INFO): Powering up
2013-05-22T15:00:23.597Z,1369234823.597 [DAT](INFO): Powering up
2013-05-22T15:00:23.597Z,1369234823.597 [DAT](DEBUG): Initializing DAT.
2013-05-22T15:00:23.799Z,1369234823.799 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-05-22T15:00:23.802Z,1369234823.802 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-05-22T15:00:23.825Z,1369234823.825 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-05-22T15:00:23.832Z,1369234823.832 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-05-22T15:00:23.882Z,1369234823.882 [MassServo](DEBUG): Initializing EZServoServo.
2013-05-22T15:00:23.889Z,1369234823.889 [MassServo](DEBUG): Initializing MassServo.
2013-05-22T15:00:23.909Z,1369234823.909 [RudderServo](DEBUG): Initializing EZServoServo.
2013-05-22T15:00:23.917Z,1369234823.917 [RudderServo](DEBUG): Initializing RudderServo.
2013-05-22T15:00:23.923Z,1369234823.923 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-05-22T15:00:23.929Z,1369234823.929 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-05-22T15:00:24.829Z,1369234824.829 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2013-05-22T15:00:24.829Z,1369234824.829 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2013-05-22T15:00:24.829Z,1369234824.829 [BuoyancyServo] Communications Fault, FailCount= 1
2013-05-22T15:00:24.829Z,1369234824.829 [BuoyancyServo](ERROR): Communications Fault
2013-05-22T15:00:25.039Z,1369234825.039 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2013-05-22T15:00:25.295Z,1369234825.295 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-05-22T15:00:25.296Z,1369234825.296 [BuoyancyServo](INFO): Powering down
2013-05-22T15:00:25.625Z,1369234825.625 [NAL9602](INFO): Powering up NAL9602
2013-05-22T15:00:27.519Z,1369234827.519 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2013-05-22T15:00:27.519Z,1369234827.519 [BuoyancyServo] No Fault, FailCount= 1
2013-05-22T15:00:27.808Z,1369234827.808 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-05-22T15:00:27.926Z,1369234827.926 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-05-22T15:00:36.450Z,1369234836.450 [NAL9602](INFO): NAL9602 initialized
2013-05-22T15:00:36.788Z,1369234836.788 [SBIT](IMPORTANT): Beginning Startup BIT
2013-05-22T15:00:36.794Z,1369234836.795 [CBIT](IMPORTANT): Beginning GF scan
2013-05-22T15:00:43.508Z,1369234843.508 [DAT](INFO): Powering down
2013-05-22T15:01:03.362Z,1369234863.362 [CBIT](FAULT): Chan 4 High side GF detected
mA:
CHAN 5 (24V): 0.039600
CHAN 4 (Batt): 0.013296
CHAN 2 (12V): 0.004400
CHAN 1 (5V): 0.000765
CHAN 0 (3.3V): 0.000574
OPEN: 0.000670
Full Scale Calc: 0.392