2012-09-17T16:22:13.606Z,1347898933.606 [Supervisor](DEBUG): Initializing supervisor.
2012-09-17T16:22:13.608Z,1347898933.608 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-09-17T16:22:13.609Z,1347898933.609 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-09-17T16:22:13.610Z,1347898933.610 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-09-17T16:22:13.613Z,1347898933.613 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-09-17T16:22:13.624Z,1347898933.624 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-09-17T16:22:13.625Z,1347898933.625 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-09-17T16:22:13.626Z,1347898933.626 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-09-17T16:22:13.626Z,1347898933.626 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-09-17T16:22:13.627Z,1347898933.628 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-09-17T16:22:13.912Z,1347898933.912 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-09-17T16:22:13.912Z,1347898933.912 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-09-17T16:22:14.092Z,1347898934.092 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-09-17T16:22:14.093Z,1347898934.093 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-09-17T16:22:14.178Z,1347898934.178 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-09-17T16:22:14.179Z,1347898934.179 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-09-17T16:22:14.381Z,1347898934.381 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-09-17T16:22:14.382Z,1347898934.382 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-09-17T16:22:14.520Z,1347898934.520 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-09-17T16:22:14.521Z,1347898934.521 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-09-17T16:22:14.775Z,1347898934.775 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-09-17T16:22:14.776Z,1347898934.776 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-09-17T16:22:14.946Z,1347898934.946 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-09-17T16:22:14.947Z,1347898934.947 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-09-17T16:22:15.199Z,1347898935.199 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-09-17T16:22:15.199Z,1347898935.199 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-09-17T16:22:15.299Z,1347898935.299 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-09-17T16:22:15.300Z,1347898935.300 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-09-17T16:22:15.698Z,1347898935.698 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-09-17T16:22:15.699Z,1347898935.699 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-09-17T16:22:15.812Z,1347898935.812 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-09-17T16:22:15.813Z,1347898935.813 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-09-17T16:22:15.898Z,1347898935.898 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-09-17T16:22:15.899Z,1347898935.899 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-09-17T16:22:15.999Z,1347898935.999 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-09-17T16:22:16.128Z,1347898936.128 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-09-17T16:22:16.214Z,1347898936.214 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-09-17T16:22:16.316Z,1347898936.316 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-09-17T16:22:16.417Z,1347898936.417 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-09-17T16:22:16.535Z,1347898936.535 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-09-17T16:22:16.625Z,1347898936.625 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-09-17T16:22:16.716Z,1347898936.716 [Supervisor](IMPORTANT): Reading configuration overrides from Data/config.db
2012-09-17T16:22:16.725Z,1347898936.726 [ComponentRegistry](DEBUG): Loaded Config Component "configDb
2012-09-17T16:22:16.756Z,1347898936.756 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-09-17T16:22:16.895Z,1347898936.895 [InternalSim] Loaded
2012-09-17T16:22:16.895Z,1347898936.895 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-09-17T16:22:16.896Z,1347898936.896 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-09-17T16:22:16.896Z,1347898936.897 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-09-17T16:22:16.953Z,1347898936.953 [SBIT](DEBUG): Construct Startup Built In Test.
2012-09-17T16:22:16.966Z,1347898936.967 [SBIT] Loaded
2012-09-17T16:22:16.967Z,1347898936.967 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-09-17T16:22:16.968Z,1347898936.968 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-09-17T16:22:16.996Z,1347898936.996 [IBIT] Loaded
2012-09-17T16:22:16.996Z,1347898936.996 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-09-17T16:22:16.999Z,1347898936.999 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-09-17T16:22:17.116Z,1347898937.116 [CBIT] Loaded
2012-09-17T16:22:17.116Z,1347898937.116 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-09-17T16:22:17.117Z,1347898937.117 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-09-17T16:22:17.117Z,1347898937.117 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-09-17T16:22:17.257Z,1347898937.257 [BuoyancyServo] Loaded
2012-09-17T16:22:17.257Z,1347898937.257 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-09-17T16:22:17.269Z,1347898937.270 [MassServo] Loaded
2012-09-17T16:22:17.270Z,1347898937.270 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-09-17T16:22:17.282Z,1347898937.282 [RudderServo] Loaded
2012-09-17T16:22:17.282Z,1347898937.282 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-09-17T16:22:17.294Z,1347898937.294 [ThrusterServo] Loaded
2012-09-17T16:22:17.294Z,1347898937.294 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-09-17T16:22:17.295Z,1347898937.295 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-09-17T16:22:17.295Z,1347898937.295 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-09-17T16:22:17.312Z,1347898937.312 [DepthRateCalculator] Loaded
2012-09-17T16:22:17.312Z,1347898937.312 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-09-17T16:22:19.798Z,1347898939.798 [HFRadarModelCalc] Loaded
2012-09-17T16:22:19.799Z,1347898939.799 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-09-17T16:22:19.814Z,1347898939.814 [NavChart] Loaded
2012-09-17T16:22:19.814Z,1347898939.815 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-09-17T16:22:19.820Z,1347898939.820 [PitchRateCalculator] Loaded
2012-09-17T16:22:19.821Z,1347898939.821 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-09-17T16:22:19.827Z,1347898939.827 [SpeedCalculator] Loaded
2012-09-17T16:22:19.827Z,1347898939.827 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-09-17T16:22:19.842Z,1347898939.842 [TempGradientCalculator] Loaded
2012-09-17T16:22:19.843Z,1347898939.843 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-09-17T16:22:19.848Z,1347898939.848 [YawRateCalculator] Loaded
2012-09-17T16:22:19.849Z,1347898939.849 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-09-17T16:22:19.869Z,1347898939.869 [Navigation] Loaded
2012-09-17T16:22:19.869Z,1347898939.869 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-09-17T16:22:19.869Z,1347898939.869 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-09-17T16:22:19.870Z,1347898939.870 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-09-17T16:22:20.093Z,1347898940.093 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-09-17T16:22:20.093Z,1347898940.093 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-09-17T16:22:20.115Z,1347898940.115 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-09-17T16:22:20.115Z,1347898940.115 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-09-17T16:22:20.155Z,1347898940.155 [VerticalControl](DEBUG): Construct VerticalControl.
2012-09-17T16:22:20.201Z,1347898940.201 [VerticalControl] Loaded
2012-09-17T16:22:20.201Z,1347898940.201 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-09-17T16:22:20.202Z,1347898940.202 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-09-17T16:22:20.223Z,1347898940.223 [HorizontalControl] Loaded
2012-09-17T16:22:20.223Z,1347898940.223 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-09-17T16:22:20.224Z,1347898940.224 [SpeedControl](DEBUG): Construct SpeedControl.
2012-09-17T16:22:20.226Z,1347898940.226 [SpeedControl] Loaded
2012-09-17T16:22:20.226Z,1347898940.226 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-09-17T16:22:20.227Z,1347898940.227 [LoopControl](DEBUG): Construct LoopControl.
2012-09-17T16:22:20.227Z,1347898940.227 [LoopControl] Loaded
2012-09-17T16:22:20.228Z,1347898940.228 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-09-17T16:22:20.228Z,1347898940.228 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-09-17T16:22:20.229Z,1347898940.229 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-09-17T16:22:20.234Z,1347898940.234 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-09-17T16:22:20.239Z,1347898940.239 [AsyncPiEstimator] Loaded
2012-09-17T16:22:20.239Z,1347898940.239 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-09-17T16:22:20.240Z,1347898940.240 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4060A4E0
2012-09-17T16:22:20.241Z,1347898940.241 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-09-17T16:22:20.242Z,1347898940.241 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-09-17T16:22:20.361Z,1347898940.361 [AHRS_sp3003D] Loaded
2012-09-17T16:22:20.361Z,1347898940.361 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-09-17T16:22:20.375Z,1347898940.375 [Depth_Keller] Loaded
2012-09-17T16:22:20.375Z,1347898940.375 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-09-17T16:22:20.490Z,1347898940.490 [DVL_micro] Loaded
2012-09-17T16:22:20.490Z,1347898940.490 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-09-17T16:22:20.491Z,1347898940.491 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4068A4E0
2012-09-17T16:22:20.572Z,1347898940.572 [NAL9602] Loaded
2012-09-17T16:22:20.573Z,1347898940.573 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-09-17T16:22:20.637Z,1347898940.638 [Onboard] Loaded
2012-09-17T16:22:20.638Z,1347898940.638 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-09-17T16:22:20.639Z,1347898940.639 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-09-17T16:22:20.640Z,1347898940.639 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-09-17T16:22:20.709Z,1347898940.709 [CTD_NeilBrown] Loaded
2012-09-17T16:22:20.709Z,1347898940.709 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-09-17T16:22:20.710Z,1347898940.710 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E24E0
2012-09-17T16:22:20.721Z,1347898940.721 [PAR_Licor] Loaded
2012-09-17T16:22:20.721Z,1347898940.721 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-09-17T16:22:20.738Z,1347898940.738 [Turbulence_NPS] Loaded
2012-09-17T16:22:20.739Z,1347898940.739 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-09-17T16:22:20.740Z,1347898940.740 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407124E0
2012-09-17T16:22:20.769Z,1347898940.769 [WetLabsBB2FL] Loaded
2012-09-17T16:22:20.769Z,1347898940.769 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-09-17T16:22:20.771Z,1347898940.770 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407424E0
2012-09-17T16:22:20.771Z,1347898940.771 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-09-17T16:22:20.774Z,1347898940.773 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-09-17T16:22:20.774Z,1347898940.774 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-09-17T16:22:20.780Z,1347898940.780 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-09-17T16:22:20.781Z,1347898940.781 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407724E0
2012-09-17T16:22:20.786Z,1347898940.786 [Supervisor](DEBUG): Running supervisor.
2012-09-17T16:22:20.789Z,1347898940.789 [controlThread](DEBUG): Initializing ControlThread
2012-09-17T16:22:20.790Z,1347898940.790 [InternalSim](DEBUG):  InternalSim initializing...
2012-09-17T16:22:20.823Z,1347898940.823 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-09-17T16:22:20.833Z,1347898940.833 [SBIT](INFO): Initialize SBIT Component.
2012-09-17T16:22:20.834Z,1347898940.834 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9842
2012-09-17T16:22:20.834Z,1347898940.834 [IBIT](INFO): Initialize IBIT Component.
2012-09-17T16:22:20.835Z,1347898940.835 [CBIT](DEBUG): Initialize CBIT Component.
2012-09-17T16:22:20.836Z,1347898940.836 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-09-17T16:22:20.855Z,1347898940.855 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-09-17T16:22:20.859Z,1347898940.859 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-17T16:22:20.860Z,1347898940.860 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-09-17T16:22:20.860Z,1347898940.860 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-09-17T16:22:20.860Z,1347898940.860 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-09-17T16:22:20.861Z,1347898940.861 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-09-17T16:22:20.863Z,1347898940.864 [WetLabsBB2FL](INFO): Powering down
2012-09-17T16:22:20.882Z,1347898940.882 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-09-17T16:22:20.882Z,1347898940.882 [Navigation](DEBUG): Initializing Navigation.
2012-09-17T16:22:20.883Z,1347898940.883 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-09-17T16:22:20.885Z,1347898940.885 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-09-17T16:22:20.886Z,1347898940.885 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-09-17T16:22:20.906Z,1347898940.906 [DVL_micro](INFO): Initializing
2012-09-17T16:22:20.907Z,1347898940.907 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-09-17T16:22:20.911Z,1347898940.911 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-09-17T16:22:20.906Z,1347898940.906 [DVL_micro](INFO): start:Powering up
2012-09-17T16:22:20.939Z,1347898940.939 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-09-17T16:22:20.975Z,1347898940.975 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-17T16:22:21.007Z,1347898941.007 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2012-09-17T16:22:21.008Z,1347898941.008 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-09-17T16:22:21.088Z,1347898941.088 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-09-17T16:22:21.090Z,1347898941.090 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-09-17T16:22:21.101Z,1347898941.101 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-17T16:22:21.118Z,1347898941.118 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-09-17T16:22:21.125Z,1347898941.125 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-17T16:22:21.129Z,1347898941.129 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-09-17T16:22:21.141Z,1347898941.141 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-09-17T16:22:21.138Z,1347898941.138 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-09-17T16:22:21.150Z,1347898941.151 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-09-17T16:22:21.161Z,1347898941.161 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-09-17T16:22:21.163Z,1347898941.163 [Default:D.SetSpeed](DEBUG): Construct.
2012-09-17T16:22:21.166Z,1347898941.166 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-17T16:22:21.169Z,1347898941.169 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-09-17T16:22:21.171Z,1347898941.171 [NavChartDb](INFO): Creating index for Soundings
2012-09-17T16:22:21.174Z,1347898941.174 [NavChartDb](INFO): Creating index for Contour 0p0
2012-09-17T16:22:21.176Z,1347898941.176 [NavChartDb](INFO): Creating index for Contour 1p8
2012-09-17T16:22:21.182Z,1347898941.182 [NavChartDb](INFO): Creating index for Contour 3p6
2012-09-17T16:22:21.184Z,1347898941.184 [NavChartDb](INFO): Creating index for Contour 5p4
2012-09-17T16:22:21.187Z,1347898941.187 [Default:F.Wait](DEBUG): Construct Wait.
2012-09-17T16:22:21.190Z,1347898941.190 [NavChartDb](INFO): Creating index for Contour 9p1
2012-09-17T16:22:21.192Z,1347898941.192 [NavChartDb](INFO): Creating index for Contour 10p9
2012-09-17T16:22:21.194Z,1347898941.194 [NavChartDb](INFO): Creating index for Contour 18p2
2012-09-17T16:22:21.196Z,1347898941.196 [NavChartDb](INFO): Creating index for Contour 36p5
2012-09-17T16:22:21.199Z,1347898941.198 [NavChartDb](INFO): Creating index for Contour 54p8
2012-09-17T16:22:21.200Z,1347898941.200 [NavChartDb](INFO): Creating index for Contour 73p1
2012-09-17T16:22:21.203Z,1347898941.203 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS" >

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2012-09-17T16:22:21.207Z,1347898941.207 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,NAL9602,Onboard,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-09-17T16:22:21.210Z,1347898941.210 [NavChartDb](INFO): Creating index for Contour 91p4
2012-09-17T16:22:21.212Z,1347898941.212 [NavChartDb](INFO): Creating index for Contour 182p8
2012-09-17T16:22:21.214Z,1347898941.214 [NavChartDb](INFO): Creating index for Contour 365p7
2012-09-17T16:22:21.216Z,1347898941.216 [NavChartDb](INFO): Creating index for Contour 548p6
2012-09-17T16:22:21.222Z,1347898941.222 [NavChartDb](INFO): Creating index for Contour 731p5
2012-09-17T16:22:21.224Z,1347898941.224 [NavChartDb](INFO): Creating index for Contour 914p4
2012-09-17T16:22:21.227Z,1347898941.227 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-09-17T16:22:21.228Z,1347898941.228 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-09-17T16:22:21.238Z,1347898941.238 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-09-17T16:22:21.240Z,1347898941.240 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-09-17T16:22:21.243Z,1347898941.243 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-09-17T16:22:21.244Z,1347898941.244 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-09-17T16:22:21.250Z,1347898941.250 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-09-17T16:22:21.252Z,1347898941.252 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-09-17T16:22:21.257Z,1347898941.257 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-17T16:22:21.258Z,1347898941.258 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-09-17T16:22:21.260Z,1347898941.260 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-09-17T16:22:21.262Z,1347898941.262 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-09-17T16:22:21.272Z,1347898941.272 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-09-17T16:22:21.274Z,1347898941.274 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-09-17T16:22:21.276Z,1347898941.276 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-09-17T16:22:21.279Z,1347898941.279 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-09-17T16:22:21.452Z,1347898941.452 [PAR_Licor](ERROR): PAR reading out of range: -0.017484 uMol/s/m2
2012-09-17T16:22:21.596Z,1347898941.596 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:21.598Z,1347898941.598 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-09-17T16:22:21.605Z,1347898941.605 [MassServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:21.606Z,1347898941.606 [MassServo](DEBUG): Initializing MassServo.
2012-09-17T16:22:21.612Z,1347898941.612 [RudderServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:21.613Z,1347898941.613 [RudderServo](DEBUG): Initializing RudderServo.
2012-09-17T16:22:21.619Z,1347898941.619 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:21.620Z,1347898941.620 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-09-17T16:22:22.510Z,1347898942.510 [DVL_micro](INFO): Querying output modes
2012-09-17T16:22:22.511Z,1347898942.511 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-17T16:22:22.515Z,1347898942.514 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-09-17T16:22:22.515Z,1347898942.515 [DVL_micro](INFO): NQ1 output enabled
2012-09-17T16:22:22.515Z,1347898942.515 [DVL_micro](INFO): RSSI output enabled
2012-09-17T16:22:22.515Z,1347898942.515 [DVL_micro](INFO): ADCP output enabled
2012-09-17T16:22:22.515Z,1347898942.515 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-17T16:22:22.523Z,1347898942.523 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-09-17T16:22:22.527Z,1347898942.527 [DVL_micro](INFO): pause:Powering down
2012-09-17T16:22:25.021Z,1347898945.021 [PAR_Licor](ERROR): PAR reading out of range: -0.031790 uMol/s/m2
2012-09-17T16:22:25.806Z,1347898945.806 [NAL9602](INFO): Powering up NAL9602
2012-09-17T16:22:27.038Z,1347898947.038 [PAR_Licor](ERROR): PAR reading out of range: -0.049274 uMol/s/m2
2012-09-17T16:22:27.070Z,1347898947.070 [MassServo](FAULT): Overload Error
2012-09-17T16:22:27.070Z,1347898947.070 [MassServo] Hardware Fault, FailCount= 1
2012-09-17T16:22:27.070Z,1347898947.070 [MassServo](ERROR): Hardware Fault
2012-09-17T16:22:27.213Z,1347898947.213 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-09-17T16:22:27.450Z,1347898947.450 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-17T16:22:27.451Z,1347898947.451 [MassServo](INFO): Powering down
2012-09-17T16:22:27.473Z,1347898947.473 [CBIT](INFO): Clearing failed state for component MassServo
2012-09-17T16:22:27.473Z,1347898947.473 [MassServo] No Fault, FailCount= 1
2012-09-17T16:22:27.846Z,1347898947.846 [PAR_Licor](ERROR): PAR reading out of range: -0.052453 uMol/s/m2
2012-09-17T16:22:27.858Z,1347898947.858 [MassServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:27.977Z,1347898947.977 [MassServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-17T16:22:27.977Z,1347898947.977 [MassServo](DEBUG): Initializing MassServo.
2012-09-17T16:22:28.638Z,1347898948.638 [PAR_Licor](ERROR): PAR reading out of range: -0.038148 uMol/s/m2
2012-09-17T16:22:31.039Z,1347898951.039 [PAR_Licor](ERROR): PAR reading out of range: -0.047685 uMol/s/m2
2012-09-17T16:22:31.840Z,1347898951.840 [PAR_Licor](ERROR): PAR reading out of range: -0.022253 uMol/s/m2
2012-09-17T16:22:31.870Z,1347898951.870 [MassServo](FAULT): Overload Error
2012-09-17T16:22:31.870Z,1347898951.870 [MassServo] Hardware Fault, FailCount= 2
2012-09-17T16:22:31.871Z,1347898951.871 [MassServo](ERROR): Hardware Fault
2012-09-17T16:22:31.918Z,1347898951.918 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-09-17T16:22:32.252Z,1347898952.252 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-17T16:22:32.252Z,1347898952.252 [MassServo](INFO): Powering down
2012-09-17T16:22:32.255Z,1347898952.255 [CBIT](INFO): Clearing failed state for component MassServo
2012-09-17T16:22:32.255Z,1347898952.255 [MassServo] No Fault, FailCount= 2
2012-09-17T16:22:32.640Z,1347898952.640 [PAR_Licor](ERROR): PAR reading out of range: -0.039737 uMol/s/m2
2012-09-17T16:22:32.652Z,1347898952.652 [MassServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:32.771Z,1347898952.771 [MassServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-17T16:22:32.772Z,1347898952.772 [MassServo](DEBUG): Initializing MassServo.
2012-09-17T16:22:33.439Z,1347898953.439 [PAR_Licor](ERROR): PAR reading out of range: -0.041327 uMol/s/m2
2012-09-17T16:22:34.238Z,1347898954.238 [PAR_Licor](ERROR): PAR reading out of range: -0.036558 uMol/s/m2
2012-09-17T16:22:35.042Z,1347898955.042 [PAR_Licor](ERROR): PAR reading out of range: -0.007947 uMol/s/m2
2012-09-17T16:22:35.839Z,1347898955.839 [PAR_Licor](ERROR): PAR reading out of range: -0.012716 uMol/s/m2
2012-09-17T16:22:36.263Z,1347898956.263 [NAL9602](INFO): NAL9602 initialized
2012-09-17T16:22:36.305Z,1347898956.305 [SBIT](IMPORTANT): Beginning Startup BIT
2012-09-17T16:22:36.307Z,1347898956.307 [CBIT](IMPORTANT): Beginning GF scan
2012-09-17T16:22:36.670Z,1347898956.670 [MassServo](FAULT): Overload Error
2012-09-17T16:22:36.670Z,1347898956.670 [MassServo] Hardware Fault, FailCount= 3
2012-09-17T16:22:36.670Z,1347898956.671 [MassServo](ERROR): Hardware Fault
2012-09-17T16:22:36.675Z,1347898956.675 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-09-17T16:22:37.061Z,1347898957.061 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-17T16:22:37.061Z,1347898957.061 [MassServo](INFO): Powering down
2012-09-17T16:22:37.066Z,1347898957.066 [CBIT](INFO): Clearing failed state for component MassServo
2012-09-17T16:22:37.066Z,1347898957.066 [MassServo] No Fault, FailCount= 3
2012-09-17T16:22:37.444Z,1347898957.444 [PAR_Licor](ERROR): PAR reading out of range: -0.066759 uMol/s/m2
2012-09-17T16:22:37.456Z,1347898957.456 [MassServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:37.576Z,1347898957.576 [MassServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-17T16:22:37.576Z,1347898957.576 [MassServo](DEBUG): Initializing MassServo.
2012-09-17T16:22:39.039Z,1347898959.039 [PAR_Licor](ERROR): PAR reading out of range: -0.084243 uMol/s/m2
2012-09-17T16:22:40.639Z,1347898960.639 [PAR_Licor](ERROR): PAR reading out of range: -0.019074 uMol/s/m2
2012-09-17T16:22:41.470Z,1347898961.470 [MassServo](FAULT): Overload Error
2012-09-17T16:22:41.470Z,1347898961.470 [MassServo] Hardware Fault, FailCount= 4
2012-09-17T16:22:41.470Z,1347898961.470 [MassServo](ERROR): Hardware Fault
2012-09-17T16:22:41.566Z,1347898961.566 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-09-17T16:22:41.851Z,1347898961.852 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-17T16:22:41.852Z,1347898961.852 [MassServo](INFO): Powering down
2012-09-17T16:22:41.905Z,1347898961.905 [CBIT](INFO): Clearing failed state for component MassServo
2012-09-17T16:22:41.905Z,1347898961.905 [MassServo] No Fault, FailCount= 4
2012-09-17T16:22:42.243Z,1347898962.243 [PAR_Licor](ERROR): PAR reading out of range: -1.042710 uMol/s/m2
2012-09-17T16:22:42.255Z,1347898962.255 [MassServo](DEBUG): Initializing EZServoServo.
2012-09-17T16:22:42.376Z,1347898962.376 [MassServo](DEBUG): Initialization error opening port: port not yet opened
2012-09-17T16:22:42.376Z,1347898962.376 [MassServo](DEBUG): Initializing MassServo.
2012-09-17T16:22:43.839Z,1347898963.839 [PAR_Licor](ERROR): PAR reading out of range: -0.044506 uMol/s/m2
2012-09-17T16:22:46.239Z,1347898966.239 [PAR_Licor](ERROR): PAR reading out of range: -0.028611 uMol/s/m2
2012-09-17T16:22:46.270Z,1347898966.270 [MassServo](FAULT): Overload Error
2012-09-17T16:22:46.270Z,1347898966.270 [MassServo] Hardware Fault, FailCount= 5
2012-09-17T16:22:46.271Z,1347898966.270 [MassServo](ERROR): Hardware Fault
2012-09-17T16:22:46.369Z,1347898966.369 [CBIT](ERROR): Hardware Fault in component: MassServo
2012-09-17T16:22:46.370Z,1347898966.370 [CBIT](CRITICAL): Hardware Fault in component: MassServo
2012-09-17T16:22:46.651Z,1347898966.651 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-17T16:22:46.651Z,1347898966.651 [MassServo](INFO): Powering down
2012-09-17T16:22:48.646Z,1347898968.646 [PAR_Licor](ERROR): PAR reading out of range: -0.001589 uMol/s/m2
2012-09-17T16:22:49.505Z,1347898969.505 [SBIT](FAULT): Mass: EXPECTED:0.004800 ACTUAL:-0.001040
2012-09-17T16:22:49.505Z,1347898969.505 [SBIT](FAULT): Rudder: EXPECTED:15.000000 ACTUAL:14.901049
2012-09-17T16:22:52.246Z,1347898972.246 [PAR_Licor](ERROR): PAR reading out of range: -0.179613 uMol/s/m2
2012-09-17T16:22:55.758Z,1347898975.759 [CommandLine](IMPORTANT): got command quit
2012-09-17T16:22:56.850Z,1347898976.850 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-09-17T16:22:56.850Z,1347898976.850 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-09-17T16:22:57.045Z,1347898977.046 [PAR_Licor](ERROR): PAR reading out of range: -0.019074 uMol/s/m2
2012-09-17T16:22:57.178Z,1347898977.178 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2012-09-17T16:22:57.310Z,1347898977.310 [WetLabsBB2FL](INFO): Powering down
2012-09-17T16:22:57.318Z,1347898977.318 [ComponentRegistry](INFO): Shutting down Turbulence_NPS ThreadHandler
2012-09-17T16:22:57.399Z,1347898977.399 [Turbulence_NPS](INFO): Powering down
2012-09-17T16:22:57.419Z,1347898977.419 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-09-17T16:22:57.423Z,1347898977.423 [CTD_NeilBrown](INFO): Powering down
2012-09-17T16:22:57.424Z,1347898977.424 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2012-09-17T16:22:57.683Z,1347898977.682 [DVL_micro](INFO): uninitialize:Powering down
2012-09-17T16:22:57.695Z,1347898977.695 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-09-17T16:22:57.827Z,1347898977.827 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-09-17T16:22:57.843Z,1347898977.843 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-09-17T16:22:57.855Z,1347898977.855 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-09-17T16:22:57.883Z,1347898977.883 [controlThread](DEBUG): Uninitializing ControlThread
2012-09-17T16:22:57.884Z,1347898977.884 [AHRS_sp3003D](INFO): Powering down
2012-09-17T16:22:57.971Z,1347898977.971 [NAL9602](INFO): Powering down
2012-09-17T16:22:57.973Z,1347898977.973 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-17T16:22:57.973Z,1347898977.973 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-09-17T16:22:57.979Z,1347898977.979 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-09-17T16:22:57.979Z,1347898977.980 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-09-17T16:22:57.980Z,1347898977.980 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-09-17T16:22:57.980Z,1347898977.980 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-09-17T16:22:57.980Z,1347898977.980 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-09-17T16:22:57.980Z,1347898977.980 [BuoyancyServo](INFO): Powering down
2012-09-17T16:22:57.982Z,1347898977.981 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-17T16:22:57.982Z,1347898977.982 [MassServo](INFO): Powering down
2012-09-17T16:22:57.983Z,1347898977.983 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-09-17T16:22:57.983Z,1347898977.983 [RudderServo](INFO): Powering down
2012-09-17T16:22:57.984Z,1347898977.984 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-09-17T16:22:57.984Z,1347898977.984 [ThrusterServo](INFO): Powering down
2012-09-17T16:22:57.984Z,1347898977.984 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-09-17T16:22:57.985Z,1347898977.985 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-09-17T16:22:57.985Z,1347898977.985 [CBIT](DEBUG): Uninitialize CBIT Component.