2012-09-24T15:12:57.455Z,1348499577.455 [Supervisor](DEBUG): Initializing supervisor.
2012-09-24T15:12:57.458Z,1348499577.458 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-09-24T15:12:57.459Z,1348499577.459 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-09-24T15:12:57.460Z,1348499577.460 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-09-24T15:12:57.465Z,1348499577.465 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-09-24T15:12:57.476Z,1348499577.476 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-09-24T15:12:57.477Z,1348499577.477 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-09-24T15:12:57.478Z,1348499577.478 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-09-24T15:12:57.478Z,1348499577.478 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-09-24T15:12:57.479Z,1348499577.480 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-09-24T15:12:57.761Z,1348499577.761 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-09-24T15:12:57.762Z,1348499577.762 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-09-24T15:12:57.951Z,1348499577.951 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-09-24T15:12:57.951Z,1348499577.951 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-09-24T15:12:58.036Z,1348499578.036 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-09-24T15:12:58.036Z,1348499578.036 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-09-24T15:12:58.229Z,1348499578.230 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-09-24T15:12:58.230Z,1348499578.230 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-09-24T15:12:58.361Z,1348499578.362 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-09-24T15:12:58.362Z,1348499578.362 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-09-24T15:12:58.594Z,1348499578.594 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-09-24T15:12:58.594Z,1348499578.594 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-09-24T15:12:58.762Z,1348499578.762 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-09-24T15:12:58.763Z,1348499578.763 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-09-24T15:12:59.015Z,1348499579.015 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-09-24T15:12:59.015Z,1348499579.016 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-09-24T15:12:59.113Z,1348499579.113 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-09-24T15:12:59.113Z,1348499579.113 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-09-24T15:12:59.525Z,1348499579.525 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-09-24T15:12:59.526Z,1348499579.526 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-09-24T15:12:59.640Z,1348499579.640 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-09-24T15:12:59.640Z,1348499579.640 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-09-24T15:12:59.724Z,1348499579.724 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-09-24T15:12:59.725Z,1348499579.725 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-09-24T15:12:59.825Z,1348499579.825 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-09-24T15:12:59.951Z,1348499579.951 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-09-24T15:13:00.035Z,1348499580.035 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-09-24T15:13:00.136Z,1348499580.136 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-09-24T15:13:00.235Z,1348499580.235 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-09-24T15:13:00.352Z,1348499580.352 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-09-24T15:13:00.441Z,1348499580.441 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-09-24T15:13:00.533Z,1348499580.533 [Supervisor](FAULT): Ignoring configuration overrides from Data/config.db
2012-09-24T15:13:00.562Z,1348499580.562 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-09-24T15:13:00.700Z,1348499580.700 [InternalSim] Loaded
2012-09-24T15:13:00.700Z,1348499580.700 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-09-24T15:13:00.701Z,1348499580.701 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-09-24T15:13:00.702Z,1348499580.702 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-09-24T15:13:00.759Z,1348499580.759 [SBIT](DEBUG): Construct Startup Built In Test.
2012-09-24T15:13:00.772Z,1348499580.772 [SBIT] Loaded
2012-09-24T15:13:00.772Z,1348499580.772 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-09-24T15:13:00.773Z,1348499580.773 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-09-24T15:13:00.801Z,1348499580.801 [IBIT] Loaded
2012-09-24T15:13:00.801Z,1348499580.801 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-09-24T15:13:00.804Z,1348499580.804 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-09-24T15:13:00.917Z,1348499580.917 [CBIT] Loaded
2012-09-24T15:13:00.917Z,1348499580.917 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-09-24T15:13:00.918Z,1348499580.918 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-09-24T15:13:00.918Z,1348499580.918 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-09-24T15:13:01.060Z,1348499581.060 [BuoyancyServo] Loaded
2012-09-24T15:13:01.061Z,1348499581.061 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-09-24T15:13:01.070Z,1348499581.070 [ElevatorServo] Loaded
2012-09-24T15:13:01.071Z,1348499581.070 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-09-24T15:13:01.082Z,1348499581.082 [MassServo] Loaded
2012-09-24T15:13:01.082Z,1348499581.082 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-09-24T15:13:01.094Z,1348499581.093 [RudderServo] Loaded
2012-09-24T15:13:01.094Z,1348499581.094 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-09-24T15:13:01.105Z,1348499581.105 [ThrusterServo] Loaded
2012-09-24T15:13:01.105Z,1348499581.105 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-09-24T15:13:01.106Z,1348499581.106 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-09-24T15:13:01.106Z,1348499581.106 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-09-24T15:13:01.125Z,1348499581.125 [DepthRateCalculator] Loaded
2012-09-24T15:13:01.125Z,1348499581.125 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-09-24T15:13:03.581Z,1348499583.581 [HFRadarModelCalc] Loaded
2012-09-24T15:13:03.581Z,1348499583.581 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-09-24T15:13:03.597Z,1348499583.597 [NavChart] Loaded
2012-09-24T15:13:03.597Z,1348499583.597 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-09-24T15:13:03.604Z,1348499583.603 [PitchRateCalculator] Loaded
2012-09-24T15:13:03.604Z,1348499583.604 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-09-24T15:13:03.610Z,1348499583.610 [SpeedCalculator] Loaded
2012-09-24T15:13:03.610Z,1348499583.610 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-09-24T15:13:03.625Z,1348499583.625 [TempGradientCalculator] Loaded
2012-09-24T15:13:03.625Z,1348499583.625 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-09-24T15:13:03.631Z,1348499583.631 [YawRateCalculator] Loaded
2012-09-24T15:13:03.631Z,1348499583.631 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-09-24T15:13:03.650Z,1348499583.651 [Navigation] Loaded
2012-09-24T15:13:03.651Z,1348499583.651 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-09-24T15:13:03.651Z,1348499583.651 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-09-24T15:13:03.652Z,1348499583.652 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-09-24T15:13:03.871Z,1348499583.871 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-09-24T15:13:03.872Z,1348499583.872 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-09-24T15:13:03.895Z,1348499583.895 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-09-24T15:13:03.895Z,1348499583.895 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-09-24T15:13:03.935Z,1348499583.935 [VerticalControl](DEBUG): Construct VerticalControl.
2012-09-24T15:13:03.979Z,1348499583.979 [VerticalControl] Loaded
2012-09-24T15:13:03.979Z,1348499583.979 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-09-24T15:13:03.980Z,1348499583.980 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-09-24T15:13:04.001Z,1348499584.000 [HorizontalControl] Loaded
2012-09-24T15:13:04.001Z,1348499584.001 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-09-24T15:13:04.002Z,1348499584.002 [SpeedControl](DEBUG): Construct SpeedControl.
2012-09-24T15:13:04.004Z,1348499584.004 [SpeedControl] Loaded
2012-09-24T15:13:04.004Z,1348499584.004 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-09-24T15:13:04.005Z,1348499584.005 [LoopControl](DEBUG): Construct LoopControl.
2012-09-24T15:13:04.005Z,1348499584.005 [LoopControl] Loaded
2012-09-24T15:13:04.006Z,1348499584.006 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-09-24T15:13:04.006Z,1348499584.006 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-09-24T15:13:04.007Z,1348499584.007 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-09-24T15:13:04.012Z,1348499584.012 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-09-24T15:13:04.017Z,1348499584.017 [AsyncPiEstimator] Loaded
2012-09-24T15:13:04.017Z,1348499584.017 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-09-24T15:13:04.018Z,1348499584.018 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4060A4E0
2012-09-24T15:13:04.019Z,1348499584.019 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-09-24T15:13:04.020Z,1348499584.020 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-09-24T15:13:04.142Z,1348499584.142 [AHRS_sp3003D] Loaded
2012-09-24T15:13:04.142Z,1348499584.142 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-09-24T15:13:04.156Z,1348499584.156 [Depth_Keller] Loaded
2012-09-24T15:13:04.156Z,1348499584.156 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-09-24T15:13:04.161Z,1348499584.161 [DropWeight] Loaded
2012-09-24T15:13:04.162Z,1348499584.162 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-09-24T15:13:04.274Z,1348499584.274 [DVL_micro] Loaded
2012-09-24T15:13:04.275Z,1348499584.274 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-09-24T15:13:04.276Z,1348499584.276 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4068A4E0
2012-09-24T15:13:04.355Z,1348499584.355 [NAL9602] Loaded
2012-09-24T15:13:04.355Z,1348499584.355 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-09-24T15:13:04.403Z,1348499584.402 [Onboard] Loaded
2012-09-24T15:13:04.403Z,1348499584.403 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-09-24T15:13:04.410Z,1348499584.409 [Radio_Freewave] Loaded
2012-09-24T15:13:04.410Z,1348499584.410 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-09-24T15:13:04.411Z,1348499584.411 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-09-24T15:13:04.411Z,1348499584.411 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-09-24T15:13:04.483Z,1348499584.483 [CTD_NeilBrown] Loaded
2012-09-24T15:13:04.483Z,1348499584.483 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-09-24T15:13:04.484Z,1348499584.484 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E24E0
2012-09-24T15:13:04.509Z,1348499584.509 [PAR_Licor] Loaded
2012-09-24T15:13:04.510Z,1348499584.510 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-09-24T15:13:04.548Z,1348499584.548 [Turbulence_NPS] Loaded
2012-09-24T15:13:04.548Z,1348499584.548 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-09-24T15:13:04.558Z,1348499584.558 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407124E0
2012-09-24T15:13:04.625Z,1348499584.625 [WetLabsBB2FL] Loaded
2012-09-24T15:13:04.625Z,1348499584.625 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-09-24T15:13:04.634Z,1348499584.634 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407424E0
2012-09-24T15:13:04.635Z,1348499584.635 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-09-24T15:13:04.637Z,1348499584.638 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-09-24T15:13:04.639Z,1348499584.639 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-09-24T15:13:04.645Z,1348499584.645 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-09-24T15:13:04.651Z,1348499584.651 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407724E0
2012-09-24T15:13:04.655Z,1348499584.655 [Supervisor](DEBUG): Running supervisor.
2012-09-24T15:13:04.663Z,1348499584.663 [CommandLine](INFO): Thread ID is 1199
2012-09-24T15:13:04.665Z,1348499584.665 [controlThread](INFO): Thread ID is 1198
2012-09-24T15:13:04.665Z,1348499584.665 [controlThread](DEBUG): Initializing ControlThread
2012-09-24T15:13:04.666Z,1348499584.666 [CycleStarter](INFO): Thread ID is 1197
2012-09-24T15:13:04.666Z,1348499584.667 [InternalSim](DEBUG):  InternalSim initializing...
2012-09-24T15:13:04.707Z,1348499584.707 [AsyncPiEstimator](INFO): Thread ID is 1260
2012-09-24T15:13:04.707Z,1348499584.707 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-09-24T15:13:04.728Z,1348499584.728 [DVL_micro](INFO): Thread ID is 1261
2012-09-24T15:13:04.738Z,1348499584.738 [DVL_micro](INFO): Initializing
2012-09-24T15:13:04.738Z,1348499584.738 [DVL_micro](INFO): start:Powering up
2012-09-24T15:13:04.739Z,1348499584.739 [DVL_micro](INFO): Opening uart, block timeout 10ths=1
2012-09-24T15:13:04.760Z,1348499584.760 [SBIT](INFO): Initialize SBIT Component.
2012-09-24T15:13:04.760Z,1348499584.760 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9883
2012-09-24T15:13:04.761Z,1348499584.761 [IBIT](INFO): Initialize IBIT Component.
2012-09-24T15:13:04.762Z,1348499584.761 [CBIT](DEBUG): Initialize CBIT Component.
2012-09-24T15:13:04.762Z,1348499584.762 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2012-09-24T15:13:04.762Z,1348499584.762 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2012-09-24T15:13:04.767Z,1348499584.767 [CTD_NeilBrown](INFO): Thread ID is 1262
2012-09-24T15:13:04.768Z,1348499584.768 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-09-24T15:13:04.775Z,1348499584.775 [Turbulence_NPS](INFO): Thread ID is 1264
2012-09-24T15:13:04.776Z,1348499584.776 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-09-24T15:13:04.781Z,1348499584.781 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=1
2012-09-24T15:13:04.795Z,1348499584.795 [WetLabsBB2FL](INFO): Thread ID is 1265
2012-09-24T15:13:04.796Z,1348499584.796 [WetLabsBB2FL](INFO): Powering down
2012-09-24T15:13:04.804Z,1348499584.804 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-24T15:13:04.804Z,1348499584.805 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-09-24T15:13:04.805Z,1348499584.805 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-09-24T15:13:04.805Z,1348499584.805 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-09-24T15:13:04.805Z,1348499584.806 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-09-24T15:13:04.807Z,1348499584.807 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-09-24T15:13:04.808Z,1348499584.808 [Navigation](DEBUG): Initializing Navigation.
2012-09-24T15:13:04.808Z,1348499584.808 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-09-24T15:13:04.810Z,1348499584.810 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-09-24T15:13:04.816Z,1348499584.816 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-09-24T15:13:04.816Z,1348499584.816 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-09-24T15:13:04.854Z,1348499584.854 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-09-24T15:13:04.864Z,1348499584.864 [NavChartDb](INFO): Thread ID is 1266
2012-09-24T15:13:04.957Z,1348499584.957 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-24T15:13:04.981Z,1348499584.981 [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-24T15:13:04.982Z,1348499584.981 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-09-24T15:13:05.031Z,1348499585.031 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-09-24T15:13:05.034Z,1348499585.034 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-09-24T15:13:05.037Z,1348499585.037 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-24T15:13:05.045Z,1348499585.045 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-09-24T15:13:05.056Z,1348499585.056 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-24T15:13:05.063Z,1348499585.063 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-09-24T15:13:05.080Z,1348499585.080 [Default:D.SetSpeed](DEBUG): Construct.
2012-09-24T15:13:05.083Z,1348499585.083 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-24T15:13:05.088Z,1348499585.088 [Default:F.Wait](DEBUG): Construct Wait.
2012-09-24T15:13:05.100Z,1348499585.100 [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-24T15:13:05.104Z,1348499585.104 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-09-24T15:13:05.133Z,1348499585.133 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-24T15:13:05.342Z,1348499585.342 [Radio_Freewave](INFO): Powering up
2012-09-24T15:13:05.955Z,1348499585.955 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-09-24T15:13:05.963Z,1348499585.963 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-09-24T15:13:05.969Z,1348499585.969 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-09-24T15:13:05.987Z,1348499585.987 [MassServo](DEBUG): Initializing MassServo.
2012-09-24T15:13:05.992Z,1348499585.992 [RudderServo](DEBUG): Initializing EZServoServo.
2012-09-24T15:13:05.999Z,1348499585.999 [RudderServo](DEBUG): Initializing RudderServo.
2012-09-24T15:13:06.005Z,1348499586.005 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-09-24T15:13:06.011Z,1348499586.011 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-09-24T15:13:06.330Z,1348499586.330 [DVL_micro](INFO): Querying output modes
2012-09-24T15:13:06.331Z,1348499586.331 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-24T15:13:06.335Z,1348499586.335 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-09-24T15:13:06.335Z,1348499586.335 [DVL_micro](INFO): NQ1 output enabled
2012-09-24T15:13:06.335Z,1348499586.335 [DVL_micro](INFO): RSSI output enabled
2012-09-24T15:13:06.335Z,1348499586.335 [DVL_micro](INFO): ADCP output enabled
2012-09-24T15:13:06.335Z,1348499586.335 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-24T15:13:06.336Z,1348499586.336 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:06.386Z,1348499586.386 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:06.438Z,1348499586.438 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:06.826Z,1348499586.826 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:06.878Z,1348499586.878 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:07.370Z,1348499587.370 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:07.799Z,1348499587.799 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:07.852Z,1348499587.852 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:07.906Z,1348499587.907 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:07.959Z,1348499587.958 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.010Z,1348499588.010 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.046Z,1348499588.046 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-09-24T15:13:08.051Z,1348499588.051 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-09-24T15:13:08.055Z,1348499588.055 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-09-24T15:13:08.059Z,1348499588.059 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-09-24T15:13:08.062Z,1348499588.062 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.064Z,1348499588.063 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-09-24T15:13:08.064Z,1348499588.064 [NavChartDb](INFO): Creating index for Soundings
2012-09-24T15:13:08.067Z,1348499588.067 [NavChartDb](INFO): Creating index for Contour 0p0
2012-09-24T15:13:08.069Z,1348499588.069 [NavChartDb](INFO): Creating index for Contour 1p8
2012-09-24T15:13:08.071Z,1348499588.071 [NavChartDb](INFO): Creating index for Contour 3p6
2012-09-24T15:13:08.073Z,1348499588.073 [NavChartDb](INFO): Creating index for Contour 5p4
2012-09-24T15:13:08.075Z,1348499588.075 [NavChartDb](INFO): Creating index for Contour 9p1
2012-09-24T15:13:08.077Z,1348499588.077 [NavChartDb](INFO): Creating index for Contour 10p9
2012-09-24T15:13:08.079Z,1348499588.079 [NavChartDb](INFO): Creating index for Contour 18p2
2012-09-24T15:13:08.081Z,1348499588.081 [NavChartDb](INFO): Creating index for Contour 36p5
2012-09-24T15:13:08.083Z,1348499588.082 [NavChartDb](INFO): Creating index for Contour 54p8
2012-09-24T15:13:08.084Z,1348499588.084 [NavChartDb](INFO): Creating index for Contour 73p1
2012-09-24T15:13:08.086Z,1348499588.086 [NavChartDb](INFO): Creating index for Contour 91p4
2012-09-24T15:13:08.088Z,1348499588.088 [NavChartDb](INFO): Creating index for Contour 182p8
2012-09-24T15:13:08.091Z,1348499588.091 [NavChartDb](INFO): Creating index for Contour 365p7
2012-09-24T15:13:08.093Z,1348499588.093 [NavChartDb](INFO): Creating index for Contour 548p6
2012-09-24T15:13:08.095Z,1348499588.095 [NavChartDb](INFO): Creating index for Contour 731p5
2012-09-24T15:13:08.097Z,1348499588.096 [NavChartDb](INFO): Creating index for Contour 914p4
2012-09-24T15:13:08.098Z,1348499588.098 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-09-24T15:13:08.100Z,1348499588.100 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-09-24T15:13:08.102Z,1348499588.102 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-09-24T15:13:08.104Z,1348499588.104 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-09-24T15:13:08.106Z,1348499588.106 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-09-24T15:13:08.108Z,1348499588.108 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-09-24T15:13:08.110Z,1348499588.110 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-09-24T15:13:08.112Z,1348499588.112 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-09-24T15:13:08.113Z,1348499588.114 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-09-24T15:13:08.115Z,1348499588.115 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.116Z,1348499588.116 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-09-24T15:13:08.118Z,1348499588.118 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-09-24T15:13:08.120Z,1348499588.120 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-09-24T15:13:08.122Z,1348499588.122 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-09-24T15:13:08.127Z,1348499588.127 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-09-24T15:13:08.129Z,1348499588.129 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-09-24T15:13:08.167Z,1348499588.167 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.219Z,1348499588.218 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.270Z,1348499588.270 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.322Z,1348499588.322 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.377Z,1348499588.377 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.430Z,1348499588.430 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.482Z,1348499588.482 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.534Z,1348499588.534 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.586Z,1348499588.586 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.638Z,1348499588.638 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.691Z,1348499588.691 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.743Z,1348499588.743 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.794Z,1348499588.794 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.846Z,1348499588.846 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.898Z,1348499588.898 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:08.950Z,1348499588.950 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.002Z,1348499589.002 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.054Z,1348499589.054 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.106Z,1348499589.106 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.161Z,1348499589.161 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.214Z,1348499589.214 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.266Z,1348499589.266 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.318Z,1348499589.318 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.370Z,1348499589.370 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.422Z,1348499589.422 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.474Z,1348499589.474 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.526Z,1348499589.526 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.578Z,1348499589.578 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.579Z,1348499589.579 [NAL9602](INFO): Powering up NAL9602
2012-09-24T15:13:09.630Z,1348499589.630 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.682Z,1348499589.682 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.734Z,1348499589.734 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.786Z,1348499589.786 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.838Z,1348499589.838 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.890Z,1348499589.890 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.942Z,1348499589.942 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:09.994Z,1348499589.994 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.046Z,1348499590.046 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.098Z,1348499590.098 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.150Z,1348499590.150 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.202Z,1348499590.202 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.254Z,1348499590.254 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.306Z,1348499590.306 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.361Z,1348499590.361 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.414Z,1348499590.414 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.467Z,1348499590.467 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.518Z,1348499590.519 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.570Z,1348499590.570 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.622Z,1348499590.622 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.674Z,1348499590.674 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.726Z,1348499590.726 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.779Z,1348499590.779 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.830Z,1348499590.830 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.882Z,1348499590.882 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.934Z,1348499590.934 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:10.986Z,1348499590.986 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:11.038Z,1348499591.039 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:11.090Z,1348499591.091 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:11.142Z,1348499591.142 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:11.194Z,1348499591.194 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:11.246Z,1348499591.246 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:11.298Z,1348499591.298 [DVL_micro](DEBUG): cleanFlush, dataAvailable=1
2012-09-24T15:13:11.354Z,1348499591.355 [DVL_micro](DEBUG): cmdResponse: 
AUTO_VEL_ON 
2012-09-24T15:13:11.359Z,1348499591.359 [DVL_micro](INFO): pause:Powering down
2012-09-24T15:13:20.399Z,1348499600.399 [NAL9602](INFO): NAL9602 initialized
2012-09-24T15:13:20.442Z,1348499600.441 [SBIT](IMPORTANT): Beginning Startup BIT
2012-09-24T15:13:20.444Z,1348499600.444 [CBIT](IMPORTANT): Beginning GF scan
2012-09-24T15:13:33.673Z,1348499613.673 [SBIT](FAULT): Rudder: EXPECTED:15.000000 ACTUAL:14.868057
2012-09-24T15:13:46.802Z,1348499626.802 [CBIT](IMPORTANT): No ground fault detected
2012-09-24T15:14:14.403Z,1348499654.402 [SBIT](CRITICAL): SBIT FAILED
2012-09-24T15:14:14.795Z,1348499654.795 [MissionManager](IMPORTANT): Started mission Startup
2012-09-24T15:14:14.795Z,1348499654.795 [Startup] Running Loop=1
2012-09-24T15:14:14.795Z,1348499654.795 [Startup](INFO): Aggregate::initialize Startup
2012-09-24T15:14:14.795Z,1348499654.796 [Startup:A.GoToSurface] Running Loop=1
2012-09-24T15:14:14.796Z,1348499654.796 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-24T15:14:14.801Z,1348499654.801 [Startup:StartupSatComms] Running Loop=1
2012-09-24T15:14:14.801Z,1348499654.801 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-09-24T15:14:14.801Z,1348499654.801 [Startup:StartupSatComms:A] Running Loop=1
2012-09-24T15:14:15.194Z,1348499655.194 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-24T15:15:15.195Z,1348499715.195 [Startup:StartupSatComms:A](INFO): Timed out from 2012-09-24T15:14:14.8Z
2012-09-24T15:15:15.195Z,1348499715.195 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-09-24T15:15:15.195Z,1348499715.195 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-09-24T15:15:15.195Z,1348499715.195 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-09-24T15:15:15.196Z,1348499715.195 [Startup:StartupSatComms:A] Stopped
2012-09-24T15:15:15.196Z,1348499715.196 [Startup:StartupSatComms:B] Running Loop=1
2012-09-24T15:15:15.591Z,1348499715.591 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-09-24T15:16:15.350Z,1348499775.350 [Startup:StartupSatComms:B](INFO): Timed out from 2012-09-24T15:15:15.2Z
2012-09-24T15:16:15.350Z,1348499775.351 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-09-24T15:16:15.351Z,1348499775.351 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-09-24T15:16:15.351Z,1348499775.351 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-09-24T15:16:15.351Z,1348499775.351 [Startup:StartupSatComms:B] Stopped
2012-09-24T15:16:15.351Z,1348499775.351 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-09-24T15:16:15.351Z,1348499775.351 [Startup:StartupSatComms] Stopped
2012-09-24T15:16:15.351Z,1348499775.351 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-09-24T15:16:15.352Z,1348499775.352 [Startup](INFO): Completed Startup
2012-09-24T15:16:15.352Z,1348499775.352 [Startup] Stopped
2012-09-24T15:16:15.352Z,1348499775.352 [Startup](INFO): Aggregate::uninitialize Startup
2012-09-24T15:16:15.352Z,1348499775.352 [Startup:A.GoToSurface] Stopped
2012-09-24T15:16:15.352Z,1348499775.352 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-24T15:16:16.255Z,1348499776.255 [MissionManager](IMPORTANT): Started mission Default
2012-09-24T15:16:16.255Z,1348499776.255 [Default] Running Loop=1
2012-09-24T15:16:16.255Z,1348499776.255 [Default](INFO): Aggregate::initialize Default
2012-09-24T15:16:16.255Z,1348499776.256 [Default:D.SetSpeed] Running Loop=1
2012-09-24T15:16:16.256Z,1348499776.256 [Default:D.SetSpeed](DEBUG): Initialize.
2012-09-24T15:16:16.256Z,1348499776.256 [Default:E.GoToSurface] Running Loop=1
2012-09-24T15:16:16.256Z,1348499776.256 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-24T15:16:16.256Z,1348499776.256 [Default:Iridium] Running Loop=1
2012-09-24T15:16:16.256Z,1348499776.256 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-09-24T15:16:16.256Z,1348499776.256 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-24T15:16:16.257Z,1348499776.257 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-09-24T15:16:16.257Z,1348499776.257 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-09-24T15:16:16.257Z,1348499776.257 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-24T15:16:16.257Z,1348499776.257 [Default:E.GoToSurface] Running Loop=1
2012-09-24T15:16:16.262Z,1348499776.262 [Default:D.SetSpeed] Running Loop=1
2012-09-24T15:16:16.267Z,1348499776.267 [Default:CallIridium] Running Loop=1
2012-09-24T15:16:16.267Z,1348499776.267 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-09-24T15:16:16.267Z,1348499776.267 [Default:CallIridium:A] Running Loop=1
2012-09-24T15:16:16.269Z,1348499776.269 [Default:CallIridium:A] Stopped
2012-09-24T15:16:16.269Z,1348499776.269 [Default:CallIridium:B] Running Loop=1
2012-09-24T15:16:16.269Z,1348499776.269 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-09-24T15:16:16.274Z,1348499776.274 [Default:Iridium:B.GoToSurface] Stopped
2012-09-24T15:16:16.274Z,1348499776.274 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-24T15:16:16.274Z,1348499776.274 [Default:Iridium:Read_Iridium] Running Loop=1
2012-09-24T15:16:16.275Z,1348499776.274 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-09-24T15:16:16.279Z,1348499776.279 [Default:GPS] Running Loop=1
2012-09-24T15:16:16.279Z,1348499776.279 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-09-24T15:16:16.279Z,1348499776.279 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-24T15:16:16.279Z,1348499776.279 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-09-24T15:16:16.280Z,1348499776.280 [Default:GPS:B.GoToSurface] Running Loop=1
2012-09-24T15:16:16.280Z,1348499776.280 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-24T15:16:16.285Z,1348499776.285 [Default:GPS:B.GoToSurface] Stopped
2012-09-24T15:16:16.285Z,1348499776.285 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-24T15:16:16.285Z,1348499776.285 [Default:GPS:Read_GPS] Running Loop=1
2012-09-24T15:16:16.285Z,1348499776.285 [Default:GPS:A.SetSpeed] Running Loop=1
2012-09-24T15:16:16.426Z,1348499776.426 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-09-24T15:16:16.428Z,1348499776.428 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-09-24T15:16:24.367Z,1348499784.367 [CommandLine](IMPORTANT): got command quit
2012-09-24T15:16:25.526Z,1348499785.526 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-09-24T15:16:25.526Z,1348499785.526 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-09-24T15:16:25.686Z,1348499785.686 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2012-09-24T15:16:26.087Z,1348499786.087 [WetLabsBB2FL](INFO): Powering down
2012-09-24T15:16:26.090Z,1348499786.090 [ComponentRegistry](INFO): Shutting down Turbulence_NPS ThreadHandler
2012-09-24T15:16:26.490Z,1348499786.490 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-09-24T15:16:26.555Z,1348499786.555 [CTD_NeilBrown](INFO): Powering down
2012-09-24T15:16:26.570Z,1348499786.570 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2012-09-24T15:16:26.903Z,1348499786.903 [DVL_micro](INFO): uninitialize:Powering down
2012-09-24T15:16:26.915Z,1348499786.915 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-09-24T15:16:27.043Z,1348499787.043 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-09-24T15:16:27.055Z,1348499787.055 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-09-24T15:16:27.056Z,1348499787.056 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-09-24T15:16:27.135Z,1348499787.135 [controlThread](DEBUG): Uninitializing ControlThread
2012-09-24T15:16:27.135Z,1348499787.135 [AHRS_sp3003D](INFO): Powering down
2012-09-24T15:16:27.223Z,1348499787.223 [NAL9602](INFO): Powering down
2012-09-24T15:16:27.225Z,1348499787.225 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-24T15:16:27.225Z,1348499787.225 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-09-24T15:16:27.227Z,1348499787.227 [Default] Stopped
2012-09-24T15:16:27.227Z,1348499787.227 [Default](INFO): Aggregate::uninitialize Default
2012-09-24T15:16:27.227Z,1348499787.227 [Default:GPS] Stopped
2012-09-24T15:16:27.227Z,1348499787.227 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-09-24T15:16:27.227Z,1348499787.227 [Default:GPS:A.SetSpeed] Stopped
2012-09-24T15:16:27.227Z,1348499787.227 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-09-24T15:16:27.227Z,1348499787.227 [Default:GPS:Read_GPS] Stopped
2012-09-24T15:16:27.227Z,1348499787.227 [Default:Iridium] Stopped
2012-09-24T15:16:27.227Z,1348499787.227 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-09-24T15:16:27.227Z,1348499787.227 [Default:Iridium:A.SetSpeed] Stopped
2012-09-24T15:16:27.228Z,1348499787.227 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-09-24T15:16:27.228Z,1348499787.228 [Default:Iridium:Read_Iridium] Stopped
2012-09-24T15:16:27.228Z,1348499787.228 [Default:CallIridium] Stopped
2012-09-24T15:16:27.228Z,1348499787.228 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-09-24T15:16:27.228Z,1348499787.228 [Default:CallIridium:B] Stopped
2012-09-24T15:16:27.228Z,1348499787.228 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-09-24T15:16:27.228Z,1348499787.228 [Default:D.SetSpeed] Stopped
2012-09-24T15:16:27.228Z,1348499787.228 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-09-24T15:16:27.228Z,1348499787.228 [Default:E.GoToSurface] Stopped
2012-09-24T15:16:27.228Z,1348499787.228 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-09-24T15:16:27.233Z,1348499787.233 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-09-24T15:16:27.233Z,1348499787.233 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-09-24T15:16:27.233Z,1348499787.233 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-09-24T15:16:27.234Z,1348499787.234 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-09-24T15:16:27.234Z,1348499787.234 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-09-24T15:16:27.234Z,1348499787.234 [BuoyancyServo](INFO): Powering down
2012-09-24T15:16:27.235Z,1348499787.235 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-09-24T15:16:27.235Z,1348499787.236 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-09-24T15:16:27.236Z,1348499787.236 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-09-24T15:16:27.236Z,1348499787.236 [RudderServo](INFO): Powering down
2012-09-24T15:16:27.237Z,1348499787.237 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-09-24T15:16:27.237Z,1348499787.237 [ThrusterServo](INFO): Powering down
2012-09-24T15:16:27.238Z,1348499787.238 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-09-24T15:16:27.238Z,1348499787.238 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-09-24T15:16:27.238Z,1348499787.238 [CBIT](DEBUG): Uninitialize CBIT Component.