2012-09-20T23:27:20.268Z,1348183640.268 [Supervisor](DEBUG): Initializing supervisor.
2012-09-20T23:27:20.274Z,1348183640.274 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-09-20T23:27:20.275Z,1348183640.275 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-09-20T23:27:20.278Z,1348183640.278 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-09-20T23:27:20.282Z,1348183640.282 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-09-20T23:27:20.292Z,1348183640.292 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-09-20T23:27:20.294Z,1348183640.294 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-09-20T23:27:20.295Z,1348183640.295 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-09-20T23:27:20.296Z,1348183640.296 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-09-20T23:27:20.298Z,1348183640.298 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-09-20T23:27:20.605Z,1348183640.605 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-09-20T23:27:20.608Z,1348183640.608 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-09-20T23:27:20.803Z,1348183640.803 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-09-20T23:27:20.803Z,1348183640.803 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-09-20T23:27:20.897Z,1348183640.898 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-09-20T23:27:20.900Z,1348183640.900 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-09-20T23:27:21.119Z,1348183641.119 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-09-20T23:27:21.119Z,1348183641.119 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-09-20T23:27:21.267Z,1348183641.267 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-09-20T23:27:21.269Z,1348183641.269 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-09-20T23:27:21.522Z,1348183641.522 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-09-20T23:27:21.522Z,1348183641.522 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-09-20T23:27:21.711Z,1348183641.711 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-09-20T23:27:21.713Z,1348183641.713 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-09-20T23:27:22.060Z,1348183642.060 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-09-20T23:27:22.062Z,1348183642.062 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-09-20T23:27:22.216Z,1348183642.216 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-09-20T23:27:22.217Z,1348183642.217 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-09-20T23:27:22.985Z,1348183642.985 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-09-20T23:27:22.986Z,1348183642.986 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-09-20T23:27:23.202Z,1348183643.202 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-09-20T23:27:23.203Z,1348183643.203 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-09-20T23:27:23.362Z,1348183643.362 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-09-20T23:27:23.387Z,1348183643.387 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-09-20T23:27:23.564Z,1348183643.564 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-09-20T23:27:23.810Z,1348183643.810 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-09-20T23:27:23.979Z,1348183643.979 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-09-20T23:27:24.150Z,1348183644.150 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-09-20T23:27:24.286Z,1348183644.286 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-09-20T23:27:24.578Z,1348183644.578 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-09-20T23:27:24.724Z,1348183644.724 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-09-20T23:27:24.922Z,1348183644.922 [Supervisor](FAULT): Ignoring configuration overrides from Data/config.db
2012-09-20T23:27:24.971Z,1348183644.971 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-09-20T23:27:25.163Z,1348183645.163 [InternalSim] Loaded
2012-09-20T23:27:25.163Z,1348183645.164 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-09-20T23:27:25.164Z,1348183645.164 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-09-20T23:27:25.165Z,1348183645.165 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-09-20T23:27:25.247Z,1348183645.247 [SBIT](DEBUG): Construct Startup Built In Test.
2012-09-20T23:27:25.264Z,1348183645.264 [SBIT] Loaded
2012-09-20T23:27:25.264Z,1348183645.264 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-09-20T23:27:25.265Z,1348183645.265 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-09-20T23:27:25.291Z,1348183645.291 [IBIT] Loaded
2012-09-20T23:27:25.292Z,1348183645.292 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-09-20T23:27:25.295Z,1348183645.295 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-09-20T23:27:25.422Z,1348183645.422 [CBIT] Loaded
2012-09-20T23:27:25.422Z,1348183645.422 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-09-20T23:27:25.423Z,1348183645.423 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-09-20T23:27:25.424Z,1348183645.424 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-09-20T23:27:25.588Z,1348183645.588 [BuoyancyServo] Loaded
2012-09-20T23:27:25.589Z,1348183645.589 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-09-20T23:27:25.601Z,1348183645.601 [RudderServo] Loaded
2012-09-20T23:27:25.601Z,1348183645.602 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-09-20T23:27:25.613Z,1348183645.612 [ThrusterServo] Loaded
2012-09-20T23:27:25.613Z,1348183645.613 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-09-20T23:27:25.613Z,1348183645.613 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-09-20T23:27:25.614Z,1348183645.614 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-09-20T23:27:25.647Z,1348183645.647 [DepthRateCalculator] Loaded
2012-09-20T23:27:25.647Z,1348183645.647 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-09-20T23:27:28.346Z,1348183648.346 [HFRadarModelCalc] Loaded
2012-09-20T23:27:28.346Z,1348183648.346 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-09-20T23:27:28.361Z,1348183648.361 [NavChart] Loaded
2012-09-20T23:27:28.361Z,1348183648.362 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-09-20T23:27:28.367Z,1348183648.367 [PitchRateCalculator] Loaded
2012-09-20T23:27:28.367Z,1348183648.367 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-09-20T23:27:28.373Z,1348183648.373 [SpeedCalculator] Loaded
2012-09-20T23:27:28.374Z,1348183648.374 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-09-20T23:27:28.392Z,1348183648.392 [TempGradientCalculator] Loaded
2012-09-20T23:27:28.392Z,1348183648.392 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-09-20T23:27:28.398Z,1348183648.398 [YawRateCalculator] Loaded
2012-09-20T23:27:28.398Z,1348183648.398 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-09-20T23:27:28.417Z,1348183648.417 [Navigation] Loaded
2012-09-20T23:27:28.417Z,1348183648.417 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-09-20T23:27:28.418Z,1348183648.418 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-09-20T23:27:28.423Z,1348183648.423 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-09-20T23:27:28.700Z,1348183648.700 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-09-20T23:27:28.701Z,1348183648.701 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-09-20T23:27:28.742Z,1348183648.742 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-09-20T23:27:28.742Z,1348183648.742 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-09-20T23:27:28.803Z,1348183648.803 [VerticalControl](DEBUG): Construct VerticalControl.
2012-09-20T23:27:28.851Z,1348183648.851 [VerticalControl] Loaded
2012-09-20T23:27:28.851Z,1348183648.851 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-09-20T23:27:28.852Z,1348183648.852 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-09-20T23:27:28.872Z,1348183648.872 [HorizontalControl] Loaded
2012-09-20T23:27:28.872Z,1348183648.872 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-09-20T23:27:28.873Z,1348183648.873 [SpeedControl](DEBUG): Construct SpeedControl.
2012-09-20T23:27:28.875Z,1348183648.875 [SpeedControl] Loaded
2012-09-20T23:27:28.875Z,1348183648.875 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-09-20T23:27:28.876Z,1348183648.876 [LoopControl](DEBUG): Construct LoopControl.
2012-09-20T23:27:28.877Z,1348183648.877 [LoopControl] Loaded
2012-09-20T23:27:28.877Z,1348183648.877 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-09-20T23:27:28.877Z,1348183648.877 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-09-20T23:27:28.878Z,1348183648.878 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-09-20T23:27:28.891Z,1348183648.891 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-09-20T23:27:28.895Z,1348183648.895 [AsyncPiEstimator] Loaded
2012-09-20T23:27:28.895Z,1348183648.895 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-09-20T23:27:28.897Z,1348183648.897 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4060A4E0
2012-09-20T23:27:28.897Z,1348183648.898 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-09-20T23:27:28.898Z,1348183648.898 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-09-20T23:27:29.629Z,1348183649.629 [AHRS_sp3003D] Loaded
2012-09-20T23:27:29.629Z,1348183649.629 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-09-20T23:27:29.642Z,1348183649.642 [Depth_Keller] Loaded
2012-09-20T23:27:29.642Z,1348183649.642 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-09-20T23:27:29.647Z,1348183649.647 [DropWeight] Loaded
2012-09-20T23:27:29.647Z,1348183649.648 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-09-20T23:27:29.770Z,1348183649.770 [DVL_micro] Loaded
2012-09-20T23:27:29.770Z,1348183649.770 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-09-20T23:27:29.774Z,1348183649.774 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4068A4E0
2012-09-20T23:27:29.860Z,1348183649.860 [NAL9602] Loaded
2012-09-20T23:27:29.860Z,1348183649.861 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-09-20T23:27:29.913Z,1348183649.912 [Onboard] Loaded
2012-09-20T23:27:29.913Z,1348183649.913 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-09-20T23:27:29.919Z,1348183649.919 [Radio_Freewave] Loaded
2012-09-20T23:27:29.919Z,1348183649.920 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-09-20T23:27:29.920Z,1348183649.920 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-09-20T23:27:29.921Z,1348183649.921 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-09-20T23:27:30.022Z,1348183650.022 [CTD_NeilBrown] Loaded
2012-09-20T23:27:30.022Z,1348183650.022 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-09-20T23:27:30.026Z,1348183650.026 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 406E24E0
2012-09-20T23:27:30.036Z,1348183650.036 [PAR_Licor] Loaded
2012-09-20T23:27:30.037Z,1348183650.037 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-09-20T23:27:30.057Z,1348183650.057 [Turbulence_NPS] Loaded
2012-09-20T23:27:30.058Z,1348183650.057 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-09-20T23:27:30.062Z,1348183650.062 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407124E0
2012-09-20T23:27:30.096Z,1348183650.096 [WetLabsBB2FL] Loaded
2012-09-20T23:27:30.096Z,1348183650.096 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-09-20T23:27:30.098Z,1348183650.098 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407424E0
2012-09-20T23:27:30.098Z,1348183650.098 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-09-20T23:27:30.101Z,1348183650.101 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-09-20T23:27:30.101Z,1348183650.101 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-09-20T23:27:30.107Z,1348183650.107 [NavChartDb](CRITICAL): No configuration setting for: NavChartDb.cycleTimeout
2012-09-20T23:27:30.108Z,1348183650.108 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-09-20T23:27:30.110Z,1348183650.110 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407724E0
2012-09-20T23:27:30.114Z,1348183650.114 [Supervisor](DEBUG): Running supervisor.
2012-09-20T23:27:30.115Z,1348183650.115 [CommandLine](INFO): Thread ID is 749
2012-09-20T23:27:30.119Z,1348183650.119 [controlThread](INFO): Thread ID is 748
2012-09-20T23:27:30.119Z,1348183650.119 [controlThread](DEBUG): Initializing ControlThread
2012-09-20T23:27:30.119Z,1348183650.119 [CycleStarter](INFO): Thread ID is 747
2012-09-20T23:27:30.120Z,1348183650.120 [InternalSim](DEBUG):  InternalSim initializing...
2012-09-20T23:27:30.240Z,1348183650.240 [AsyncPiEstimator](INFO): Thread ID is 815
2012-09-20T23:27:30.240Z,1348183650.240 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-09-20T23:27:30.313Z,1348183650.313 [DVL_micro](INFO): Thread ID is 816
2012-09-20T23:27:30.506Z,1348183650.506 [CTD_NeilBrown](INFO): Thread ID is 817
2012-09-20T23:27:30.507Z,1348183650.507 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-09-20T23:27:30.510Z,1348183650.510 [Turbulence_NPS](INFO): Thread ID is 818
2012-09-20T23:27:30.530Z,1348183650.530 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-09-20T23:27:30.619Z,1348183650.619 [WetLabsBB2FL](INFO): Thread ID is 819
2012-09-20T23:27:30.620Z,1348183650.620 [WetLabsBB2FL](INFO): Powering down
2012-09-20T23:27:30.633Z,1348183650.633 [SBIT](INFO): Initialize SBIT Component.
2012-09-20T23:27:30.634Z,1348183650.634 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9861
2012-09-20T23:27:30.635Z,1348183650.635 [IBIT](INFO): Initialize IBIT Component.
2012-09-20T23:27:30.635Z,1348183650.635 [CBIT](DEBUG): Initialize CBIT Component.
2012-09-20T23:27:30.636Z,1348183650.635 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2012-09-20T23:27:30.636Z,1348183650.636 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-09-20T23:27:30.771Z,1348183650.771 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-09-20T23:27:30.772Z,1348183650.772 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-09-20T23:27:30.772Z,1348183650.772 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-09-20T23:27:30.772Z,1348183650.772 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-09-20T23:27:31.162Z,1348183651.162 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-09-20T23:27:31.164Z,1348183651.164 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-09-20T23:27:31.164Z,1348183651.164 [Navigation](DEBUG): Initializing Navigation.
2012-09-20T23:27:31.165Z,1348183651.165 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-09-20T23:27:31.174Z,1348183651.174 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-09-20T23:27:31.175Z,1348183651.175 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-09-20T23:27:31.176Z,1348183651.175 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-09-20T23:27:31.179Z,1348183651.179 [NavChartDb](INFO): Thread ID is 820
2012-09-20T23:27:31.199Z,1348183651.199 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-09-20T23:27:31.268Z,1348183651.267 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-20T23:27:31.277Z,1348183651.277 [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-20T23:27:31.278Z,1348183651.278 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-09-20T23:27:31.317Z,1348183651.317 [DVL_micro](INFO): Initializing
2012-09-20T23:27:31.317Z,1348183651.317 [DVL_micro](INFO): start:Powering up
2012-09-20T23:27:31.330Z,1348183651.330 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-09-20T23:27:31.332Z,1348183651.332 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-09-20T23:27:31.335Z,1348183651.335 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-20T23:27:31.343Z,1348183651.343 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-09-20T23:27:31.346Z,1348183651.346 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-20T23:27:31.353Z,1348183651.353 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-09-20T23:27:31.361Z,1348183651.361 [Default:D.SetSpeed](DEBUG): Construct.
2012-09-20T23:27:31.364Z,1348183651.364 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-09-20T23:27:31.369Z,1348183651.369 [Default:F.Wait](DEBUG): Construct Wait.
2012-09-20T23:27:31.373Z,1348183651.373 [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-20T23:27:31.378Z,1348183651.378 [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,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-09-20T23:27:31.398Z,1348183651.398 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-20T23:27:31.581Z,1348183651.581 [Depth_Keller](INFO): A/D timeout, 2 tries over 168 ms

2012-09-20T23:27:31.581Z,1348183651.581 [Depth_Keller] Data Fault, FailCount= 1
2012-09-20T23:27:31.581Z,1348183651.581 [Depth_Keller](ERROR): Data Fault
2012-09-20T23:27:31.614Z,1348183651.614 [Radio_Freewave](INFO): Powering up
2012-09-20T23:27:31.722Z,1348183651.722 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-09-20T23:27:31.723Z,1348183651.723 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-09-20T23:27:31.730Z,1348183651.730 [RudderServo](DEBUG): Initializing EZServoServo.
2012-09-20T23:27:31.731Z,1348183651.731 [RudderServo](DEBUG): Initializing RudderServo.
2012-09-20T23:27:31.737Z,1348183651.737 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-09-20T23:27:31.743Z,1348183651.743 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-09-20T23:27:31.765Z,1348183651.765 [CBIT](ERROR): Data Fault in component: Depth_Keller
2012-09-20T23:27:31.765Z,1348183651.765 [CBIT](INFO): Clearing failed state for component Depth_Keller
2012-09-20T23:27:31.765Z,1348183651.765 [Depth_Keller] No Fault, FailCount= 1
2012-09-20T23:27:35.201Z,1348183655.201 [NAL9602](INFO): Powering up NAL9602
2012-09-20T23:27:36.676Z,1348183656.676 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-09-20T23:27:36.697Z,1348183656.697 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-09-20T23:27:36.717Z,1348183656.717 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-09-20T23:27:36.738Z,1348183656.737 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-09-20T23:27:36.975Z,1348183656.975 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-09-20T23:27:36.975Z,1348183656.976 [NavChartDb](INFO): Creating index for Soundings
2012-09-20T23:27:37.083Z,1348183657.083 [NavChartDb](INFO): Creating index for Contour 0p0
2012-09-20T23:27:37.085Z,1348183657.085 [NavChartDb](INFO): Creating index for Contour 1p8
2012-09-20T23:27:37.631Z,1348183657.631 [NavChartDb](INFO): Creating index for Contour 3p6
2012-09-20T23:27:37.633Z,1348183657.633 [NavChartDb](INFO): Creating index for Contour 5p4
2012-09-20T23:27:37.903Z,1348183657.903 [NavChartDb](INFO): Creating index for Contour 9p1
2012-09-20T23:27:37.905Z,1348183657.905 [NavChartDb](INFO): Creating index for Contour 10p9
2012-09-20T23:27:37.951Z,1348183657.951 [NavChartDb](INFO): Creating index for Contour 18p2
2012-09-20T23:27:37.953Z,1348183657.953 [NavChartDb](INFO): Creating index for Contour 36p5
2012-09-20T23:27:38.032Z,1348183658.032 [NavChartDb](INFO): Creating index for Contour 54p8
2012-09-20T23:27:38.430Z,1348183658.430 [NavChartDb](INFO): Creating index for Contour 73p1
2012-09-20T23:27:38.928Z,1348183658.928 [NavChartDb](INFO): Creating index for Contour 91p4
2012-09-20T23:27:38.930Z,1348183658.930 [NavChartDb](INFO): Creating index for Contour 182p8
2012-09-20T23:27:39.088Z,1348183659.088 [NavChartDb](INFO): Creating index for Contour 365p7
2012-09-20T23:27:39.090Z,1348183659.090 [NavChartDb](INFO): Creating index for Contour 548p6
2012-09-20T23:27:39.112Z,1348183659.112 [NavChartDb](INFO): Creating index for Contour 731p5
2012-09-20T23:27:39.113Z,1348183659.113 [NavChartDb](INFO): Creating index for Contour 914p4
2012-09-20T23:27:39.128Z,1348183659.128 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-09-20T23:27:39.130Z,1348183659.130 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-09-20T23:27:39.152Z,1348183659.152 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-09-20T23:27:39.153Z,1348183659.153 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-09-20T23:27:39.175Z,1348183659.175 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-09-20T23:27:39.177Z,1348183659.177 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-09-20T23:27:39.212Z,1348183659.212 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-09-20T23:27:39.459Z,1348183659.459 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-09-20T23:27:39.461Z,1348183659.461 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-09-20T23:27:39.475Z,1348183659.475 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-09-20T23:27:39.477Z,1348183659.477 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-09-20T23:27:39.543Z,1348183659.543 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-09-20T23:27:39.545Z,1348183659.545 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-09-20T23:27:39.863Z,1348183659.863 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-09-20T23:27:39.865Z,1348183659.865 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-09-20T23:27:45.634Z,1348183665.634 [NAL9602](ERROR): NAL9602 initialize error - Can't enter command mode:pCopyright(c) 2010
NAL Research Corporation
2012-09-20T23:27:45.634Z,1348183665.634 [NAL9602] Communications Fault, FailCount= 1
2012-09-20T23:27:45.634Z,1348183665.634 [NAL9602](ERROR): Communications Fault
2012-09-20T23:27:45.700Z,1348183665.700 [CBIT](ERROR): Communications Fault in component: NAL9602
2012-09-20T23:27:45.786Z,1348183665.786 [DVL_micro](INFO): Querying output modes
2012-09-20T23:27:45.786Z,1348183665.786 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-09-20T23:27:46.048Z,1348183666.048 [NAL9602](INFO): Powering down
2012-09-20T23:27:46.137Z,1348183666.137 [SBIT](IMPORTANT): Beginning Startup BIT
2012-09-20T23:27:46.139Z,1348183666.139 [CBIT](INFO): Clearing failed state for component NAL9602
2012-09-20T23:27:46.140Z,1348183666.139 [NAL9602] No Fault, FailCount= 1
2012-09-20T23:27:46.140Z,1348183666.140 [CBIT](IMPORTANT): Beginning GF scan
2012-09-20T23:27:46.876Z,1348183666.876 [Radio_Freewave](INFO): Powering down
2012-09-20T23:27:47.312Z,1348183667.312 [Radio_Freewave](INFO): Powering up
2012-09-20T23:27:51.123Z,1348183671.123 [NAL9602](INFO): Powering up NAL9602
2012-09-20T23:27:52.987Z,1348183672.987 [AHRS_sp3003D](FAULT): Read Heading/Pitch/Roll Failure.
2012-09-20T23:27:52.987Z,1348183672.987 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-20T23:27:52.987Z,1348183672.987 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-20T23:27:52.991Z,1348183672.991 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-09-20T23:27:52.991Z,1348183672.991 [DropWeight] Hardware Fault, FailCount= 1
2012-09-20T23:27:52.992Z,1348183672.991 [DropWeight](ERROR): Hardware Fault
2012-09-20T23:27:53.464Z,1348183673.464 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-20T23:27:53.465Z,1348183673.464 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-09-20T23:27:53.465Z,1348183673.465 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-09-20T23:27:53.523Z,1348183673.523 [AHRS_sp3003D](INFO): Powering down
2012-09-20T23:27:54.362Z,1348183674.362 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-20T23:27:54.362Z,1348183674.362 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-20T23:27:54.854Z,1348183674.854 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-20T23:27:56.026Z,1348183676.026 [DVL_micro](DEBUG): cmdResponse: ÿ01 03 16
2012-09-20T23:27:56.027Z,1348183676.027 [DVL_micro](INFO): NQ1 output enabled
2012-09-20T23:27:56.027Z,1348183676.027 [DVL_micro](INFO): RSSI output enabled
2012-09-20T23:27:56.027Z,1348183676.027 [DVL_micro](INFO): ADCP output enabled
2012-09-20T23:27:56.027Z,1348183676.027 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-09-20T23:28:00.991Z,1348183680.991 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-20T23:28:00.991Z,1348183680.991 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-09-20T23:28:00.991Z,1348183680.991 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-20T23:28:01.030Z,1348183681.030 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-20T23:28:01.069Z,1348183681.069 [AHRS_sp3003D](INFO): Powering down
2012-09-20T23:28:01.930Z,1348183681.930 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-20T23:28:01.930Z,1348183681.930 [AHRS_sp3003D] No Fault, FailCount= 1
2012-09-20T23:28:01.981Z,1348183681.981 [NAL9602](ERROR): NAL9602 initialize error - Can't enter command mode:Copyright(c) 2010
NAL Research Corporation
2012-09-20T23:28:01.982Z,1348183681.981 [NAL9602] Communications Fault, FailCount= 2
2012-09-20T23:28:01.982Z,1348183681.982 [NAL9602](ERROR): Communications Fault
2012-09-20T23:28:02.489Z,1348183682.490 [CBIT](ERROR): Communications Fault in component: NAL9602
2012-09-20T23:28:02.490Z,1348183682.490 [CBIT](CRITICAL): Communications Fault in component: NAL9602
2012-09-20T23:28:02.532Z,1348183682.532 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-20T23:28:02.535Z,1348183682.536 [NAL9602](INFO): Powering down
2012-09-20T23:28:04.143Z,1348183684.143 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-09-20T23:28:04.143Z,1348183684.143 [AHRS_sp3003D] Communications Fault, FailCount= 2
2012-09-20T23:28:04.143Z,1348183684.143 [AHRS_sp3003D](ERROR): Communications Fault
2012-09-20T23:28:04.906Z,1348183684.906 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-09-20T23:28:04.959Z,1348183684.959 [AHRS_sp3003D](INFO): Powering down
2012-09-20T23:28:05.834Z,1348183685.834 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-09-20T23:28:05.834Z,1348183685.834 [AHRS_sp3003D] No Fault, FailCount= 2
2012-09-20T23:28:06.222Z,1348183686.223 [DVL_micro](DEBUG): cmdResponse: 
AUTO_VEL_ON 
2012-09-20T23:28:06.240Z,1348183686.240 [DVL_micro](INFO): pause:Powering down
2012-09-20T23:28:06.315Z,1348183686.315 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-09-20T23:28:14.755Z,1348183694.755 [CBIT](IMPORTANT): No ground fault detected
2012-09-20T23:28:39.551Z,1348183719.551 [SBIT](IMPORTANT): SBIT PASSED
2012-09-20T23:28:39.948Z,1348183719.948 [MissionManager](IMPORTANT): Started mission Startup
2012-09-20T23:28:39.948Z,1348183719.948 [Startup] Running Loop=1
2012-09-20T23:28:39.948Z,1348183719.948 [Startup](INFO): Aggregate::initialize Startup
2012-09-20T23:28:39.948Z,1348183719.948 [Startup:A.GoToSurface] Running Loop=1
2012-09-20T23:28:39.948Z,1348183719.948 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-09-20T23:28:39.953Z,1348183719.954 [Startup:StartupSatComms] Running Loop=1
2012-09-20T23:28:39.954Z,1348183719.954 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-09-20T23:28:39.954Z,1348183719.954 [Startup:StartupSatComms:A] Running Loop=1
2012-09-20T23:28:40.348Z,1348183720.348 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix