2011-11-12T17:34:36.24560Z,1321119276.2456 [Supervisor](DEBUG): Initializing supervisor.
2011-11-12T17:34:36.24800Z,1321119276.248 [SyncHandler](DEBUG): Created PCaller Thread at 1077007584
2011-11-12T17:34:36.24860Z,1321119276.2486 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2011-11-12T17:34:36.24960Z,1321119276.2496 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077073120
2011-11-12T17:34:36.25050Z,1321119276.2505 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2011-11-12T17:34:36.26030Z,1321119276.2603 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2011-11-12T17:34:36.26130Z,1321119276.2613 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077138656
2011-11-12T17:34:36.26220Z,1321119276.2622 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2011-11-12T17:34:36.26260Z,1321119276.2626 [Supervisor](INFO): Looking for Config files in directory: Config/
2011-11-12T17:34:36.26380Z,1321119276.2638 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2011-11-12T17:34:36.52820Z,1321119276.5282 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2011-11-12T17:34:36.52870Z,1321119276.5287 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2011-11-12T17:34:36.69750Z,1321119276.6975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2011-11-12T17:34:36.69810Z,1321119276.6981 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2011-11-12T17:34:36.78200Z,1321119276.782 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2011-11-12T17:34:36.78250Z,1321119276.7825 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2011-11-12T17:34:36.96950Z,1321119276.9695 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2011-11-12T17:34:36.97010Z,1321119276.9701 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2011-11-12T17:34:37.09130Z,1321119277.0913 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2011-11-12T17:34:37.09180Z,1321119277.0918 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2011-11-12T17:34:37.30910Z,1321119277.3091 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2011-11-12T17:34:37.30960Z,1321119277.3096 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2011-11-12T17:34:37.44840Z,1321119277.4484 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2011-11-12T17:34:37.44900Z,1321119277.449 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2011-11-12T17:34:37.69090Z,1321119277.6909 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2011-11-12T17:34:37.69150Z,1321119277.6915 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2011-11-12T17:34:37.79210Z,1321119277.7921 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2011-11-12T17:34:37.79260Z,1321119277.7926 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2011-11-12T17:34:38.15280Z,1321119278.1528 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2011-11-12T17:34:38.15340Z,1321119278.1534 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2011-11-12T17:34:38.26120Z,1321119278.2612 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2011-11-12T17:34:38.26180Z,1321119278.2618 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2011-11-12T17:34:38.34670Z,1321119278.3467 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-tethys/
2011-11-12T17:34:38.34770Z,1321119278.3477 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/vehicle.cfg
2011-11-12T17:34:38.44840Z,1321119278.4484 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Sensor.cfg
2011-11-12T17:34:38.56430Z,1321119278.5643 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/BIT.cfg
2011-11-12T17:34:38.66040Z,1321119278.6604 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Servo.cfg
2011-11-12T17:34:38.75470Z,1321119278.7547 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Science.cfg
2011-11-12T17:34:38.84560Z,1321119278.8456 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/workSite.cfg
2011-11-12T17:34:38.93200Z,1321119278.932 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Simulator.cfg
2011-11-12T17:34:39.01650Z,1321119279.0165 [Supervisor](INFO): Opening Config file at: Config/lrauv-tethys/Derivation.cfg
2011-11-12T17:34:39.12380Z,1321119279.1238 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2011-11-12T17:34:39.20490Z,1321119279.2049 [InternalSim] Loaded
2011-11-12T17:34:39.20520Z,1321119279.2052 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2011-11-12T17:34:39.20600Z,1321119279.206 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2011-11-12T17:34:39.20660Z,1321119279.2066 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2011-11-12T17:34:39.21930Z,1321119279.2193 [SBIT](DEBUG): Construct Startup Built In Test.
2011-11-12T17:34:39.24600Z,1321119279.246 [SBIT] Loaded
2011-11-12T17:34:39.24630Z,1321119279.2463 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2011-11-12T17:34:39.24730Z,1321119279.2473 [IBIT](DEBUG): Construct Initiated Built In Test.
2011-11-12T17:34:39.26950Z,1321119279.2695 [IBIT] Loaded
2011-11-12T17:34:39.26980Z,1321119279.2698 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2011-11-12T17:34:39.27640Z,1321119279.2764 [CBIT](DEBUG): Construct CBIT Built In Test.
2011-11-12T17:34:39.32880Z,1321119279.3288 [CBIT] Loaded
2011-11-12T17:34:39.32900Z,1321119279.329 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2011-11-12T17:34:39.32940Z,1321119279.3294 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2011-11-12T17:34:39.32990Z,1321119279.3299 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2011-11-12T17:34:39.42420Z,1321119279.4242 [BuoyancyServo] Loaded
2011-11-12T17:34:39.42450Z,1321119279.4245 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2011-11-12T17:34:39.43100Z,1321119279.431 [ElevatorServo] Loaded
2011-11-12T17:34:39.43130Z,1321119279.4313 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2011-11-12T17:34:39.43780Z,1321119279.4378 [MassServo] Loaded
2011-11-12T17:34:39.43810Z,1321119279.4381 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2011-11-12T17:34:39.44450Z,1321119279.4445 [RudderServo] Loaded
2011-11-12T17:34:39.44480Z,1321119279.4448 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2011-11-12T17:34:39.45140Z,1321119279.4514 [ThrusterServo] Loaded
2011-11-12T17:34:39.45160Z,1321119279.4516 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2011-11-12T17:34:39.45200Z,1321119279.452 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2011-11-12T17:34:39.45260Z,1321119279.4526 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2011-11-12T17:34:39.47340Z,1321119279.4734 [Bathymetry] Loaded
2011-11-12T17:34:39.47360Z,1321119279.4736 [ComponentRegistry](DEBUG): SyncComponent "Bathymetry" handled in the control thread.
2011-11-12T17:34:39.47910Z,1321119279.4791 [DepthRateCalculator] Loaded
2011-11-12T17:34:39.47940Z,1321119279.4794 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2011-11-12T17:34:39.48480Z,1321119279.4848 [PitchRateCalculator] Loaded
2011-11-12T17:34:39.48510Z,1321119279.4851 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2011-11-12T17:34:39.49040Z,1321119279.4904 [SpeedCalculator] Loaded
2011-11-12T17:34:39.49070Z,1321119279.4907 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2011-11-12T17:34:39.50420Z,1321119279.5042 [TempGradientCalculator] Loaded
2011-11-12T17:34:39.50450Z,1321119279.5045 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2011-11-12T17:34:39.51000Z,1321119279.51 [YawRateCalculator] Loaded
2011-11-12T17:34:39.51020Z,1321119279.5102 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2011-11-12T17:34:39.53890Z,1321119279.5389 [Navigation] Loaded
2011-11-12T17:34:39.53920Z,1321119279.5392 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2011-11-12T17:34:39.53960Z,1321119279.5396 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2011-11-12T17:34:39.54020Z,1321119279.5402 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2011-11-12T17:34:39.58820Z,1321119279.5882 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2011-11-12T17:34:39.58880Z,1321119279.5888 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2011-11-12T17:34:39.59810Z,1321119279.5981 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2011-11-12T17:34:39.59870Z,1321119279.5987 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2011-11-12T17:34:39.61100Z,1321119279.611 [VerticalControl](DEBUG): Construct VerticalControl.
2011-11-12T17:34:39.80570Z,1321119279.8057 [VerticalControl] Loaded
2011-11-12T17:34:39.80600Z,1321119279.806 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2011-11-12T17:34:39.80680Z,1321119279.8068 [HorizontalControl](DEBUG): Construct HorizontalControl.
2011-11-12T17:34:39.85640Z,1321119279.8564 [HorizontalControl] Loaded
2011-11-12T17:34:39.85660Z,1321119279.8566 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2011-11-12T17:34:39.85760Z,1321119279.8576 [SpeedControl](DEBUG): Construct SpeedControl.
2011-11-12T17:34:39.85930Z,1321119279.8593 [SpeedControl] Loaded
2011-11-12T17:34:39.85950Z,1321119279.8595 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2011-11-12T17:34:39.86040Z,1321119279.8604 [LoopControl](DEBUG): Construct LoopControl.
2011-11-12T17:34:39.86110Z,1321119279.8611 [LoopControl] Loaded
2011-11-12T17:34:39.86130Z,1321119279.8613 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2011-11-12T17:34:39.86170Z,1321119279.8617 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2011-11-12T17:34:39.86230Z,1321119279.8623 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2011-11-12T17:34:39.86760Z,1321119279.8676 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2011-11-12T17:34:39.87210Z,1321119279.8721 [AsyncPiEstimator] Loaded
2011-11-12T17:34:39.87240Z,1321119279.8724 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2011-11-12T17:34:39.87360Z,1321119279.8736 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078400224
2011-11-12T17:34:39.87420Z,1321119279.8742 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2011-11-12T17:34:39.87480Z,1321119279.8748 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2011-11-12T17:34:39.95750Z,1321119279.9575 [AHRS_sp3003D] Loaded
2011-11-12T17:34:39.95780Z,1321119279.9578 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2011-11-12T17:34:39.99580Z,1321119279.9958 [AHRS_3DMGX3] Loaded
2011-11-12T17:34:39.99610Z,1321119279.9961 [ComponentRegistry](DEBUG): SyncComponent "AHRS_3DMGX3" handled in the control thread.
2011-11-12T17:34:40.27920Z,1321119280.2792 [Batt_Ocean_Server] Loaded
2011-11-12T17:34:40.27950Z,1321119280.2795 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2011-11-12T17:34:40.29110Z,1321119280.2911 [Depth_Keller] Loaded
2011-11-12T17:34:40.29140Z,1321119280.2914 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2011-11-12T17:34:40.29680Z,1321119280.2968 [DropWeight] Loaded
2011-11-12T17:34:40.29710Z,1321119280.2971 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2011-11-12T17:34:40.38470Z,1321119280.3847 [DVL_micro] Loaded
2011-11-12T17:34:40.38500Z,1321119280.385 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2011-11-12T17:34:40.46010Z,1321119280.4601 [NAL9601] Loaded
2011-11-12T17:34:40.46040Z,1321119280.4604 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2011-11-12T17:34:40.50690Z,1321119280.5069 [Onboard] Loaded
2011-11-12T17:34:40.50720Z,1321119280.5072 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2011-11-12T17:34:40.51320Z,1321119280.5132 [Radio_Freewave] Loaded
2011-11-12T17:34:40.51350Z,1321119280.5135 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2011-11-12T17:34:40.53190Z,1321119280.5319 [DAT] Loaded
2011-11-12T17:34:40.53220Z,1321119280.5322 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2011-11-12T17:34:40.53260Z,1321119280.5326 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2011-11-12T17:34:40.53320Z,1321119280.5332 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2011-11-12T17:34:40.57530Z,1321119280.5753 [WetLabsBB2FL] Loaded
2011-11-12T17:34:40.57560Z,1321119280.5756 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2011-11-12T17:34:40.57660Z,1321119280.5766 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2011-11-12T17:34:40.57880Z,1321119280.5788 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2011-11-12T17:34:40.57970Z,1321119280.5797 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2011-11-12T17:34:40.58040Z,1321119280.5804 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2011-11-12T17:34:40.58050Z,1321119280.5805 [Supervisor](DEBUG): Running supervisor.
2011-11-12T17:34:40.58380Z,1321119280.5838 [controlThread](DEBUG): Initializing ControlThread
2011-11-12T17:34:40.58470Z,1321119280.5847 [InternalSim](DEBUG):  InternalSim initializing...
2011-11-12T17:34:40.61600Z,1321119280.616 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2011-11-12T17:34:40.62680Z,1321119280.6268 [SBIT](INFO): Initialize SBIT Component.
2011-11-12T17:34:40.62840Z,1321119280.6284 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9356 $
2011-11-12T17:34:40.62900Z,1321119280.629 [IBIT](INFO): Initialize IBIT Component.
2011-11-12T17:34:40.63230Z,1321119280.6323 [CBIT](DEBUG): Initialize CBIT Component.
2011-11-12T17:34:40.63260Z,1321119280.6326 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2011-11-12T17:34:40.65650Z,1321119280.6565 [Bathymetry](DEBUG): Initialize Bathymetry Derivation.
2011-11-12T17:34:40.66100Z,1321119280.661 [Bathymetry](DEBUG): Opened 
2011-11-12T17:34:40.66980Z,1321119280.6698 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2011-11-12T17:34:40.67020Z,1321119280.6702 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2011-11-12T17:34:40.67050Z,1321119280.6705 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2011-11-12T17:34:40.67120Z,1321119280.6712 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2011-11-12T17:34:40.67250Z,1321119280.6725 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2011-11-12T17:34:40.67280Z,1321119280.6728 [Navigation](DEBUG): Initializing Navigation.
2011-11-12T17:34:40.67320Z,1321119280.6732 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2011-11-12T17:34:40.68680Z,1321119280.6868 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2011-11-12T17:34:40.68970Z,1321119280.6897 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2011-11-12T17:34:40.69040Z,1321119280.6904 [LoopControl](DEBUG): Initialize LoopControlComponent.
2011-11-12T17:34:42.29620Z,1321119282.2962 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2011-11-12T17:34:42.30060Z,1321119282.3006 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2011-11-12T17:34:42.31050Z,1321119282.3105 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2011-11-12T17:34:42.32010Z,1321119282.3201 [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>


2011-11-12T17:34:42.32090Z,1321119282.3209 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2011-11-12T17:34:42.34820Z,1321119282.3482 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2011-11-12T17:34:42.35170Z,1321119282.3517 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2011-11-12T17:34:42.35780Z,1321119282.3578 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2011-11-12T17:34:42.36120Z,1321119282.3612 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2011-11-12T17:34:42.36730Z,1321119282.3673 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2011-11-12T17:34:42.37980Z,1321119282.3798 [Default:E.SetSpeed](DEBUG): Construct.
2011-11-12T17:34:42.38300Z,1321119282.383 [Default:F.GoToSurface](DEBUG): Construct GoToSurface.
2011-11-12T17:34:42.38760Z,1321119282.3876 [Default:G.Wait](DEBUG): Construct Wait.
2011-11-12T17:34:42.39150Z,1321119282.3915 [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">

    <Aggregate Id="GPS" >

<!--    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>

    </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 on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout><Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="CallGPS" >

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

        <Call RefId="GPS"/>

    </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>

        <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>


2011-11-12T17:34:42.39690Z,1321119282.3969 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,AHRS_3DMGX3,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,DAT,WetLabsBB2FL,Depth_Keller,Bathymetry,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintainer,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2011-11-12T17:34:42.41480Z,1321119282.4148 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2011-11-12T17:34:42.42130Z,1321119282.4213 [AHRS_3DMGX3](DEBUG): Initializing AHRS_3DMGX3.
2011-11-12T17:34:42.53160Z,1321119282.5316 [DVL_micro](DEBUG): Initializing DVL_micro.
2011-11-12T17:34:42.55160Z,1321119282.5516 [Radio_Freewave](INFO): Powering up
2011-11-12T17:34:42.55670Z,1321119282.5567 [DAT](INFO): Powering up
2011-11-12T17:34:42.55690Z,1321119282.5569 [DAT](DEBUG): Initializing DAT.
2011-11-12T17:34:42.56240Z,1321119282.5624 [WetLabsBB2FL](INFO): Powering down
2011-11-12T17:34:42.63170Z,1321119282.6317 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2011-11-12T17:34:42.63270Z,1321119282.6327 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2011-11-12T17:34:42.64150Z,1321119282.6415 [ElevatorServo](DEBUG): Initializing EZServoServo.
2011-11-12T17:34:42.64240Z,1321119282.6424 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2011-11-12T17:34:42.65020Z,1321119282.6502 [MassServo](DEBUG): Initializing EZServoServo.
2011-11-12T17:34:42.65150Z,1321119282.6515 [MassServo](DEBUG): Initializing MassServo.
2011-11-12T17:34:42.65850Z,1321119282.6585 [RudderServo](DEBUG): Initializing EZServoServo.
2011-11-12T17:34:42.65960Z,1321119282.6596 [RudderServo](DEBUG): Initializing RudderServo.
2011-11-12T17:34:42.66700Z,1321119282.667 [ThrusterServo](DEBUG): Initializing EZServoServo.
2011-11-12T17:34:42.66810Z,1321119282.6681 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2011-11-12T17:34:45.51760Z,1321119285.5176 [NAL9601](INFO): Powering up NAL9601
2011-11-12T17:34:56.33620Z,1321119296.3362 [SBIT](IMPORTANT): Beginning Startup BIT
2011-11-12T17:34:56.33820Z,1321119296.3382 [CBIT](IMPORTANT): Beginning GF scan
2011-11-12T17:34:57.52630Z,1321119297.5263 [DAT](INFO): Powering down
2011-11-12T17:35:22.57860Z,1321119322.5786 [CBIT](IMPORTANT): No ground fault detected
2011-11-12T17:35:38.07570Z,1321119338.0757 [SBIT](IMPORTANT): SBIT PASSED
2011-11-12T17:35:38.46610Z,1321119338.4661 [MissionManager](IMPORTANT): Started mission Startup
2011-11-12T17:35:38.46620Z,1321119338.4662 [Startup] Running Loop=1
2011-11-12T17:35:38.46630Z,1321119338.4663 [Startup](INFO): Aggregate::initialize Startup
2011-11-12T17:35:38.46640Z,1321119338.4664 [Startup:A.GoToSurface] Running Loop=1
2011-11-12T17:35:38.46650Z,1321119338.4665 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:35:38.47190Z,1321119338.4719 [Startup:StartupSatComms] Running Loop=1
2011-11-12T17:35:38.47210Z,1321119338.4721 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2011-11-12T17:35:38.47230Z,1321119338.4723 [Startup:StartupSatComms:A] Running Loop=1
2011-11-12T17:35:38.86650Z,1321119338.8665 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-11-12T17:35:51.32770Z,1321119351.3277 [NAL9601](INFO): NAL9601 initialized
2011-11-12T17:35:52.48050Z,1321119352.4805 [NAL9601](IMPORTANT): GPS fix at: 1321119345
2011-11-12T17:35:52.49230Z,1321119352.4923 [Startup:StartupSatComms:A] Stopped
2011-11-12T17:35:52.49250Z,1321119352.4925 [Startup:StartupSatComms:B] Running Loop=1
2011-11-12T17:35:52.87690Z,1321119352.8769 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-11-12T17:36:24.72210Z,1321119384.7221 [NAL9601](INFO): SBD MO Status=1, MOMSN=37318, MT Status=0, MTMSN=0
2011-11-12T17:36:24.86360Z,1321119384.8636 [NAL9601](INFO): Sent 332 bytes from file Logs/20111112T165502/shore0005.lzma
2011-11-12T17:36:24.86390Z,1321119384.8639 [NAL9601](INFO): Packets left to send: 1
2011-11-12T17:36:24.86510Z,1321119384.8651 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2011-11-12T17:36:31.99410Z,1321119391.9941 [NAL9601](INFO): SBD MO Status=1, MOMSN=37319, MT Status=0, MTMSN=0
2011-11-12T17:36:32.15160Z,1321119392.1516 [NAL9601](INFO): Sent 28 bytes from file Logs/20111112T165502/shore0005.lzma
2011-11-12T17:36:32.15180Z,1321119392.1518 [NAL9601](INFO): Packets left to send: 0
2011-11-12T17:36:32.15280Z,1321119392.1528 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2011-11-12T17:36:39.68500Z,1321119399.685 [NAL9601](INFO): SBD MO Status=1, MOMSN=37320, MT Status=0, MTMSN=0
2011-11-12T17:36:39.83960Z,1321119399.8396 [NAL9601](INFO): Sent 332 bytes from file Logs/20111112T173436/shore0000.lzma
2011-11-12T17:36:39.83980Z,1321119399.8398 [NAL9601](INFO): Packets left to send: 1
2011-11-12T17:36:39.84080Z,1321119399.8408 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2011-11-12T17:36:46.96200Z,1321119406.962 [NAL9601](INFO): SBD MO Status=1, MOMSN=37321, MT Status=0, MTMSN=0
2011-11-12T17:36:47.12760Z,1321119407.1276 [NAL9601](INFO): Sent 193 bytes from file Logs/20111112T173436/shore0000.lzma
2011-11-12T17:36:47.12780Z,1321119407.1278 [NAL9601](INFO): Packets left to send: 0
2011-11-12T17:36:47.12880Z,1321119407.1288 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2011-11-12T17:36:52.56710Z,1321119412.5671 [Startup:StartupSatComms:B](INFO): Timed out from 2011-11-12T17:35:52.Z
2011-11-12T17:36:52.56730Z,1321119412.5673 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2011-11-12T17:36:52.56740Z,1321119412.5674 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2011-11-12T17:36:52.56770Z,1321119412.5677 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2011-11-12T17:36:52.56770Z,1321119412.5677 [Startup:StartupSatComms:B] Stopped
2011-11-12T17:36:52.56790Z,1321119412.5679 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2011-11-12T17:36:52.56800Z,1321119412.568 [Startup:StartupSatComms] Stopped
2011-11-12T17:36:52.56810Z,1321119412.5681 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2011-11-12T17:36:52.56850Z,1321119412.5685 [Startup](INFO): Completed Startup
2011-11-12T17:36:52.56860Z,1321119412.5686 [Startup] Stopped
2011-11-12T17:36:52.56880Z,1321119412.5688 [Startup](INFO): Aggregate::uninitialize Startup
2011-11-12T17:36:52.56880Z,1321119412.5688 [Startup:A.GoToSurface] Stopped
2011-11-12T17:36:52.56890Z,1321119412.5689 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:36:52.97550Z,1321119412.9755 [MissionManager](IMPORTANT): Started mission Default
2011-11-12T17:36:52.97560Z,1321119412.9756 [Default] Running Loop=1
2011-11-12T17:36:52.97570Z,1321119412.9757 [Default](INFO): Aggregate::initialize Default
2011-11-12T17:36:52.97580Z,1321119412.9758 [Default:E.SetSpeed] Running Loop=1
2011-11-12T17:36:52.97590Z,1321119412.9759 [Default:E.SetSpeed](DEBUG): Initialize.
2011-11-12T17:36:52.97620Z,1321119412.9762 [Default:F.GoToSurface] Running Loop=1
2011-11-12T17:36:52.97620Z,1321119412.9762 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:36:52.97670Z,1321119412.9767 [Default:GPS] Running Loop=1
2011-11-12T17:36:52.97680Z,1321119412.9768 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T17:36:52.97690Z,1321119412.9769 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T17:36:52.97700Z,1321119412.977 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:36:52.97720Z,1321119412.9772 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T17:36:52.97730Z,1321119412.9773 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:36:52.97810Z,1321119412.9781 [Default:F.GoToSurface] Running Loop=1
2011-11-12T17:36:52.98250Z,1321119412.9825 [Default:E.SetSpeed] Running Loop=1
2011-11-12T17:36:52.98690Z,1321119412.9869 [Default:CallIridium] Running Loop=1
2011-11-12T17:36:52.98710Z,1321119412.9871 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T17:36:52.98730Z,1321119412.9873 [Default:CallIridium:A] Running Loop=1
2011-11-12T17:36:52.98740Z,1321119412.9874 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T17:36:52.98760Z,1321119412.9876 [Default:CallGPS] Running Loop=1
2011-11-12T17:36:52.98770Z,1321119412.9877 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T17:36:52.98790Z,1321119412.9879 [Default:CallGPS:A] Running Loop=1
2011-11-12T17:36:52.98800Z,1321119412.988 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T17:36:52.99250Z,1321119412.9925 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T17:36:52.99250Z,1321119412.9925 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:36:52.99270Z,1321119412.9927 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T17:36:52.99270Z,1321119412.9927 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T17:36:53.36760Z,1321119413.3676 [Default:Iridium] Running Loop=1
2011-11-12T17:36:53.36780Z,1321119413.3678 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T17:36:53.36790Z,1321119413.3679 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T17:36:53.36790Z,1321119413.3679 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:36:53.36820Z,1321119413.3682 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T17:36:53.36830Z,1321119413.3683 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:36:53.37320Z,1321119413.3732 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T17:36:53.37330Z,1321119413.3733 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:36:53.37350Z,1321119413.3735 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T17:36:53.37350Z,1321119413.3735 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T17:36:53.37880Z,1321119413.3788 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-11-12T17:36:53.82950Z,1321119413.8295 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-11-12T17:36:54.55680Z,1321119414.5568 [NAL9601](INFO): SBD MO Status=0, MOMSN=37322, MT Status=0, MTMSN=0
2011-11-12T17:36:54.72740Z,1321119414.7274 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T17:36:54.72790Z,1321119414.7279 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T17:36:54.72800Z,1321119414.728 [Default:Iridium] Stopped
2011-11-12T17:36:54.72810Z,1321119414.7281 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T17:36:54.72820Z,1321119414.7282 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T17:36:54.72830Z,1321119414.7283 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:36:54.97630Z,1321119414.9763 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T17:36:54.97640Z,1321119414.9764 [Default:CallIridium:A] Stopped
2011-11-12T17:36:54.97650Z,1321119414.9765 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T17:36:54.97670Z,1321119414.9767 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T17:36:54.97680Z,1321119414.9768 [Default:CallIridium] Stopped
2011-11-12T17:36:54.97690Z,1321119414.9769 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T17:36:55.76340Z,1321119415.7634 [NAL9601](IMPORTANT): GPS fix at: 1321119408
2011-11-12T17:36:55.77650Z,1321119415.7765 [Default:GPS:Read_GPS] Stopped
2011-11-12T17:36:55.77690Z,1321119415.7769 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T17:36:55.77700Z,1321119415.777 [Default:GPS] Stopped
2011-11-12T17:36:55.77710Z,1321119415.7771 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T17:36:55.77720Z,1321119415.7772 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T17:36:55.77720Z,1321119415.7772 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:36:55.77740Z,1321119415.7774 [Default:Iridium] Running Loop=1
2011-11-12T17:36:55.77750Z,1321119415.7775 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T17:36:55.77760Z,1321119415.7776 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T17:36:55.77770Z,1321119415.7777 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:36:55.77780Z,1321119415.7778 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T17:36:55.77790Z,1321119415.7779 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:36:56.17300Z,1321119416.173 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T17:36:56.17300Z,1321119416.173 [Default:CallGPS:A] Stopped
2011-11-12T17:36:56.17320Z,1321119416.1732 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T17:36:56.17340Z,1321119416.1734 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T17:36:56.17350Z,1321119416.1735 [Default:CallGPS] Stopped
2011-11-12T17:36:56.17360Z,1321119416.1736 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T17:36:56.17400Z,1321119416.174 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T17:36:56.17400Z,1321119416.174 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:36:56.17420Z,1321119416.1742 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T17:37:05.95650Z,1321119425.9565 [NAL9601](INFO): SBD MO Status=1, MOMSN=37323, MT Status=0, MTMSN=0
2011-11-12T17:37:06.09960Z,1321119426.0996 [NAL9601](INFO): Sent 149 bytes from file Logs/20111112T173436/shore0001.lzma
2011-11-12T17:37:06.09980Z,1321119426.0998 [NAL9601](INFO): Packets left to send: 0
2011-11-12T17:37:06.10090Z,1321119426.1009 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2011-11-12T17:37:11.99190Z,1321119431.9919 [NAL9601](INFO): SBD MO Status=0, MOMSN=37324, MT Status=0, MTMSN=0
2011-11-12T17:37:12.20400Z,1321119432.204 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T17:37:12.20430Z,1321119432.2043 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T17:37:12.20440Z,1321119432.2044 [Default:Iridium] Stopped
2011-11-12T17:37:12.20460Z,1321119432.2046 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T17:37:12.20460Z,1321119432.2046 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T17:37:12.20470Z,1321119432.2047 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:37:12.20490Z,1321119432.2049 [Default:G.Wait] Running Loop=1
2011-11-12T17:37:12.20490Z,1321119432.2049 [Default:G.Wait](DEBUG): Initialize Wait Component.
2011-11-12T17:37:22.49440Z,1321119442.4944 [NAL9601](INFO): Powering down
2011-11-12T17:42:12.53280Z,1321119732.5328 [Default:CallIridium] Running Loop=1
2011-11-12T17:42:12.53290Z,1321119732.5329 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T17:42:12.53310Z,1321119732.5331 [Default:CallIridium:A] Running Loop=1
2011-11-12T17:42:12.53320Z,1321119732.5332 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T17:42:12.53330Z,1321119732.5333 [Default:CallGPS] Running Loop=1
2011-11-12T17:42:12.53350Z,1321119732.5335 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T17:42:12.53360Z,1321119732.5336 [Default:CallGPS:A] Running Loop=1
2011-11-12T17:42:12.53370Z,1321119732.5337 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T17:42:17.48790Z,1321119737.4879 [Default:Iridium] Running Loop=1
2011-11-12T17:42:17.48810Z,1321119737.4881 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T17:42:17.48820Z,1321119737.4882 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T17:42:17.48830Z,1321119737.4883 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:42:17.48850Z,1321119737.4885 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T17:42:17.48850Z,1321119737.4885 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:42:17.48910Z,1321119737.4891 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T17:42:17.48920Z,1321119737.4892 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:42:17.48930Z,1321119737.4893 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T17:42:17.48960Z,1321119737.4896 [Default:GPS] Running Loop=1
2011-11-12T17:42:17.48970Z,1321119737.4897 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T17:42:17.48980Z,1321119737.4898 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T17:42:17.48990Z,1321119737.4899 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:42:17.49010Z,1321119737.4901 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T17:42:17.49010Z,1321119737.4901 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:42:17.49070Z,1321119737.4907 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T17:42:17.49070Z,1321119737.4907 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:42:17.49090Z,1321119737.4909 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T17:42:18.16850Z,1321119738.1685 [NAL9601](INFO): Powering up
2011-11-12T17:43:23.87980Z,1321119803.8798 [NAL9601](INFO): NAL9601 initialized
2011-11-12T17:43:40.05020Z,1321119820.0502 [NAL9601](INFO): SBD MO Status=1, MOMSN=37325, MT Status=0, MTMSN=0
2011-11-12T17:43:40.24360Z,1321119820.2436 [NAL9601](INFO): Sent 88 bytes from file Logs/20111112T173436/shore0002.lzma
2011-11-12T17:43:40.24380Z,1321119820.2438 [NAL9601](INFO): Packets left to send: 0
2011-11-12T17:43:40.24490Z,1321119820.2449 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2011-11-12T17:43:48.00600Z,1321119828.006 [NAL9601](INFO): SBD MO Status=0, MOMSN=37326, MT Status=0, MTMSN=0
2011-11-12T17:43:48.14360Z,1321119828.1436 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T17:43:48.14400Z,1321119828.144 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T17:43:48.14400Z,1321119828.144 [Default:Iridium] Stopped
2011-11-12T17:43:48.14420Z,1321119828.1442 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T17:43:48.14430Z,1321119828.1443 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T17:43:48.14430Z,1321119828.1443 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:43:48.41700Z,1321119828.417 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T17:43:48.41710Z,1321119828.4171 [Default:CallIridium:A] Stopped
2011-11-12T17:43:48.41720Z,1321119828.4172 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T17:43:48.41740Z,1321119828.4174 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T17:43:48.41750Z,1321119828.4175 [Default:CallIridium] Stopped
2011-11-12T17:43:48.41760Z,1321119828.4176 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T17:45:13.20750Z,1321119913.2075 [NAL9601](IMPORTANT): GPS fix at: 1321119907
2011-11-12T17:45:13.22030Z,1321119913.2203 [Default:GPS:Read_GPS] Stopped
2011-11-12T17:45:13.22070Z,1321119913.2207 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T17:45:13.22080Z,1321119913.2208 [Default:GPS] Stopped
2011-11-12T17:45:13.22090Z,1321119913.2209 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T17:45:13.22100Z,1321119913.221 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T17:45:13.22110Z,1321119913.2211 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:45:13.63520Z,1321119913.6352 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T17:45:13.63530Z,1321119913.6353 [Default:CallGPS:A] Stopped
2011-11-12T17:45:13.63540Z,1321119913.6354 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T17:45:13.63560Z,1321119913.6356 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T17:45:13.63570Z,1321119913.6357 [Default:CallGPS] Stopped
2011-11-12T17:45:13.63580Z,1321119913.6358 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T17:45:33.78150Z,1321119933.7815 [NAL9601](INFO): Powering down
2011-11-12T17:48:48.74100Z,1321120128.741 [Default:CallIridium] Running Loop=1
2011-11-12T17:48:48.74110Z,1321120128.7411 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T17:48:48.74130Z,1321120128.7413 [Default:CallIridium:A] Running Loop=1
2011-11-12T17:48:48.74140Z,1321120128.7414 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T17:48:48.74150Z,1321120128.7415 [Default:CallGPS] Running Loop=1
2011-11-12T17:48:48.74170Z,1321120128.7417 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T17:48:48.74180Z,1321120128.7418 [Default:CallGPS:A] Running Loop=1
2011-11-12T17:48:48.74190Z,1321120128.7419 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T17:48:53.79720Z,1321120133.7972 [Default:Iridium] Running Loop=1
2011-11-12T17:48:53.79740Z,1321120133.7974 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T17:48:53.79750Z,1321120133.7975 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T17:48:53.79760Z,1321120133.7976 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:48:53.79770Z,1321120133.7977 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T17:48:53.79780Z,1321120133.7978 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:48:53.79840Z,1321120133.7984 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T17:48:53.79850Z,1321120133.7985 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:48:53.79860Z,1321120133.7986 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T17:48:53.79890Z,1321120133.7989 [Default:GPS] Running Loop=1
2011-11-12T17:48:53.79900Z,1321120133.799 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T17:48:53.79930Z,1321120133.7993 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T17:48:53.79940Z,1321120133.7994 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:48:53.79950Z,1321120133.7995 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T17:48:53.79960Z,1321120133.7996 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:48:53.80020Z,1321120133.8002 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T17:48:53.80020Z,1321120133.8002 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:48:53.80040Z,1321120133.8004 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T17:48:54.42680Z,1321120134.4268 [NAL9601](INFO): Powering up
2011-11-12T17:50:00.13570Z,1321120200.1357 [NAL9601](INFO): NAL9601 initialized
2011-11-12T17:50:20.27810Z,1321120220.2781 [NAL9601](INFO): SBD MO Status=1, MOMSN=37327, MT Status=0, MTMSN=0
2011-11-12T17:50:20.49560Z,1321120220.4956 [NAL9601](INFO): Sent 243 bytes from file Logs/20111112T173436/shore0003.lzma
2011-11-12T17:50:20.49580Z,1321120220.4958 [NAL9601](INFO): Packets left to send: 0
2011-11-12T17:50:20.49690Z,1321120220.4969 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2011-11-12T17:50:27.06200Z,1321120227.062 [NAL9601](INFO): SBD MO Status=0, MOMSN=37328, MT Status=0, MTMSN=0
2011-11-12T17:50:27.19560Z,1321120227.1956 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T17:50:27.19600Z,1321120227.196 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T17:50:27.19610Z,1321120227.1961 [Default:Iridium] Stopped
2011-11-12T17:50:27.19620Z,1321120227.1962 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T17:50:27.19630Z,1321120227.1963 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T17:50:27.19640Z,1321120227.1964 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:50:27.46770Z,1321120227.4677 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T17:50:27.46780Z,1321120227.4678 [Default:CallIridium:A] Stopped
2011-11-12T17:50:27.46800Z,1321120227.468 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T17:50:27.46820Z,1321120227.4682 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T17:50:27.46820Z,1321120227.4682 [Default:CallIridium] Stopped
2011-11-12T17:50:27.46840Z,1321120227.4684 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T17:50:40.26360Z,1321120240.2636 [NAL9601](IMPORTANT): GPS fix at: 1321120234
2011-11-12T17:50:40.27640Z,1321120240.2764 [Default:GPS:Read_GPS] Stopped
2011-11-12T17:50:40.27680Z,1321120240.2768 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T17:50:40.27690Z,1321120240.2769 [Default:GPS] Stopped
2011-11-12T17:50:40.27700Z,1321120240.277 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T17:50:40.27710Z,1321120240.2771 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T17:50:40.27720Z,1321120240.2772 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:50:40.69250Z,1321120240.6925 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T17:50:40.69260Z,1321120240.6926 [Default:CallGPS:A] Stopped
2011-11-12T17:50:40.69270Z,1321120240.6927 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T17:50:40.69290Z,1321120240.6929 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T17:50:40.69300Z,1321120240.693 [Default:CallGPS] Stopped
2011-11-12T17:50:40.69310Z,1321120240.6931 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T17:51:00.83560Z,1321120260.8356 [NAL9601](INFO): Powering down
2011-11-12T17:55:30.84080Z,1321120530.8408 [Default:CallIridium] Running Loop=1
2011-11-12T17:55:30.84100Z,1321120530.841 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T17:55:30.84120Z,1321120530.8412 [Default:CallIridium:A] Running Loop=1
2011-11-12T17:55:30.84130Z,1321120530.8413 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T17:55:30.84140Z,1321120530.8414 [Default:CallGPS] Running Loop=1
2011-11-12T17:55:30.84150Z,1321120530.8415 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T17:55:30.84170Z,1321120530.8417 [Default:CallGPS:A] Running Loop=1
2011-11-12T17:55:30.84180Z,1321120530.8418 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T17:55:35.84520Z,1321120535.8452 [Default:Iridium] Running Loop=1
2011-11-12T17:55:35.84540Z,1321120535.8454 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T17:55:35.84550Z,1321120535.8455 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T17:55:35.84550Z,1321120535.8455 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:55:35.84570Z,1321120535.8457 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T17:55:35.84580Z,1321120535.8458 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:55:35.84640Z,1321120535.8464 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T17:55:35.84650Z,1321120535.8465 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:55:35.84660Z,1321120535.8466 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T17:55:35.84690Z,1321120535.8469 [Default:GPS] Running Loop=1
2011-11-12T17:55:35.84710Z,1321120535.8471 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T17:55:35.84720Z,1321120535.8472 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T17:55:35.84730Z,1321120535.8473 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T17:55:35.84750Z,1321120535.8475 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T17:55:35.84750Z,1321120535.8475 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T17:55:35.84810Z,1321120535.8481 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T17:55:35.84820Z,1321120535.8482 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T17:55:35.84840Z,1321120535.8484 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T17:55:36.45570Z,1321120536.4557 [NAL9601](INFO): Powering up
2011-11-12T17:56:42.16770Z,1321120602.1677 [NAL9601](INFO): NAL9601 initialized
2011-11-12T17:56:58.75820Z,1321120618.7582 [NAL9601](INFO): SBD MO Status=1, MOMSN=37329, MT Status=0, MTMSN=0
2011-11-12T17:56:58.93160Z,1321120618.9316 [NAL9601](INFO): Sent 129 bytes from file Logs/20111112T173436/shore0004.lzma
2011-11-12T17:56:58.93180Z,1321120618.9318 [NAL9601](INFO): Packets left to send: 0
2011-11-12T17:56:58.93300Z,1321120618.933 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2011-11-12T17:57:02.75820Z,1321120622.7582 [NAL9601](INFO): SBD MO Status=0, MOMSN=37330, MT Status=0, MTMSN=0
2011-11-12T17:57:02.93520Z,1321120622.9352 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T17:57:02.93560Z,1321120622.9356 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T17:57:02.93570Z,1321120622.9357 [Default:Iridium] Stopped
2011-11-12T17:57:02.93580Z,1321120622.9358 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T17:57:02.93590Z,1321120622.9359 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T17:57:02.93600Z,1321120622.936 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:57:03.17380Z,1321120623.1738 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T17:57:03.17380Z,1321120623.1738 [Default:CallIridium:A] Stopped
2011-11-12T17:57:03.17400Z,1321120623.174 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T17:57:03.17420Z,1321120623.1742 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T17:57:03.17430Z,1321120623.1743 [Default:CallIridium] Stopped
2011-11-12T17:57:03.17440Z,1321120623.1744 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T17:57:41.96740Z,1321120661.9674 [NAL9601](IMPORTANT): GPS fix at: 1321120656
2011-11-12T17:57:41.98030Z,1321120661.9803 [Default:GPS:Read_GPS] Stopped
2011-11-12T17:57:41.98070Z,1321120661.9807 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T17:57:41.98070Z,1321120661.9807 [Default:GPS] Stopped
2011-11-12T17:57:41.98090Z,1321120661.9809 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T17:57:41.98100Z,1321120661.981 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T17:57:41.98100Z,1321120661.981 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T17:57:42.36800Z,1321120662.368 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T17:57:42.36810Z,1321120662.3681 [Default:CallGPS:A] Stopped
2011-11-12T17:57:42.36820Z,1321120662.3682 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T17:57:42.36840Z,1321120662.3684 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T17:57:42.36850Z,1321120662.3685 [Default:CallGPS] Stopped
2011-11-12T17:57:42.36860Z,1321120662.3686 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T17:58:02.58240Z,1321120682.5824 [NAL9601](INFO): Powering down
2011-11-12T18:02:07.59350Z,1321120927.5935 [Default:CallIridium] Running Loop=1
2011-11-12T18:02:07.59360Z,1321120927.5936 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T18:02:07.59380Z,1321120927.5938 [Default:CallIridium:A] Running Loop=1
2011-11-12T18:02:07.59390Z,1321120927.5939 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T18:02:07.59410Z,1321120927.5941 [Default:CallGPS] Running Loop=1
2011-11-12T18:02:07.59420Z,1321120927.5942 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T18:02:07.59430Z,1321120927.5943 [Default:CallGPS:A] Running Loop=1
2011-11-12T18:02:07.59440Z,1321120927.5944 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T18:02:12.49290Z,1321120932.4929 [Default:Iridium] Running Loop=1
2011-11-12T18:02:12.49310Z,1321120932.4931 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T18:02:12.49320Z,1321120932.4932 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T18:02:12.49320Z,1321120932.4932 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T18:02:12.49340Z,1321120932.4934 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T18:02:12.49350Z,1321120932.4935 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T18:02:12.49410Z,1321120932.4941 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T18:02:12.49420Z,1321120932.4942 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:02:12.49440Z,1321120932.4944 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T18:02:12.49460Z,1321120932.4946 [Default:GPS] Running Loop=1
2011-11-12T18:02:12.49480Z,1321120932.4948 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T18:02:12.49480Z,1321120932.4948 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T18:02:12.49490Z,1321120932.4949 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T18:02:12.49510Z,1321120932.4951 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T18:02:12.49520Z,1321120932.4952 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T18:02:12.49580Z,1321120932.4958 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T18:02:12.49590Z,1321120932.4959 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:02:12.49600Z,1321120932.496 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T18:02:13.25450Z,1321120933.2545 [NAL9601](INFO): Powering up
2011-11-12T18:03:18.86370Z,1321120998.8637 [NAL9601](INFO): NAL9601 initialized
2011-11-12T18:03:34.22500Z,1321121014.225 [NAL9601](INFO): SBD MO Status=1, MOMSN=37331, MT Status=0, MTMSN=0
2011-11-12T18:03:34.43160Z,1321121014.4316 [NAL9601](INFO): Sent 127 bytes from file Logs/20111112T173436/shore0005.lzma
2011-11-12T18:03:34.43180Z,1321121014.4318 [NAL9601](INFO): Packets left to send: 0
2011-11-12T18:03:34.43290Z,1321121014.4329 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2011-11-12T18:03:43.43000Z,1321121023.43 [NAL9601](INFO): SBD MO Status=0, MOMSN=37332, MT Status=0, MTMSN=0
2011-11-12T18:03:43.63680Z,1321121023.6368 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T18:03:43.63720Z,1321121023.6372 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T18:03:43.63730Z,1321121023.6373 [Default:Iridium] Stopped
2011-11-12T18:03:43.63740Z,1321121023.6374 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T18:03:43.63750Z,1321121023.6375 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T18:03:43.63750Z,1321121023.6375 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:03:43.85760Z,1321121023.8576 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T18:03:43.85770Z,1321121023.8577 [Default:CallIridium:A] Stopped
2011-11-12T18:03:43.85780Z,1321121023.8578 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T18:03:43.85800Z,1321121023.858 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T18:03:43.85810Z,1321121023.8581 [Default:CallIridium] Stopped
2011-11-12T18:03:43.85820Z,1321121023.8582 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T18:03:48.63540Z,1321121028.6354 [NAL9601](IMPORTANT): GPS fix at: 1321121024
2011-11-12T18:03:48.64790Z,1321121028.6479 [Default:GPS:Read_GPS] Stopped
2011-11-12T18:03:48.64830Z,1321121028.6483 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T18:03:48.64840Z,1321121028.6484 [Default:GPS] Stopped
2011-11-12T18:03:48.64850Z,1321121028.6485 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T18:03:48.64860Z,1321121028.6486 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T18:03:48.64860Z,1321121028.6486 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:03:49.04100Z,1321121029.041 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T18:03:49.04110Z,1321121029.0411 [Default:CallGPS:A] Stopped
2011-11-12T18:03:49.04120Z,1321121029.0412 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T18:03:49.04140Z,1321121029.0414 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T18:03:49.04150Z,1321121029.0415 [Default:CallGPS] Stopped
2011-11-12T18:03:49.04160Z,1321121029.0416 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T18:04:09.16020Z,1321121049.1602 [NAL9601](INFO): Powering down
2011-11-12T18:08:44.16510Z,1321121324.1651 [Default:CallIridium] Running Loop=1
2011-11-12T18:08:44.16530Z,1321121324.1653 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T18:08:44.16540Z,1321121324.1654 [Default:CallIridium:A] Running Loop=1
2011-11-12T18:08:44.16550Z,1321121324.1655 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T18:08:44.16570Z,1321121324.1657 [Default:CallGPS] Running Loop=1
2011-11-12T18:08:44.16580Z,1321121324.1658 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T18:08:44.16590Z,1321121324.1659 [Default:CallGPS:A] Running Loop=1
2011-11-12T18:08:44.16600Z,1321121324.166 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T18:08:49.12820Z,1321121329.1282 [Batt_Ocean_Server](FAULT): Over Temperature Alarm! Battery Bank #0 STATUS: 5911
2011-11-12T18:08:49.12850Z,1321121329.1285 [Batt_Ocean_Server](FAULT): Not Initialized - Battery Bank #0 STATUS: 5911
2011-11-12T18:08:49.20960Z,1321121329.2096 [Default:Iridium] Running Loop=1
2011-11-12T18:08:49.20980Z,1321121329.2098 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T18:08:49.20990Z,1321121329.2099 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T18:08:49.20990Z,1321121329.2099 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T18:08:49.21010Z,1321121329.2101 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T18:08:49.21020Z,1321121329.2102 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T18:08:49.21080Z,1321121329.2108 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T18:08:49.21080Z,1321121329.2108 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:08:49.21100Z,1321121329.211 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T18:08:49.21140Z,1321121329.2114 [Default:GPS] Running Loop=1
2011-11-12T18:08:49.21150Z,1321121329.2115 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T18:08:49.21160Z,1321121329.2116 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T18:08:49.21170Z,1321121329.2117 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T18:08:49.21180Z,1321121329.2118 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T18:08:49.21190Z,1321121329.2119 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T18:08:49.21240Z,1321121329.2124 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T18:08:49.21250Z,1321121329.2125 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:08:49.21260Z,1321121329.2126 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T18:08:49.82870Z,1321121329.8287 [NAL9601](INFO): Powering up
2011-11-12T18:09:55.53970Z,1321121395.5397 [NAL9601](INFO): NAL9601 initialized
2011-11-12T18:10:21.76950Z,1321121421.7695 [Batt_Ocean_Server](FAULT): Over Temperature Alarm! Battery Bank #7 STATUS: 5911
2011-11-12T18:10:21.76980Z,1321121421.7698 [Batt_Ocean_Server](FAULT): Not Initialized - Battery Bank #7 STATUS: 5911
2011-11-12T18:10:22.13790Z,1321121422.1379 [NAL9601](INFO): SBD MO Status=1, MOMSN=37333, MT Status=0, MTMSN=0
2011-11-12T18:10:22.28760Z,1321121422.2876 [NAL9601](INFO): Sent 243 bytes from file Logs/20111112T173436/shore0006.lzma
2011-11-12T18:10:22.28780Z,1321121422.2878 [NAL9601](INFO): Packets left to send: 0
2011-11-12T18:10:22.28890Z,1321121422.2889 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2011-11-12T18:10:30.93810Z,1321121430.9381 [NAL9601](INFO): SBD MO Status=0, MOMSN=37334, MT Status=0, MTMSN=0
2011-11-12T18:10:31.08340Z,1321121431.0834 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T18:10:31.08380Z,1321121431.0838 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T18:10:31.08390Z,1321121431.0839 [Default:Iridium] Stopped
2011-11-12T18:10:31.08400Z,1321121431.084 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T18:10:31.08410Z,1321121431.0841 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T18:10:31.08420Z,1321121431.0842 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:10:31.34300Z,1321121431.343 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T18:10:31.34300Z,1321121431.343 [Default:CallIridium:A] Stopped
2011-11-12T18:10:31.34320Z,1321121431.3432 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T18:10:31.34340Z,1321121431.3434 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T18:10:31.34350Z,1321121431.3435 [Default:CallIridium] Stopped
2011-11-12T18:10:31.34370Z,1321121431.3437 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T18:11:04.13950Z,1321121464.1395 [NAL9601](IMPORTANT): GPS fix at: 1321121460
2011-11-12T18:11:04.15200Z,1321121464.152 [Default:GPS:Read_GPS] Stopped
2011-11-12T18:11:04.15240Z,1321121464.1524 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T18:11:04.15250Z,1321121464.1525 [Default:GPS] Stopped
2011-11-12T18:11:04.15260Z,1321121464.1526 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T18:11:04.15270Z,1321121464.1527 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T18:11:04.15270Z,1321121464.1527 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:11:04.54370Z,1321121464.5437 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T18:11:04.54380Z,1321121464.5438 [Default:CallGPS:A] Stopped
2011-11-12T18:11:04.54400Z,1321121464.544 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T18:11:04.54410Z,1321121464.5441 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T18:11:04.54420Z,1321121464.5442 [Default:CallGPS] Stopped
2011-11-12T18:11:04.54430Z,1321121464.5443 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T18:11:24.71840Z,1321121484.7184 [NAL9601](INFO): Powering down
2011-11-12T18:12:24.68370Z,1321121544.6837 [Batt_Ocean_Server](FAULT): Over Temperature Alarm! Battery Bank #9 STATUS: 5911
2011-11-12T18:12:24.68400Z,1321121544.684 [Batt_Ocean_Server](FAULT): Not Initialized - Battery Bank #9 STATUS: 5911
2011-11-12T18:15:34.71940Z,1321121734.7194 [Default:CallIridium] Running Loop=1
2011-11-12T18:15:34.71960Z,1321121734.7196 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T18:15:34.71980Z,1321121734.7198 [Default:CallIridium:A] Running Loop=1
2011-11-12T18:15:34.71990Z,1321121734.7199 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T18:15:34.72000Z,1321121734.72 [Default:CallGPS] Running Loop=1
2011-11-12T18:15:34.72020Z,1321121734.7202 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T18:15:34.72030Z,1321121734.7203 [Default:CallGPS:A] Running Loop=1
2011-11-12T18:15:34.72040Z,1321121734.7204 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T18:15:39.70450Z,1321121739.7045 [Default:Iridium] Running Loop=1
2011-11-12T18:15:39.70470Z,1321121739.7047 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T18:15:39.70480Z,1321121739.7048 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T18:15:39.70490Z,1321121739.7049 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T18:15:39.70500Z,1321121739.705 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T18:15:39.70510Z,1321121739.7051 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T18:15:39.70580Z,1321121739.7058 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T18:15:39.70590Z,1321121739.7059 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:15:39.70600Z,1321121739.706 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T18:15:39.70630Z,1321121739.7063 [Default:GPS] Running Loop=1
2011-11-12T18:15:39.70650Z,1321121739.7065 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T18:15:39.70660Z,1321121739.7066 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T18:15:39.70660Z,1321121739.7066 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T18:15:39.70680Z,1321121739.7068 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T18:15:39.70680Z,1321121739.7068 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T18:15:39.70770Z,1321121739.7077 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T18:15:39.70780Z,1321121739.7078 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:15:39.70790Z,1321121739.7079 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T18:15:40.33180Z,1321121740.3318 [NAL9601](INFO): Powering up
2011-11-12T18:16:46.04370Z,1321121806.0437 [NAL9601](INFO): NAL9601 initialized
2011-11-12T18:17:20.19400Z,1321121840.194 [NAL9601](IMPORTANT): SBD MO Status=2, MOMSN=37335, MT Status=1, MTMSN=3153
2011-11-12T18:17:20.19420Z,1321121840.1942 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:17:32.44610Z,1321121852.4461 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=37335, MT Status=1, MTMSN=3153
2011-11-12T18:17:32.65960Z,1321121852.6596 [NAL9601](INFO): Sent 233 bytes from file Logs/20111112T173436/shore0007.lzma
2011-11-12T18:17:32.65990Z,1321121852.6599 [NAL9601](INFO): Packets left to send: 0
2011-11-12T18:17:32.66090Z,1321121852.6609 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2011-11-12T18:17:32.97710Z,1321121852.9771 [NAL9601](INFO): Received command:run Transport/transit_3km.xml
2011-11-12T18:17:32.99440Z,1321121852.9944 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_3km.xml
2011-11-12T18:17:32.99470Z,1321121852.9947 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2011-11-12T18:17:33.03650Z,1321121853.0365 [MissionManager](INFO): DefineArg transit_3km.ApproachDepth = 10 m
2011-11-12T18:17:33.03930Z,1321121853.0393 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lat = 36.806966 arcdeg
2011-11-12T18:17:33.04220Z,1321121853.0422 [MissionManager](INFO): DefineArg transit_3km.Wpt1Lon = -121.824326 arcdeg
2011-11-12T18:17:33.04910Z,1321121853.0491 [MissionManager](INFO): DefineArg transit_3km.Speed = 1 m/s
2011-11-12T18:17:33.05090Z,1321121853.0509 [transit_3km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2011-11-12T18:17:33.05820Z,1321121853.0582 [transit_3km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2011-11-12T18:17:33.07000Z,1321121853.07 [transit_3km:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2011-11-12T18:17:33.08620Z,1321121853.0862 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2011-11-12T18:17:33.09230Z,1321121853.0923 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2011-11-12T18:17:33.12830Z,1321121853.1283 [transit_3km:WaypointOne:A.Pitch](DEBUG): Construct.
2011-11-12T18:17:33.14000Z,1321121853.14 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2011-11-12T18:17:33.16750Z,1321121853.1675 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2011-11-12T18:17:33.17730Z,1321121853.1773 [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="transit_3km">

<!-- To be used within 6km of waypoint. No science collection.  -->

    <DefineArg Name="ApproachDepth"><Units:meter /><Value>10.0</Value></DefineArg>

    <DefineArg Name="Wpt1Lat"><Units:degree /><Value>36.806966</Value></DefineArg>

    <DefineArg Name="Wpt1Lon"><Units:degree /><Value>-121.824326</Value></DefineArg>

    <DefineArg Name="Speed"><Units:meter_per_second/><Value>1</Value></DefineArg>

    <Timeout Duration="P130M" />

    <Guidance:AltitudeEnvelope RunIn="Parallel">
        <Setting><Guidance:AltitudeEnvelope.minAltitude /><Units:meter /><Value>7</Value></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.maxDepth /><Units:meter /><Value>20</Value></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:OffshoreEnvelope RunIn="Parallel">
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Units:kilometer/><Value>1</Value></Setting>
    </Guidance:OffshoreEnvelope>

    <Aggregate Id="SURFACECOMMS">

        <Guidance:GoToSurface RunIn="Progression" />

        <Aggregate>

            <Preemptive><True /></Preemptive>

            <Guidance:SetSpeed RunIn="Parallel">
                <Setting><Guidance:SetSpeed.speed /><Units:meter_per_second /><Value>0</Value></Setting>
            </Guidance:SetSpeed>

            <ReadDatum><Universal:latitude_fix />
            </ReadDatum>

            <ReadDatum>
                <Timeout Duration="P30M">
                    <Assign Id="TouchComms"><Universal:platform_communications/></Assign>
                </Timeout><Universal:platform_communications />
            </ReadDatum>

            <ReadDatum><Universal:latitude_fix />
            </ReadDatum>

        </Aggregate>

    </Aggregate>

<!-- GPS Update.  Don't go too long w/o a GPS fix. -->

    <Aggregate Id="NeedComms">

        <When>
            <Elapsed><Universal:time_fix /></Elapsed>
            <Gt><Units:minute/><Value>35</Value></Gt>
        </When>

        <Call Id="NEEDCOMMS" RefId="SURFACECOMMS" />

    </Aggregate>

    <Aggregate Id="WaypointOne">

<!-- Go to Wpt1 -->

        <Guidance:Pitch RunIn="Parallel">
            <Setting><Guidance:Pitch.depth /><Arg Name="ApproachDepth" /></Setting>
        </Guidance:Pitch>

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.speed/><Arg Name="Speed"/></Setting>
        </Guidance:SetSpeed>

        <Guidance:Waypoint Id="WaypointW1" RunIn="Sequence">
            <Setting><Guidance:Waypoint.latitude /><Arg Name="Wpt1Lat" /></Setting>
            <Setting><Guidance:Waypoint.longitude /><Arg Name="Wpt1Lon" /></Setting>
        </Guidance:Waypoint>

        <Call Id="PHONEHOMEWPT1" RefId="SURFACECOMMS" />

    </Aggregate>

</Mission>


2011-11-12T18:17:33.17780Z,1321121853.1778 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_3km.xml
2011-11-12T18:17:33.28290Z,1321121853.2829 [Default] Stopped
2011-11-12T18:17:33.28300Z,1321121853.283 [Default](INFO): Aggregate::uninitialize Default
2011-11-12T18:17:33.28580Z,1321121853.2858 [Default:GPS] Stopped
2011-11-12T18:17:33.28600Z,1321121853.286 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T18:17:33.28600Z,1321121853.286 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T18:17:33.28610Z,1321121853.2861 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:17:33.28620Z,1321121853.2862 [Default:GPS:Read_GPS] Stopped
2011-11-12T18:17:33.28630Z,1321121853.2863 [Default:Iridium] Stopped
2011-11-12T18:17:33.28640Z,1321121853.2864 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T18:17:33.28650Z,1321121853.2865 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T18:17:33.28650Z,1321121853.2865 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:17:33.28660Z,1321121853.2866 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T18:17:33.28670Z,1321121853.2867 [Default:CallGPS] Stopped
2011-11-12T18:17:33.28680Z,1321121853.2868 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T18:17:33.28690Z,1321121853.2869 [Default:CallGPS:A] Stopped
2011-11-12T18:17:33.28700Z,1321121853.287 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T18:17:33.28710Z,1321121853.2871 [Default:CallIridium] Stopped
2011-11-12T18:17:33.28720Z,1321121853.2872 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T18:17:33.28730Z,1321121853.2873 [Default:CallIridium:A] Stopped
2011-11-12T18:17:33.28740Z,1321121853.2874 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T18:17:33.28750Z,1321121853.2875 [Default:E.SetSpeed] Stopped
2011-11-12T18:17:33.28760Z,1321121853.2876 [Default:E.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:17:33.28760Z,1321121853.2876 [Default:F.GoToSurface] Stopped
2011-11-12T18:17:33.28770Z,1321121853.2877 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:17:33.28780Z,1321121853.2878 [Default:G.Wait] Stopped
2011-11-12T18:17:33.28790Z,1321121853.2879 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T18:17:33.28800Z,1321121853.288 [MissionManager](IMPORTANT): Started mission transit_3km
2011-11-12T18:17:33.28810Z,1321121853.2881 [transit_3km] Running Loop=1
2011-11-12T18:17:33.28820Z,1321121853.2882 [transit_3km](INFO): Aggregate::initialize transit_3km
2011-11-12T18:17:33.28830Z,1321121853.2883 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2011-11-12T18:17:33.28840Z,1321121853.2884 [transit_3km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2011-11-12T18:17:33.28860Z,1321121853.2886 [transit_3km:B.DepthEnvelope] Running Loop=1
2011-11-12T18:17:33.28870Z,1321121853.2887 [transit_3km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2011-11-12T18:17:33.29010Z,1321121853.2901 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2011-11-12T18:17:33.29020Z,1321121853.2902 [transit_3km:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2011-11-12T18:17:33.29610Z,1321121853.2961 [transit_3km:C.OffshoreEnvelope](DEBUG): Opened Resources/cencalShoreDist.nc
2011-11-12T18:17:33.30820Z,1321121853.3082 [transit_3km:SURFACECOMMS] Running Loop=1
2011-11-12T18:17:33.30840Z,1321121853.3084 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2011-11-12T18:17:33.30850Z,1321121853.3085 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2011-11-12T18:17:33.30850Z,1321121853.3085 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T18:17:33.31370Z,1321121853.3137 [transit_3km:SURFACECOMMS:B] Running Loop=1
2011-11-12T18:17:33.31380Z,1321121853.3138 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2011-11-12T18:17:33.31390Z,1321121853.3139 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2011-11-12T18:17:33.31400Z,1321121853.314 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2011-11-12T18:17:33.31420Z,1321121853.3142 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2011-11-12T18:17:33.31430Z,1321121853.3143 [transit_3km:C.OffshoreEnvelope] Running Loop=1
2011-11-12T18:17:33.32720Z,1321121853.3272 [transit_3km:B.DepthEnvelope] Running Loop=1
2011-11-12T18:17:33.33190Z,1321121853.3319 [transit_3km:A.AltitudeEnvelope] Running Loop=1
2011-11-12T18:17:33.68970Z,1321121853.6897 [transit_3km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-11-12T18:17:33.69090Z,1321121853.6909 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2011-11-12T18:17:34.10040Z,1321121854.1004 [NAL9601](IMPORTANT): GPS fix at: 1321121850
2011-11-12T18:17:34.11290Z,1321121854.1129 [transit_3km:SURFACECOMMS:B:B] Stopped
2011-11-12T18:17:34.11300Z,1321121854.113 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2011-11-12T18:17:34.48880Z,1321121854.4888 [transit_3km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-11-12T18:17:42.01810Z,1321121862.0181 [NAL9601](INFO): SBD MO Status=0, MOMSN=37336, MT Status=0, MTMSN=0
2011-11-12T18:17:49.99360Z,1321121869.9936 [Radio_Freewave](INFO): Powering down
2011-11-12T18:17:59.04210Z,1321121879.0421 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:17:59.04230Z,1321121879.0423 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:18:25.84820Z,1321121905.8482 [Radio_Freewave](INFO): Powering up
2011-11-12T18:18:40.86580Z,1321121920.8658 [Radio_Freewave](INFO): Powering down
2011-11-12T18:18:44.89840Z,1321121924.8984 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:18:44.89860Z,1321121924.8986 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:19:33.62420Z,1321121973.6242 [Radio_Freewave](INFO): Powering up
2011-11-12T18:19:43.63600Z,1321121983.636 [Radio_Freewave](INFO): Powering down
2011-11-12T18:19:49.19400Z,1321121989.194 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:19:49.19420Z,1321121989.1942 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:20:33.26970Z,1321122033.2697 [Radio_Freewave](INFO): Powering up
2011-11-12T18:20:40.91170Z,1321122040.9117 [Radio_Freewave](INFO): Powering down
2011-11-12T18:21:33.85620Z,1321122093.8562 [Radio_Freewave](INFO): Powering up
2011-11-12T18:21:43.54280Z,1321122103.5428 [Radio_Freewave](INFO): Powering down
2011-11-12T18:21:49.15480Z,1321122109.1548 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:21:49.15500Z,1321122109.155 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:22:32.48970Z,1321122152.4897 [Radio_Freewave](INFO): Powering up
2011-11-12T18:22:40.88560Z,1321122160.8856 [Radio_Freewave](INFO): Powering down
2011-11-12T18:22:52.65450Z,1321122172.6545 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:22:52.65480Z,1321122172.6548 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:23:35.22070Z,1321122215.2207 [Radio_Freewave](INFO): Powering up
2011-11-12T18:23:44.18510Z,1321122224.1851 [Radio_Freewave](INFO): Powering down
2011-11-12T18:23:55.76190Z,1321122235.7619 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:23:55.76220Z,1321122235.7622 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:24:31.29260Z,1321122271.2926 [Radio_Freewave](INFO): Powering up
2011-11-12T18:24:40.59700Z,1321122280.597 [Radio_Freewave](INFO): Powering down
2011-11-12T18:24:52.58030Z,1321122292.5803 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:24:52.58050Z,1321122292.5805 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:25:29.69870Z,1321122329.6987 [Radio_Freewave](INFO): Powering up
2011-11-12T18:25:44.20570Z,1321122344.2057 [Radio_Freewave](INFO): Powering down
2011-11-12T18:25:47.00200Z,1321122347.002 [NAL9601](INFO): SBD MO Status=2, MOMSN=37337, MT Status=2, MTMSN=0
2011-11-12T18:25:47.00220Z,1321122347.0022 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T18:26:13.98850Z,1321122373.9885 [Radio_Freewave](INFO): Powering up
2011-11-12T18:26:49.32620Z,1321122409.3262 [NAL9601](INFO): SBD MO Status=1, MOMSN=37337, MT Status=0, MTMSN=0
2011-11-12T18:26:49.49560Z,1321122409.4956 [NAL9601](INFO): Sent 332 bytes from file Logs/20111112T173436/shore0008.lzma
2011-11-12T18:26:49.49580Z,1321122409.4958 [NAL9601](INFO): Packets left to send: 1
2011-11-12T18:26:49.49690Z,1321122409.4969 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2011-11-12T18:27:05.84990Z,1321122425.8499 [NAL9601](INFO): SBD MO Status=1, MOMSN=37338, MT Status=0, MTMSN=0
2011-11-12T18:27:05.96760Z,1321122425.9676 [NAL9601](INFO): Sent 82 bytes from file Logs/20111112T173436/shore0008.lzma
2011-11-12T18:27:05.96780Z,1321122425.9678 [NAL9601](INFO): Packets left to send: 0
2011-11-12T18:27:05.96890Z,1321122425.9689 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2011-11-12T18:27:17.09840Z,1321122437.0984 [NAL9601](INFO): SBD MO Status=0, MOMSN=37339, MT Status=0, MTMSN=0
2011-11-12T18:27:17.26360Z,1321122437.2636 [transit_3km:SURFACECOMMS:B:C] Stopped
2011-11-12T18:27:17.26370Z,1321122437.2637 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2011-11-12T18:27:17.45600Z,1321122437.456 [transit_3km:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2011-11-12T18:27:19.46360Z,1321122439.4636 [NAL9601](IMPORTANT): GPS fix at: 1321122437
2011-11-12T18:27:19.47610Z,1321122439.4761 [transit_3km:SURFACECOMMS:B:D] Stopped
2011-11-12T18:27:19.47660Z,1321122439.4766 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2011-11-12T18:27:19.47660Z,1321122439.4766 [transit_3km:SURFACECOMMS:B] Stopped
2011-11-12T18:27:19.47680Z,1321122439.4768 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2011-11-12T18:27:19.47680Z,1321122439.4768 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2011-11-12T18:27:19.47690Z,1321122439.4769 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T18:27:19.47730Z,1321122439.4773 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2011-11-12T18:27:19.47740Z,1321122439.4774 [transit_3km:SURFACECOMMS] Stopped
2011-11-12T18:27:19.47760Z,1321122439.4776 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2011-11-12T18:27:19.47760Z,1321122439.4776 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2011-11-12T18:27:19.47770Z,1321122439.4777 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T18:27:19.47780Z,1321122439.4778 [transit_3km:WaypointOne] Running Loop=1
2011-11-12T18:27:19.47800Z,1321122439.478 [transit_3km:WaypointOne](INFO): Aggregate::initialize transit_3km:WaypointOne
2011-11-12T18:27:19.47810Z,1321122439.4781 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2011-11-12T18:27:19.47810Z,1321122439.4781 [transit_3km:WaypointOne:A.Pitch](DEBUG): Initialize.
2011-11-12T18:27:19.47830Z,1321122439.4783 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2011-11-12T18:27:19.47840Z,1321122439.4784 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2011-11-12T18:27:19.47870Z,1321122439.4787 [transit_3km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2011-11-12T18:27:19.47870Z,1321122439.4787 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2011-11-12T18:27:19.86560Z,1321122439.8656 [transit_3km:WaypointOne:B.SetSpeed] Running Loop=1
2011-11-12T18:27:19.86960Z,1321122439.8696 [transit_3km:WaypointOne:A.Pitch] Running Loop=1
2011-11-12T18:27:25.88070Z,1321122445.8807 [NAL9601](INFO): Powering down
2011-11-12T18:28:26.21400Z,1321122506.214 [Radio_Freewave](INFO): Powering down
2011-11-12T18:39:44.81690Z,1321123184.8169 [Batt_Ocean_Server](FAULT): Over Temperature Alarm! Battery Bank #7 STATUS: 5911
2011-11-12T18:39:44.81720Z,1321123184.8172 [Batt_Ocean_Server](FAULT): Not Initialized - Battery Bank #7 STATUS: 5911
2011-11-12T18:58:46.22470Z,1321124326.2247 [transit_3km:WaypointOne:WaypointW1.Waypoint](INFO): Reached Waypoint: 36.806966,-121.824326
2011-11-12T18:58:46.22500Z,1321124326.225 [transit_3km:WaypointOne:WaypointW1.Waypoint] Stopped
2011-11-12T18:58:46.22510Z,1321124326.2251 [transit_3km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2011-11-12T18:58:46.22520Z,1321124326.2252 [transit_3km:WaypointOne:PHONEHOMEWPT1] Running Loop=1
2011-11-12T18:58:46.22540Z,1321124326.2254 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::initialize transit_3km:WaypointOne:PHONEHOMEWPT1
2011-11-12T18:58:46.66030Z,1321124326.6603 [transit_3km:SURFACECOMMS] Running Loop=1
2011-11-12T18:58:46.66050Z,1321124326.6605 [transit_3km:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:SURFACECOMMS
2011-11-12T18:58:46.66060Z,1321124326.6606 [transit_3km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2011-11-12T18:58:46.66060Z,1321124326.6606 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:00:02.43820Z,1321124402.4382 [Batt_Ocean_Server](FAULT): Over Temperature Alarm! Battery Bank #11 STATUS: 5911
2011-11-12T19:00:02.43850Z,1321124402.4385 [Batt_Ocean_Server](FAULT): Not Initialized - Battery Bank #11 STATUS: 5911
2011-11-12T19:01:23.30970Z,1321124483.3097 [Radio_Freewave](INFO): Powering up
2011-11-12T19:01:23.31850Z,1321124483.3185 [transit_3km:SURFACECOMMS:B] Running Loop=1
2011-11-12T19:01:23.31860Z,1321124483.3186 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:SURFACECOMMS:B
2011-11-12T19:01:23.31870Z,1321124483.3187 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2011-11-12T19:01:23.31880Z,1321124483.3188 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:01:23.31900Z,1321124483.319 [transit_3km:SURFACECOMMS:B:B] Running Loop=1
2011-11-12T19:01:24.10870Z,1321124484.1087 [NAL9601](INFO): Powering up
2011-11-12T19:02:29.61970Z,1321124549.6197 [NAL9601](INFO): NAL9601 initialized
2011-11-12T19:02:30.77160Z,1321124550.7716 [NAL9601](IMPORTANT): GPS fix at: 1321124551
2011-11-12T19:02:30.78390Z,1321124550.7839 [transit_3km:SURFACECOMMS:B:B] Stopped
2011-11-12T19:02:30.78410Z,1321124550.7841 [transit_3km:SURFACECOMMS:B:C] Running Loop=1
2011-11-12T19:02:58.51000Z,1321124578.51 [NAL9601](INFO): SBD MO Status=1, MOMSN=37340, MT Status=0, MTMSN=0
2011-11-12T19:02:58.66360Z,1321124578.6636 [NAL9601](INFO): Sent 332 bytes from file Logs/20111112T173436/shore0009.lzma
2011-11-12T19:02:58.66380Z,1321124578.6638 [NAL9601](INFO): Packets left to send: 2
2011-11-12T19:02:58.66490Z,1321124578.6649 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2011-11-12T19:03:28.99450Z,1321124608.9945 [NAL9601](INFO): SBD MO Status=2, MOMSN=37341, MT Status=0, MTMSN=0
2011-11-12T19:03:28.99480Z,1321124608.9948 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T19:03:58.44200Z,1321124638.442 [NAL9601](INFO): SBD MO Status=1, MOMSN=37341, MT Status=0, MTMSN=0
2011-11-12T19:03:58.57560Z,1321124638.5756 [NAL9601](INFO): Sent 332 bytes from file Logs/20111112T173436/shore0009.lzma
2011-11-12T19:03:58.57580Z,1321124638.5758 [NAL9601](INFO): Packets left to send: 1
2011-11-12T19:03:58.57680Z,1321124638.5768 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000014
2011-11-12T19:04:08.62490Z,1321124648.6249 [NAL9601](INFO): SBD MO Status=1, MOMSN=37342, MT Status=0, MTMSN=0
2011-11-12T19:04:08.75560Z,1321124648.7556 [NAL9601](INFO): Sent 174 bytes from file Logs/20111112T173436/shore0009.lzma
2011-11-12T19:04:08.75580Z,1321124648.7558 [NAL9601](INFO): Packets left to send: 0
2011-11-12T19:04:08.75690Z,1321124648.7569 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000015
2011-11-12T19:04:24.17390Z,1321124664.1739 [NAL9601](INFO): SBD MO Status=2, MOMSN=37343, MT Status=2, MTMSN=0
2011-11-12T19:04:24.17420Z,1321124664.1742 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T19:04:42.38210Z,1321124682.3821 [NAL9601](INFO): SBD MO Status=0, MOMSN=37343, MT Status=0, MTMSN=0
2011-11-12T19:04:42.51570Z,1321124682.5157 [transit_3km:SURFACECOMMS:B:C] Stopped
2011-11-12T19:04:42.51590Z,1321124682.5159 [transit_3km:SURFACECOMMS:B:D] Running Loop=1
2011-11-12T19:04:44.83570Z,1321124684.8357 [NAL9601](IMPORTANT): GPS fix at: 1321124685
2011-11-12T19:04:44.84820Z,1321124684.8482 [transit_3km:SURFACECOMMS:B:D] Stopped
2011-11-12T19:04:44.84860Z,1321124684.8486 [transit_3km:SURFACECOMMS:B](INFO): Completed transit_3km:SURFACECOMMS:B
2011-11-12T19:04:44.84870Z,1321124684.8487 [transit_3km:SURFACECOMMS:B] Stopped
2011-11-12T19:04:44.84880Z,1321124684.8488 [transit_3km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS:B
2011-11-12T19:04:44.84890Z,1321124684.8489 [transit_3km:SURFACECOMMS:B:A.SetSpeed] Stopped
2011-11-12T19:04:44.84900Z,1321124684.849 [transit_3km:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:04:44.84950Z,1321124684.8495 [transit_3km:SURFACECOMMS](INFO): Completed transit_3km:SURFACECOMMS
2011-11-12T19:04:44.84960Z,1321124684.8496 [transit_3km:SURFACECOMMS] Stopped
2011-11-12T19:04:44.84970Z,1321124684.8497 [transit_3km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:SURFACECOMMS
2011-11-12T19:04:44.84980Z,1321124684.8498 [transit_3km:SURFACECOMMS:A.GoToSurface] Stopped
2011-11-12T19:04:44.84980Z,1321124684.8498 [transit_3km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:04:45.19320Z,1321124685.1932 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Completed transit_3km:WaypointOne:PHONEHOMEWPT1
2011-11-12T19:04:45.19330Z,1321124685.1933 [transit_3km:WaypointOne:PHONEHOMEWPT1] Stopped
2011-11-12T19:04:45.19350Z,1321124685.1935 [transit_3km:WaypointOne:PHONEHOMEWPT1](INFO): Aggregate::uninitialize transit_3km:WaypointOne:PHONEHOMEWPT1
2011-11-12T19:04:45.19430Z,1321124685.1943 [transit_3km:WaypointOne](INFO): Completed transit_3km:WaypointOne
2011-11-12T19:04:45.19440Z,1321124685.1944 [transit_3km:WaypointOne] Stopped
2011-11-12T19:04:45.19450Z,1321124685.1945 [transit_3km:WaypointOne](INFO): Aggregate::uninitialize transit_3km:WaypointOne
2011-11-12T19:04:45.19460Z,1321124685.1946 [transit_3km:WaypointOne:A.Pitch] Stopped
2011-11-12T19:04:45.19470Z,1321124685.1947 [transit_3km:WaypointOne:B.SetSpeed] Stopped
2011-11-12T19:04:45.19470Z,1321124685.1947 [transit_3km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:04:45.19600Z,1321124685.196 [transit_3km](INFO): Completed transit_3km
2011-11-12T19:04:45.19610Z,1321124685.1961 [transit_3km] Stopped
2011-11-12T19:04:45.19620Z,1321124685.1962 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2011-11-12T19:04:45.19630Z,1321124685.1963 [transit_3km:A.AltitudeEnvelope] Stopped
2011-11-12T19:04:45.19630Z,1321124685.1963 [transit_3km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2011-11-12T19:04:45.19640Z,1321124685.1964 [transit_3km:B.DepthEnvelope] Stopped
2011-11-12T19:04:45.19650Z,1321124685.1965 [transit_3km:B.DepthEnvelope](DEBUG): Uninitialize.
2011-11-12T19:04:45.19660Z,1321124685.1966 [transit_3km:C.OffshoreEnvelope] Stopped
2011-11-12T19:04:45.19660Z,1321124685.1966 [transit_3km:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2011-11-12T19:04:45.59230Z,1321124685.5923 [MissionManager](IMPORTANT): Started mission Default
2011-11-12T19:04:45.59240Z,1321124685.5924 [Default] Running Loop=1
2011-11-12T19:04:45.59250Z,1321124685.5925 [Default](INFO): Aggregate::initialize Default
2011-11-12T19:04:45.59260Z,1321124685.5926 [Default:E.SetSpeed] Running Loop=1
2011-11-12T19:04:45.59270Z,1321124685.5927 [Default:E.SetSpeed](DEBUG): Initialize.
2011-11-12T19:04:45.59280Z,1321124685.5928 [Default:F.GoToSurface] Running Loop=1
2011-11-12T19:04:45.59290Z,1321124685.5929 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:04:45.59330Z,1321124685.5933 [Default:GPS] Running Loop=1
2011-11-12T19:04:45.59350Z,1321124685.5935 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T19:04:45.59360Z,1321124685.5936 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T19:04:45.59360Z,1321124685.5936 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:04:45.59380Z,1321124685.5938 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T19:04:45.59390Z,1321124685.5939 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:04:45.59580Z,1321124685.5958 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T19:04:45.59590Z,1321124685.5959 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:04:45.59600Z,1321124685.596 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T19:04:47.98340Z,1321124687.9834 [NAL9601](IMPORTANT): GPS fix at: 1321124689
2011-11-12T19:04:47.99620Z,1321124687.9962 [Default:GPS:Read_GPS] Stopped
2011-11-12T19:04:47.99660Z,1321124687.9966 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T19:04:47.99670Z,1321124687.9967 [Default:GPS] Stopped
2011-11-12T19:04:47.99680Z,1321124687.9968 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T19:04:47.99690Z,1321124687.9969 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T19:04:47.99690Z,1321124687.9969 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:04:47.99710Z,1321124687.9971 [Default:Iridium] Running Loop=1
2011-11-12T19:04:47.99720Z,1321124687.9972 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T19:04:47.99730Z,1321124687.9973 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T19:04:47.99740Z,1321124687.9974 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:04:47.99750Z,1321124687.9975 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T19:04:47.99760Z,1321124687.9976 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:04:48.39360Z,1321124688.3936 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T19:04:48.39370Z,1321124688.3937 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:04:48.39390Z,1321124688.3939 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T19:05:07.85000Z,1321124707.85 [NAL9601](INFO): SBD MO Status=1, MOMSN=37344, MT Status=0, MTMSN=0
2011-11-12T19:05:08.06370Z,1321124708.0637 [NAL9601](INFO): Sent 187 bytes from file Logs/20111112T173436/shore0010.lzma
2011-11-12T19:05:08.06390Z,1321124708.0639 [NAL9601](INFO): Packets left to send: 0
2011-11-12T19:05:08.06500Z,1321124708.065 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000016
2011-11-12T19:05:14.65000Z,1321124714.65 [NAL9601](INFO): SBD MO Status=2, MOMSN=37345, MT Status=2, MTMSN=0
2011-11-12T19:05:14.65020Z,1321124714.6502 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T19:05:22.82100Z,1321124722.821 [NAL9601](INFO): SBD MO Status=0, MOMSN=37345, MT Status=0, MTMSN=0
2011-11-12T19:05:22.95440Z,1321124722.9544 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T19:05:22.95480Z,1321124722.9548 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T19:05:22.95480Z,1321124722.9548 [Default:Iridium] Stopped
2011-11-12T19:05:22.95500Z,1321124722.955 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T19:05:22.95500Z,1321124722.955 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T19:05:22.95530Z,1321124722.9553 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:05:22.95550Z,1321124722.9555 [Default:G.Wait] Running Loop=1
2011-11-12T19:05:22.95550Z,1321124722.9555 [Default:G.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:05:33.39700Z,1321124733.397 [NAL9601](INFO): Powering down
2011-11-12T19:10:23.41250Z,1321125023.4125 [Default:CallIridium] Running Loop=1
2011-11-12T19:10:23.41270Z,1321125023.4127 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T19:10:23.41280Z,1321125023.4128 [Default:CallIridium:A] Running Loop=1
2011-11-12T19:10:23.41290Z,1321125023.4129 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T19:10:23.41310Z,1321125023.4131 [Default:CallGPS] Running Loop=1
2011-11-12T19:10:23.41320Z,1321125023.4132 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T19:10:23.41330Z,1321125023.4133 [Default:CallGPS:A] Running Loop=1
2011-11-12T19:10:23.41350Z,1321125023.4135 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T19:10:28.41210Z,1321125028.4121 [Default:Iridium] Running Loop=1
2011-11-12T19:10:28.41220Z,1321125028.4122 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T19:10:28.41230Z,1321125028.4123 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T19:10:28.41240Z,1321125028.4124 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:10:28.41260Z,1321125028.4126 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T19:10:28.41270Z,1321125028.4127 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:10:28.41330Z,1321125028.4133 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T19:10:28.41340Z,1321125028.4134 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:10:28.41360Z,1321125028.4136 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T19:10:28.41380Z,1321125028.4138 [Default:GPS] Running Loop=1
2011-11-12T19:10:28.41400Z,1321125028.414 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T19:10:28.41400Z,1321125028.414 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T19:10:28.41410Z,1321125028.4141 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:10:28.41430Z,1321125028.4143 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T19:10:28.41430Z,1321125028.4143 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:10:28.41490Z,1321125028.4149 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T19:10:28.41500Z,1321125028.415 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:10:28.41540Z,1321125028.4154 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T19:10:29.01990Z,1321125029.0199 [NAL9601](INFO): Powering up
2011-11-12T19:11:34.73170Z,1321125094.7317 [NAL9601](INFO): NAL9601 initialized
2011-11-12T19:11:52.09810Z,1321125112.0981 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=37346, MT Status=1, MTMSN=3154
2011-11-12T19:11:52.29160Z,1321125112.2916 [NAL9601](INFO): Sent 120 bytes from file Logs/20111112T173436/shore0011.lzma
2011-11-12T19:11:52.29190Z,1321125112.2919 [NAL9601](INFO): Packets left to send: 0
2011-11-12T19:11:52.29500Z,1321125112.295 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000017
2011-11-12T19:11:52.72030Z,1321125112.7203 [NAL9601](INFO): Received command:run Maintenance/ballast_and_trim.xml
2011-11-12T19:11:52.81550Z,1321125112.8155 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2011-11-12T19:11:52.81580Z,1321125112.8158 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2011-11-12T19:11:52.88120Z,1321125112.8812 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25 m
2011-11-12T19:11:52.88600Z,1321125112.886 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25 min
2011-11-12T19:11:52.91300Z,1321125112.913 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1 m/s
2011-11-12T19:11:52.91590Z,1321125112.9159 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4 m
2011-11-12T19:11:52.91870Z,1321125112.9187 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 5 s
2011-11-12T19:11:52.92610Z,1321125112.9261 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2011-11-12T19:11:52.96940Z,1321125112.9694 [ballast_and_trim:B.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2011-11-12T19:11:52.97650Z,1321125112.9765 [ballast_and_trim:C.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2011-11-12T19:11:52.99230Z,1321125112.9923 [ballast_and_trim:D.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2011-11-12T19:11:53.02390Z,1321125113.0239 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2011-11-12T19:11:53.04570Z,1321125113.0457 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2011-11-12T19:11:53.04870Z,1321125113.0487 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2011-11-12T19:11:53.06380Z,1321125113.0638 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.5 m/s
2011-11-12T19:11:53.06700Z,1321125113.067 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30 min
2011-11-12T19:11:53.06820Z,1321125113.0682 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2011-11-12T19:11:53.09840Z,1321125113.0984 [ballast_and_trim:F.SetSpeed](DEBUG): Construct.
2011-11-12T19:11:53.10340Z,1321125113.1034 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2011-11-12T19:11:53.15330Z,1321125113.1533 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2011-11-12T19:11:53.17300Z,1321125113.173 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2011-11-12T19:11:53.18010Z,1321125113.1801 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Construct Wait.
2011-11-12T19:11:53.19600Z,1321125113.196 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2011-11-12T19:11:53.19930Z,1321125113.1993 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2011-11-12T19:11:53.20290Z,1321125113.2029 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2011-11-12T19:11:53.22320Z,1321125113.2232 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Trigger="Tethys/Trigger" 
       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/Trigger http://aosn.mbari.org/tethys/Xml/Trigger.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="ballast_and_trim">

<!-- The following arguments are input arguments -->

    <DefineArg Name="BallastDepth"><Units:meter/><Value>25.0</Value></DefineArg>

    <DefineArg Name="HoldDuration"><Units:minute/><Value>25</Value></DefineArg>

    <DefineArg Name="Speed"><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Units:meter/><Value>4.0</Value></DefineArg>

    <DefineArg Name="BuoyPeriod"><Units:second/><Value>5.0</Value></DefineArg>

    <DefineArg Name="BuoyancyDefault"><CustomUri Uri="Config/Control.buoyancyDefault"/></DefineArg>

<!-- The timeout -->

    <Timeout Duration="P90M"/>

<!-- And now the mission -->

    <Guidance:VerticalControlConfig RunIn="Parallel">
        <Setting><Guidance:VerticalControlConfig.kpPitchMass/><Units:count/><Value>0.01</Value></Setting>
        <Setting><Guidance:VerticalControlConfig.kiPitchMass/><Units:reciprocal_second/><Value>0.0015</Value></Setting>
        <Setting><Guidance:VerticalControlConfig.kdPitchMass/><Units:second/><Value>0</Value></Setting>
    </Guidance:VerticalControlConfig>

    <Guidance:AltitudeEnvelope RunIn="Parallel">
        <Setting><Guidance:AltitudeEnvelope.minAltitude/><Units:meter/><Value>7</Value></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.maxDepth/><Units:meter/><Value>52</Value></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:OffshoreEnvelope RunIn="Parallel">
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Units:kilometer/><Value>2.0</Value></Setting>
        <Setting><Guidance:OffshoreEnvelope.maxOffshore/><Units:kilometer/><Value>30.0</Value></Setting>
    </Guidance:OffshoreEnvelope>

    <Insert Filename="Insert/Surface.xml" Id="SurfaceComms" />

    <Guidance:SetSpeed>
        <While><Universal:platform_propeller_rotation_rate/>
            <Eq><Units:radian_per_second/><Value>0</Value></Eq>
        </While>
        <Setting><Guidance:SetSpeed.period/><Arg Name="BuoyPeriod"/></Setting>
    </Guidance:SetSpeed>

    <Aggregate Id="ballast">

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
        </Guidance:SetSpeed>

        <Guidance:VerticalControlConfig RunIn="Parallel">
            <Setting><Guidance:VerticalControlConfig.depthDeadband/><Arg Name="DepthDeadband"/></Setting>
        </Guidance:VerticalControlConfig>

        <Guidance:Pitch RunIn="Parallel">
            <Setting><Guidance:Pitch.depth /><Arg Name="BallastDepth" /></Setting>
        </Guidance:Pitch>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Arg Name="HoldDuration"/></Setting>
        </Guidance:Wait>

        <Aggregate Id="ReportPositions" Repeat="5" >

            <Syslog Severity="Important">Buoyancy:<Universal:platform_buoyancy_position/><Units:cubic_centimeter/>
            </Syslog>

            <Syslog Severity="Important">Mass:<Universal:platform_mass_position/><Units:centimeter/>
            </Syslog>

            <Syslog Severity="Important">Pitch:<Universal:platform_pitch_angle/><Units:degree/>
            </Syslog>

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P1M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

        <Aggregate Id="Float_Up">

            <Until><Universal:depth/>
                <Lt><Units:meter/><Value>1</Value></Lt>
            </Until>

            <Guidance:SetSpeed RunIn="Parallel">
                <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
            </Guidance:SetSpeed>

            <Guidance:Buoyancy RunIn="Parallel">
                <Setting><Guidance:Buoyancy.position /><Arg Name="BuoyancyDefault"/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P15M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

    </Aggregate>

</Mission>


2011-11-12T19:11:53.22380Z,1321125113.2238 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2011-11-12T19:11:53.35890Z,1321125113.3589 [Default] Stopped
2011-11-12T19:11:53.35920Z,1321125113.3592 [Default](INFO): Aggregate::uninitialize Default
2011-11-12T19:11:53.35920Z,1321125113.3592 [Default:GPS] Stopped
2011-11-12T19:11:53.35940Z,1321125113.3594 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T19:11:53.35950Z,1321125113.3595 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T19:11:53.35950Z,1321125113.3595 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:11:53.35960Z,1321125113.3596 [Default:GPS:Read_GPS] Stopped
2011-11-12T19:11:53.35970Z,1321125113.3597 [Default:Iridium] Stopped
2011-11-12T19:11:53.35980Z,1321125113.3598 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T19:11:53.35990Z,1321125113.3599 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T19:11:53.35990Z,1321125113.3599 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:11:53.36000Z,1321125113.36 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T19:11:53.36010Z,1321125113.3601 [Default:CallGPS] Stopped
2011-11-12T19:11:53.36020Z,1321125113.3602 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T19:11:53.36020Z,1321125113.3602 [Default:CallGPS:A] Stopped
2011-11-12T19:11:53.36040Z,1321125113.3604 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T19:11:53.36050Z,1321125113.3605 [Default:CallIridium] Stopped
2011-11-12T19:11:53.36060Z,1321125113.3606 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T19:11:53.36070Z,1321125113.3607 [Default:CallIridium:A] Stopped
2011-11-12T19:11:53.36080Z,1321125113.3608 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T19:11:53.36090Z,1321125113.3609 [Default:E.SetSpeed] Stopped
2011-11-12T19:11:53.36090Z,1321125113.3609 [Default:E.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:11:53.36100Z,1321125113.361 [Default:F.GoToSurface] Stopped
2011-11-12T19:11:53.36110Z,1321125113.3611 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:11:53.36110Z,1321125113.3611 [Default:G.Wait] Stopped
2011-11-12T19:11:53.36120Z,1321125113.3612 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:11:53.36140Z,1321125113.3614 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2011-11-12T19:11:53.36150Z,1321125113.3615 [ballast_and_trim] Running Loop=1
2011-11-12T19:11:53.36160Z,1321125113.3616 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2011-11-12T19:11:53.36170Z,1321125113.3617 [ballast_and_trim:A.VerticalControlConfig] Running Loop=1
2011-11-12T19:11:53.36190Z,1321125113.3619 [ballast_and_trim:B.AltitudeEnvelope] Running Loop=1
2011-11-12T19:11:53.36190Z,1321125113.3619 [ballast_and_trim:B.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2011-11-12T19:11:53.36210Z,1321125113.3621 [ballast_and_trim:C.DepthEnvelope] Running Loop=1
2011-11-12T19:11:53.36220Z,1321125113.3622 [ballast_and_trim:C.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2011-11-12T19:11:53.36340Z,1321125113.3634 [ballast_and_trim:D.OffshoreEnvelope] Running Loop=1
2011-11-12T19:11:53.36350Z,1321125113.3635 [ballast_and_trim:D.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2011-11-12T19:11:53.36580Z,1321125113.3658 [ballast_and_trim:D.OffshoreEnvelope](DEBUG): Opened Resources/cencalShoreDist.nc
2011-11-12T19:11:53.37690Z,1321125113.3769 [ballast_and_trim:F.SetSpeed] Running Loop=1
2011-11-12T19:11:53.37690Z,1321125113.3769 [ballast_and_trim:F.SetSpeed](DEBUG): Initialize.
2011-11-12T19:11:53.37730Z,1321125113.3773 [ballast_and_trim:SurfaceComms] Running Loop=1
2011-11-12T19:11:53.37740Z,1321125113.3774 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2011-11-12T19:11:53.37750Z,1321125113.3775 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2011-11-12T19:11:53.37760Z,1321125113.3776 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:11:53.37840Z,1321125113.3784 [ballast_and_trim:F.SetSpeed] Running Loop=1
2011-11-12T19:11:53.38720Z,1321125113.3872 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2011-11-12T19:11:53.38740Z,1321125113.3874 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2011-11-12T19:11:53.38760Z,1321125113.3876 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2011-11-12T19:11:53.38770Z,1321125113.3877 [ballast_and_trim:D.OffshoreEnvelope] Running Loop=1
2011-11-12T19:11:53.39280Z,1321125113.3928 [ballast_and_trim:C.DepthEnvelope] Running Loop=1
2011-11-12T19:11:53.39740Z,1321125113.3974 [ballast_and_trim:B.AltitudeEnvelope] Running Loop=1
2011-11-12T19:11:53.40180Z,1321125113.4018 [ballast_and_trim:A.VerticalControlConfig] Running Loop=1
2011-11-12T19:11:58.54170Z,1321125118.5417 [ballast_and_trim:F.SetSpeed] Preempted
2011-11-12T19:11:58.54250Z,1321125118.5425 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-11-12T19:13:22.36800Z,1321125202.368 [NAL9601](IMPORTANT): GPS fix at: 1321125204
2011-11-12T19:13:22.38000Z,1321125202.38 [ballast_and_trim:SurfaceComms:B:A] Stopped
2011-11-12T19:13:22.38020Z,1321125202.3802 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2011-11-12T19:13:22.76060Z,1321125202.7606 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2011-11-12T19:13:30.14920Z,1321125210.1492 [NAL9601](INFO): SBD MO Status=0, MOMSN=37347, MT Status=0, MTMSN=0
2011-11-12T19:13:56.00210Z,1321125236.0021 [NAL9601](INFO): SBD MO Status=2, MOMSN=37348, MT Status=2, MTMSN=0
2011-11-12T19:13:56.00240Z,1321125236.0024 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T19:14:22.70670Z,1321125262.7067 [NAL9601](INFO): SBD MO Status=2, MOMSN=37348, MT Status=2, MTMSN=0
2011-11-12T19:14:22.70690Z,1321125262.7069 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T19:14:50.19850Z,1321125290.1985 [NAL9601](INFO): SBD MO Status=1, MOMSN=37348, MT Status=0, MTMSN=0
2011-11-12T19:14:50.31560Z,1321125290.3156 [NAL9601](INFO): Sent 309 bytes from file Logs/20111112T173436/shore0012.lzma
2011-11-12T19:14:50.31590Z,1321125290.3159 [NAL9601](INFO): Packets left to send: 0
2011-11-12T19:14:50.31690Z,1321125290.3169 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000018
2011-11-12T19:15:03.79350Z,1321125303.7935 [NAL9601](INFO): SBD MO Status=0, MOMSN=37349, MT Status=0, MTMSN=0
2011-11-12T19:15:04.00750Z,1321125304.0075 [ballast_and_trim:SurfaceComms:B:B] Stopped
2011-11-12T19:15:04.00760Z,1321125304.0076 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2011-11-12T19:15:04.19710Z,1321125304.1971 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2011-11-12T19:15:06.18750Z,1321125306.1875 [NAL9601](IMPORTANT): GPS fix at: 1321125308
2011-11-12T19:15:06.19980Z,1321125306.1998 [ballast_and_trim:SurfaceComms:B:C] Stopped
2011-11-12T19:15:06.20000Z,1321125306.2 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2011-11-12T19:15:06.20010Z,1321125306.2001 [ballast_and_trim:SurfaceComms:B] Stopped
2011-11-12T19:15:06.20020Z,1321125306.2002 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2011-11-12T19:15:06.20070Z,1321125306.2007 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2011-11-12T19:15:06.20070Z,1321125306.2007 [ballast_and_trim:SurfaceComms] Stopped
2011-11-12T19:15:06.20090Z,1321125306.2009 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2011-11-12T19:15:06.20090Z,1321125306.2009 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2011-11-12T19:15:06.20100Z,1321125306.201 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:15:06.20120Z,1321125306.2012 [ballast_and_trim:ballast] Running Loop=1
2011-11-12T19:15:06.20130Z,1321125306.2013 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2011-11-12T19:15:06.20140Z,1321125306.2014 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2011-11-12T19:15:06.20140Z,1321125306.2014 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:15:06.20160Z,1321125306.2016 [ballast_and_trim:ballast:B.VerticalControlConfig] Running Loop=1
2011-11-12T19:15:06.20180Z,1321125306.2018 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2011-11-12T19:15:06.20190Z,1321125306.2019 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2011-11-12T19:15:06.20220Z,1321125306.2022 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2011-11-12T19:15:06.20220Z,1321125306.2022 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:15:06.59620Z,1321125306.5962 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2011-11-12T19:15:06.60070Z,1321125306.6007 [ballast_and_trim:ballast:B.VerticalControlConfig] Running Loop=1
2011-11-12T19:15:06.60530Z,1321125306.6053 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2011-11-12T19:15:06.60970Z,1321125306.6097 [ballast_and_trim:F.SetSpeed] Running Loop=1
2011-11-12T19:15:26.75690Z,1321125326.7569 [NAL9601](INFO): Powering down
2011-11-12T19:19:51.75850Z,1321125591.7585 [Radio_Freewave](INFO): Powering down
2011-11-12T19:40:06.73730Z,1321126806.7373 [ballast_and_trim:ballast:D.Wait](INFO): Done Waiting.
2011-11-12T19:40:06.73760Z,1321126806.7376 [ballast_and_trim:ballast:D.Wait] Stopped
2011-11-12T19:40:06.73760Z,1321126806.7376 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:40:06.73780Z,1321126806.7378 [ballast_and_trim:ballast:ReportPositions] Running Loop=1
2011-11-12T19:40:06.73790Z,1321126806.7379 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:40:06.73810Z,1321126806.7381 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2011-11-12T19:40:11.78540Z,1321126811.7854 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 457.9529632 cc 
2011-11-12T19:40:11.78680Z,1321126811.7868 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2011-11-12T19:40:11.78690Z,1321126811.7869 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2011-11-12T19:40:16.77300Z,1321126816.773 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: -0.4734606948 cm 
2011-11-12T19:40:16.77430Z,1321126816.7743 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2011-11-12T19:40:16.77450Z,1321126816.7745 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2011-11-12T19:40:21.74520Z,1321126821.7452 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: 0.5694531482 arcdeg 
2011-11-12T19:40:21.74660Z,1321126821.7466 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2011-11-12T19:40:21.74670Z,1321126821.7467 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2011-11-12T19:40:21.74680Z,1321126821.7468 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:41:21.78560Z,1321126881.7856 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2011-11-12T19:40:21.Z
2011-11-12T19:41:21.78570Z,1321126881.7857 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2011-11-12T19:41:21.78580Z,1321126881.7858 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:41:21.78610Z,1321126881.7861 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:41:21.78620Z,1321126881.7862 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2011-11-12T19:41:21.78630Z,1321126881.7863 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:41:21.78650Z,1321126881.7865 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2011-11-12T19:41:21.78660Z,1321126881.7866 [ballast_and_trim:ballast:ReportPositions] Stopped
2011-11-12T19:41:21.78670Z,1321126881.7867 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:41:21.78690Z,1321126881.7869 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #2
2011-11-12T19:41:21.78700Z,1321126881.787 [ballast_and_trim:ballast:ReportPositions] Running Loop=2
2011-11-12T19:41:21.78720Z,1321126881.7872 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:41:21.78730Z,1321126881.7873 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2011-11-12T19:41:26.77360Z,1321126886.7736 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 457.9529632 cc 
2011-11-12T19:41:26.77380Z,1321126886.7738 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2011-11-12T19:41:26.77390Z,1321126886.7739 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2011-11-12T19:41:31.79460Z,1321126891.7946 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: -0.4450327251 cm 
2011-11-12T19:41:31.79480Z,1321126891.7948 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2011-11-12T19:41:31.79500Z,1321126891.795 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2011-11-12T19:41:36.79460Z,1321126896.7946 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -0.08972655428 arcdeg 
2011-11-12T19:41:36.79490Z,1321126896.7949 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2011-11-12T19:41:36.79500Z,1321126896.795 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2011-11-12T19:41:36.79520Z,1321126896.7952 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:42:41.73710Z,1321126961.7371 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2011-11-12T19:41:36.Z
2011-11-12T19:42:41.73720Z,1321126961.7372 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2011-11-12T19:42:41.73740Z,1321126961.7374 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:42:41.73760Z,1321126961.7376 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:42:41.73770Z,1321126961.7377 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2011-11-12T19:42:41.73770Z,1321126961.7377 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:42:41.73790Z,1321126961.7379 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2011-11-12T19:42:41.73800Z,1321126961.738 [ballast_and_trim:ballast:ReportPositions] Stopped
2011-11-12T19:42:41.73810Z,1321126961.7381 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:42:41.73840Z,1321126961.7384 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #3
2011-11-12T19:42:41.73840Z,1321126961.7384 [ballast_and_trim:ballast:ReportPositions] Running Loop=3
2011-11-12T19:42:41.73860Z,1321126961.7386 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:42:41.73870Z,1321126961.7387 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2011-11-12T19:42:46.76910Z,1321126966.7691 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 457.9529632 cc 
2011-11-12T19:42:46.76920Z,1321126966.7692 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2011-11-12T19:42:46.76940Z,1321126966.7694 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2011-11-12T19:42:51.78520Z,1321126971.7852 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: -0.4450327251 cm 
2011-11-12T19:42:51.78550Z,1321126971.7855 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2011-11-12T19:42:51.78560Z,1321126971.7856 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2011-11-12T19:42:56.72910Z,1321126976.7291 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: -0.04578125056 arcdeg 
2011-11-12T19:42:56.72930Z,1321126976.7293 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2011-11-12T19:42:56.72940Z,1321126976.7294 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2011-11-12T19:42:56.72950Z,1321126976.7295 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:43:56.82380Z,1321127036.8238 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2011-11-12T19:42:56.Z
2011-11-12T19:43:56.82400Z,1321127036.824 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2011-11-12T19:43:56.82410Z,1321127036.8241 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:43:56.82430Z,1321127036.8243 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:43:56.82440Z,1321127036.8244 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2011-11-12T19:43:56.82450Z,1321127036.8245 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:43:56.82470Z,1321127036.8247 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2011-11-12T19:43:56.82470Z,1321127036.8247 [ballast_and_trim:ballast:ReportPositions] Stopped
2011-11-12T19:43:56.82490Z,1321127036.8249 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:43:56.82510Z,1321127036.8251 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #4
2011-11-12T19:43:56.82520Z,1321127036.8252 [ballast_and_trim:ballast:ReportPositions] Running Loop=4
2011-11-12T19:43:56.82530Z,1321127036.8253 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:43:56.82540Z,1321127036.8254 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2011-11-12T19:44:01.80980Z,1321127041.8098 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 457.9529632 cc 
2011-11-12T19:44:01.80990Z,1321127041.8099 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2011-11-12T19:44:01.81010Z,1321127041.8101 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2011-11-12T19:44:06.72920Z,1321127046.7292 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: -0.4529000726 cm 
2011-11-12T19:44:06.72940Z,1321127046.7294 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2011-11-12T19:44:06.72950Z,1321127046.7295 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2011-11-12T19:44:11.78500Z,1321127051.785 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: 0.1080273458 arcdeg 
2011-11-12T19:44:11.78530Z,1321127051.7853 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2011-11-12T19:44:11.78540Z,1321127051.7854 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2011-11-12T19:44:11.78550Z,1321127051.7855 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:45:16.73320Z,1321127116.7332 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2011-11-12T19:44:11.Z
2011-11-12T19:45:16.73330Z,1321127116.7333 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2011-11-12T19:45:16.73350Z,1321127116.7335 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:45:16.73370Z,1321127116.7337 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:45:16.73380Z,1321127116.7338 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2011-11-12T19:45:16.73380Z,1321127116.7338 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:45:16.73400Z,1321127116.734 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2011-11-12T19:45:16.73410Z,1321127116.7341 [ballast_and_trim:ballast:ReportPositions] Stopped
2011-11-12T19:45:16.73420Z,1321127116.7342 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:45:16.73440Z,1321127116.7344 [ballast_and_trim:ballast:ReportPositions](INFO): Running loop #5
2011-11-12T19:45:16.73450Z,1321127116.7345 [ballast_and_trim:ballast:ReportPositions] Running Loop=5
2011-11-12T19:45:16.73460Z,1321127116.7346 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:45:16.73480Z,1321127116.7348 [ballast_and_trim:ballast:ReportPositions:A] Running Loop=1
2011-11-12T19:45:21.78520Z,1321127121.7852 [ballast_and_trim:ballast:ReportPositions:A](IMPORTANT): Buoyancy: 453.7896311 cc 
2011-11-12T19:45:21.78540Z,1321127121.7854 [ballast_and_trim:ballast:ReportPositions:A] Stopped
2011-11-12T19:45:21.78550Z,1321127121.7855 [ballast_and_trim:ballast:ReportPositions:B] Running Loop=1
2011-11-12T19:45:26.78080Z,1321127126.7808 [ballast_and_trim:ballast:ReportPositions:B](IMPORTANT): Mass: -0.4436133895 cm 
2011-11-12T19:45:26.78100Z,1321127126.781 [ballast_and_trim:ballast:ReportPositions:B] Stopped
2011-11-12T19:45:26.78110Z,1321127126.7811 [ballast_and_trim:ballast:ReportPositions:C] Running Loop=1
2011-11-12T19:45:31.77520Z,1321127131.7752 [ballast_and_trim:ballast:ReportPositions:C](IMPORTANT): Pitch: 0.1080273458 arcdeg 
2011-11-12T19:45:31.77550Z,1321127131.7755 [ballast_and_trim:ballast:ReportPositions:C] Stopped
2011-11-12T19:45:31.77560Z,1321127131.7756 [ballast_and_trim:ballast:ReportPositions:D.Wait] Running Loop=1
2011-11-12T19:45:31.77570Z,1321127131.7757 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:46:31.79030Z,1321127191.7903 [ballast_and_trim:ballast:ReportPositions:D.Wait](INFO): Timed out from 2011-11-12T19:45:31.Z
2011-11-12T19:46:31.79040Z,1321127191.7904 [ballast_and_trim:ballast:ReportPositions:A_Timeout] Running Loop=1
2011-11-12T19:46:31.79050Z,1321127191.7905 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Aggregate::initialize ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:46:31.79070Z,1321127191.7907 [ballast_and_trim:ballast:ReportPositions:A_Timeout](INFO): Completed ballast_and_trim:ballast:ReportPositions:A_Timeout
2011-11-12T19:46:31.79080Z,1321127191.7908 [ballast_and_trim:ballast:ReportPositions:D.Wait] Stopped
2011-11-12T19:46:31.79090Z,1321127191.7909 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:46:31.79110Z,1321127191.7911 [ballast_and_trim:ballast:ReportPositions](INFO): Completed ballast_and_trim:ballast:ReportPositions
2011-11-12T19:46:31.79120Z,1321127191.7912 [ballast_and_trim:ballast:ReportPositions] Stopped
2011-11-12T19:46:31.79140Z,1321127191.7914 [ballast_and_trim:ballast:ReportPositions](INFO): Aggregate::uninitialize ballast_and_trim:ballast:ReportPositions
2011-11-12T19:46:31.79150Z,1321127191.7915 [ballast_and_trim:ballast:Float_Up] Running Loop=1
2011-11-12T19:46:31.79170Z,1321127191.7917 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::initialize ballast_and_trim:ballast:Float_Up
2011-11-12T19:46:31.79170Z,1321127191.7917 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2011-11-12T19:46:31.79180Z,1321127191.7918 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:46:31.79190Z,1321127191.7919 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2011-11-12T19:46:31.79200Z,1321127191.792 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2011-11-12T19:46:31.79270Z,1321127191.7927 [ballast_and_trim:ballast:Float_Up:C.Wait] Running Loop=1
2011-11-12T19:46:31.79280Z,1321127191.7928 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:46:36.77270Z,1321127196.7727 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Running Loop=1
2011-11-12T19:46:36.77680Z,1321127196.7768 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Running Loop=1
2011-11-12T19:49:46.77330Z,1321127386.7733 [ballast_and_trim:ballast:Float_Up] Stopped
2011-11-12T19:49:46.77350Z,1321127386.7735 [ballast_and_trim:ballast:Float_Up](INFO): Aggregate::uninitialize ballast_and_trim:ballast:Float_Up
2011-11-12T19:49:46.77360Z,1321127386.7736 [ballast_and_trim:ballast:Float_Up:A.SetSpeed] Stopped
2011-11-12T19:49:46.77360Z,1321127386.7736 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:49:46.77370Z,1321127386.7737 [ballast_and_trim:ballast:Float_Up:B.Buoyancy] Stopped
2011-11-12T19:49:46.77380Z,1321127386.7738 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2011-11-12T19:49:46.77380Z,1321127386.7738 [ballast_and_trim:ballast:Float_Up:C.Wait] Stopped
2011-11-12T19:49:46.77390Z,1321127386.7739 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T19:49:46.77460Z,1321127386.7746 [ballast_and_trim:ballast](INFO): Completed ballast_and_trim:ballast
2011-11-12T19:49:46.77470Z,1321127386.7747 [ballast_and_trim:ballast] Stopped
2011-11-12T19:49:46.77490Z,1321127386.7749 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2011-11-12T19:49:46.77490Z,1321127386.7749 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2011-11-12T19:49:46.77500Z,1321127386.775 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:49:46.77510Z,1321127386.7751 [ballast_and_trim:ballast:B.VerticalControlConfig] Stopped
2011-11-12T19:49:46.77520Z,1321127386.7752 [ballast_and_trim:ballast:C.Pitch] Stopped
2011-11-12T19:49:46.77650Z,1321127386.7765 [ballast_and_trim](INFO): Completed ballast_and_trim
2011-11-12T19:49:46.77660Z,1321127386.7766 [ballast_and_trim] Stopped
2011-11-12T19:49:46.77670Z,1321127386.7767 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2011-11-12T19:49:46.77680Z,1321127386.7768 [ballast_and_trim:A.VerticalControlConfig] Stopped
2011-11-12T19:49:46.77680Z,1321127386.7768 [ballast_and_trim:B.AltitudeEnvelope] Stopped
2011-11-12T19:49:46.77690Z,1321127386.7769 [ballast_and_trim:B.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2011-11-12T19:49:46.77700Z,1321127386.777 [ballast_and_trim:C.DepthEnvelope] Stopped
2011-11-12T19:49:46.77700Z,1321127386.777 [ballast_and_trim:C.DepthEnvelope](DEBUG): Uninitialize.
2011-11-12T19:49:46.77710Z,1321127386.7771 [ballast_and_trim:D.OffshoreEnvelope] Stopped
2011-11-12T19:49:46.77720Z,1321127386.7772 [ballast_and_trim:D.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2011-11-12T19:49:46.77760Z,1321127386.7776 [ballast_and_trim:F.SetSpeed] Stopped
2011-11-12T19:49:46.77770Z,1321127386.7777 [ballast_and_trim:F.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:49:51.73140Z,1321127391.7314 [Radio_Freewave](INFO): Powering up
2011-11-12T19:49:51.73830Z,1321127391.7383 [MissionManager](IMPORTANT): Started mission Default
2011-11-12T19:49:51.73840Z,1321127391.7384 [Default] Running Loop=1
2011-11-12T19:49:51.73860Z,1321127391.7386 [Default](INFO): Aggregate::initialize Default
2011-11-12T19:49:51.73870Z,1321127391.7387 [Default:E.SetSpeed] Running Loop=1
2011-11-12T19:49:51.73870Z,1321127391.7387 [Default:E.SetSpeed](DEBUG): Initialize.
2011-11-12T19:49:51.73880Z,1321127391.7388 [Default:F.GoToSurface] Running Loop=1
2011-11-12T19:49:51.73890Z,1321127391.7389 [Default:F.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:49:51.73950Z,1321127391.7395 [Default:GPS] Running Loop=1
2011-11-12T19:49:51.73970Z,1321127391.7397 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T19:49:51.73980Z,1321127391.7398 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T19:49:51.73980Z,1321127391.7398 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:49:51.74000Z,1321127391.74 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T19:49:51.74010Z,1321127391.7401 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:49:51.74150Z,1321127391.7415 [Default:CallIridium] Running Loop=1
2011-11-12T19:49:51.74160Z,1321127391.7416 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T19:49:51.74180Z,1321127391.7418 [Default:CallIridium:A] Running Loop=1
2011-11-12T19:49:51.74190Z,1321127391.7419 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T19:49:51.74200Z,1321127391.742 [Default:CallGPS] Running Loop=1
2011-11-12T19:49:51.74210Z,1321127391.7421 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T19:49:51.74230Z,1321127391.7423 [Default:CallGPS:A] Running Loop=1
2011-11-12T19:49:51.74240Z,1321127391.7424 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T19:49:51.74270Z,1321127391.7427 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T19:49:51.74280Z,1321127391.7428 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:49:51.74290Z,1321127391.7429 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T19:49:51.99730Z,1321127391.9973 [Default:Iridium] Running Loop=1
2011-11-12T19:49:51.99750Z,1321127391.9975 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T19:49:51.99760Z,1321127391.9976 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T19:49:51.99760Z,1321127391.9976 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:49:51.99780Z,1321127391.9978 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T19:49:51.99790Z,1321127391.9979 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:49:51.99850Z,1321127391.9985 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T19:49:51.99850Z,1321127391.9985 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:49:51.99870Z,1321127391.9987 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T19:49:52.40070Z,1321127392.4007 [NAL9601](INFO): Powering up
2011-11-12T19:50:58.01170Z,1321127458.0117 [NAL9601](INFO): NAL9601 initialized
2011-11-12T19:50:59.18260Z,1321127459.1826 [NAL9601](IMPORTANT): GPS fix at: 1321127464
2011-11-12T19:50:59.19590Z,1321127459.1959 [Default:GPS:Read_GPS] Stopped
2011-11-12T19:50:59.19620Z,1321127459.1962 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T19:50:59.19630Z,1321127459.1963 [Default:GPS] Stopped
2011-11-12T19:50:59.19640Z,1321127459.1964 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T19:50:59.19650Z,1321127459.1965 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T19:50:59.19660Z,1321127459.1966 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:50:59.61570Z,1321127459.6157 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T19:50:59.61580Z,1321127459.6158 [Default:CallGPS:A] Stopped
2011-11-12T19:50:59.61590Z,1321127459.6159 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T19:50:59.61610Z,1321127459.6161 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T19:50:59.61620Z,1321127459.6162 [Default:CallGPS] Stopped
2011-11-12T19:50:59.61630Z,1321127459.6163 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T19:51:00.00070Z,1321127460.0007 [Default:CallGPS] Running Loop=1
2011-11-12T19:51:00.00080Z,1321127460.0008 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T19:51:00.00100Z,1321127460.001 [Default:CallGPS:A] Running Loop=1
2011-11-12T19:51:00.00110Z,1321127460.0011 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T19:51:00.43770Z,1321127460.4377 [Default:GPS] Running Loop=1
2011-11-12T19:51:00.43790Z,1321127460.4379 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T19:51:00.43800Z,1321127460.438 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T19:51:00.43810Z,1321127460.4381 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:51:00.43830Z,1321127460.4383 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T19:51:00.43830Z,1321127460.4383 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:51:00.43900Z,1321127460.439 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T19:51:00.43910Z,1321127460.4391 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:51:00.43930Z,1321127460.4393 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T19:51:14.25370Z,1321127474.2537 [NAL9601](INFO): SBD MO Status=1, MOMSN=37350, MT Status=0, MTMSN=0
2011-11-12T19:51:14.37560Z,1321127474.3756 [NAL9601](INFO): Sent 332 bytes from file Logs/20111112T173436/shore0013.lzma
2011-11-12T19:51:14.37580Z,1321127474.3758 [NAL9601](INFO): Packets left to send: 1
2011-11-12T19:51:14.37690Z,1321127474.3769 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000019
2011-11-12T19:51:23.51400Z,1321127483.514 [NAL9601](INFO): SBD MO Status=1, MOMSN=37351, MT Status=0, MTMSN=0
2011-11-12T19:51:23.65960Z,1321127483.6596 [NAL9601](INFO): Sent 322 bytes from file Logs/20111112T173436/shore0013.lzma
2011-11-12T19:51:23.65980Z,1321127483.6598 [NAL9601](INFO): Packets left to send: 0
2011-11-12T19:51:23.66090Z,1321127483.6609 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000020
2011-11-12T19:51:29.91410Z,1321127489.9141 [NAL9601](INFO): SBD MO Status=0, MOMSN=37352, MT Status=0, MTMSN=0
2011-11-12T19:51:30.06330Z,1321127490.0633 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T19:51:30.06370Z,1321127490.0637 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T19:51:30.06380Z,1321127490.0638 [Default:Iridium] Stopped
2011-11-12T19:51:30.06390Z,1321127490.0639 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T19:51:30.06400Z,1321127490.064 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T19:51:30.06400Z,1321127490.064 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:51:30.06420Z,1321127490.0642 [Default:G.Wait] Running Loop=1
2011-11-12T19:51:30.06430Z,1321127490.0643 [Default:G.Wait](DEBUG): Initialize Wait Component.
2011-11-12T19:51:30.35970Z,1321127490.3597 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T19:51:30.35980Z,1321127490.3598 [Default:CallIridium:A] Stopped
2011-11-12T19:51:30.35990Z,1321127490.3599 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T19:51:30.36010Z,1321127490.3601 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T19:51:30.36020Z,1321127490.3602 [Default:CallIridium] Stopped
2011-11-12T19:51:30.36030Z,1321127490.3603 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T19:51:31.11580Z,1321127491.1158 [NAL9601](IMPORTANT): GPS fix at: 1321127496
2011-11-12T19:51:31.12830Z,1321127491.1283 [Default:GPS:Read_GPS] Stopped
2011-11-12T19:51:31.12870Z,1321127491.1287 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T19:51:31.12880Z,1321127491.1288 [Default:GPS] Stopped
2011-11-12T19:51:31.12890Z,1321127491.1289 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T19:51:31.12900Z,1321127491.129 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T19:51:31.12910Z,1321127491.1291 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:51:31.52020Z,1321127491.5202 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T19:51:31.52030Z,1321127491.5203 [Default:CallGPS:A] Stopped
2011-11-12T19:51:31.52050Z,1321127491.5205 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T19:51:31.52070Z,1321127491.5207 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T19:51:31.52080Z,1321127491.5208 [Default:CallGPS] Stopped
2011-11-12T19:51:31.52090Z,1321127491.5209 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T19:51:51.64340Z,1321127511.6434 [NAL9601](INFO): Powering down
2011-11-12T19:56:31.66940Z,1321127791.6694 [Default:CallIridium] Running Loop=1
2011-11-12T19:56:31.66950Z,1321127791.6695 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T19:56:31.66970Z,1321127791.6697 [Default:CallIridium:A] Running Loop=1
2011-11-12T19:56:31.66980Z,1321127791.6698 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T19:56:31.66990Z,1321127791.6699 [Default:CallGPS] Running Loop=1
2011-11-12T19:56:31.67010Z,1321127791.6701 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T19:56:31.67020Z,1321127791.6702 [Default:CallGPS:A] Running Loop=1
2011-11-12T19:56:31.67030Z,1321127791.6703 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T19:56:36.69880Z,1321127796.6988 [Default:Iridium] Running Loop=1
2011-11-12T19:56:36.69900Z,1321127796.699 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T19:56:36.69920Z,1321127796.6992 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T19:56:36.69920Z,1321127796.6992 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:56:36.69940Z,1321127796.6994 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T19:56:36.69950Z,1321127796.6995 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:56:36.70020Z,1321127796.7002 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T19:56:36.70020Z,1321127796.7002 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:56:36.70040Z,1321127796.7004 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T19:56:36.70060Z,1321127796.7006 [Default:GPS] Running Loop=1
2011-11-12T19:56:36.70080Z,1321127796.7008 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T19:56:36.70090Z,1321127796.7009 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T19:56:36.70090Z,1321127796.7009 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T19:56:36.70110Z,1321127796.7011 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T19:56:36.70120Z,1321127796.7012 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T19:56:36.70170Z,1321127796.7017 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T19:56:36.70180Z,1321127796.7018 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T19:56:36.70200Z,1321127796.702 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T19:56:37.31660Z,1321127797.3166 [NAL9601](INFO): Powering up
2011-11-12T19:57:43.02770Z,1321127863.0277 [NAL9601](INFO): NAL9601 initialized
2011-11-12T19:58:00.38570Z,1321127880.3857 [NAL9601](INFO): SBD MO Status=1, MOMSN=37353, MT Status=0, MTMSN=0
2011-11-12T19:58:00.58760Z,1321127880.5876 [NAL9601](INFO): Sent 153 bytes from file Logs/20111112T173436/shore0014.lzma
2011-11-12T19:58:00.58780Z,1321127880.5878 [NAL9601](INFO): Packets left to send: 0
2011-11-12T19:58:00.58890Z,1321127880.5889 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000021
2011-11-12T19:58:08.37010Z,1321127888.3701 [NAL9601](INFO): SBD MO Status=0, MOMSN=37354, MT Status=0, MTMSN=0
2011-11-12T19:58:08.58760Z,1321127888.5876 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T19:58:08.58790Z,1321127888.5879 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T19:58:08.58800Z,1321127888.588 [Default:Iridium] Stopped
2011-11-12T19:58:08.58820Z,1321127888.5882 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T19:58:08.58820Z,1321127888.5882 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T19:58:08.58830Z,1321127888.5883 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:58:08.78090Z,1321127888.7809 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T19:58:08.78100Z,1321127888.781 [Default:CallIridium:A] Stopped
2011-11-12T19:58:08.78120Z,1321127888.7812 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T19:58:08.78140Z,1321127888.7814 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T19:58:08.78150Z,1321127888.7815 [Default:CallIridium] Stopped
2011-11-12T19:58:08.78160Z,1321127888.7816 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T19:58:19.57150Z,1321127899.5715 [NAL9601](IMPORTANT): GPS fix at: 1321127905
2011-11-12T19:58:19.58390Z,1321127899.5839 [Default:GPS:Read_GPS] Stopped
2011-11-12T19:58:19.58430Z,1321127899.5843 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T19:58:19.58440Z,1321127899.5844 [Default:GPS] Stopped
2011-11-12T19:58:19.58450Z,1321127899.5845 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T19:58:19.58460Z,1321127899.5846 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T19:58:19.58470Z,1321127899.5847 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T19:58:19.98110Z,1321127899.9811 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T19:58:19.98120Z,1321127899.9812 [Default:CallGPS:A] Stopped
2011-11-12T19:58:19.98130Z,1321127899.9813 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T19:58:19.98150Z,1321127899.9815 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T19:58:19.98160Z,1321127899.9816 [Default:CallGPS] Stopped
2011-11-12T19:58:19.98170Z,1321127899.9817 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T19:58:40.12490Z,1321127920.1249 [NAL9601](INFO): Powering down
2011-11-12T20:00:05.07230Z,1321128005.0723 [Batt_Ocean_Server](FAULT): Over Temperature Alarm! Battery Bank #4 STATUS: 5911
2011-11-12T20:00:05.07260Z,1321128005.0726 [Batt_Ocean_Server](FAULT): Not Initialized - Battery Bank #4 STATUS: 5911
2011-11-12T20:03:10.15730Z,1321128190.1573 [Default:CallIridium] Running Loop=1
2011-11-12T20:03:10.15740Z,1321128190.1574 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T20:03:10.15760Z,1321128190.1576 [Default:CallIridium:A] Running Loop=1
2011-11-12T20:03:10.15770Z,1321128190.1577 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T20:03:10.15790Z,1321128190.1579 [Default:CallGPS] Running Loop=1
2011-11-12T20:03:10.15800Z,1321128190.158 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T20:03:10.15810Z,1321128190.1581 [Default:CallGPS:A] Running Loop=1
2011-11-12T20:03:10.15820Z,1321128190.1582 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T20:03:15.10450Z,1321128195.1045 [Default:Iridium] Running Loop=1
2011-11-12T20:03:15.10460Z,1321128195.1046 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T20:03:15.10470Z,1321128195.1047 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T20:03:15.10480Z,1321128195.1048 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:03:15.10500Z,1321128195.105 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T20:03:15.10510Z,1321128195.1051 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:03:15.10570Z,1321128195.1057 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T20:03:15.10580Z,1321128195.1058 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:03:15.10590Z,1321128195.1059 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T20:03:15.10620Z,1321128195.1062 [Default:GPS] Running Loop=1
2011-11-12T20:03:15.10630Z,1321128195.1063 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T20:03:15.10640Z,1321128195.1064 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T20:03:15.10650Z,1321128195.1065 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:03:15.10670Z,1321128195.1067 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T20:03:15.10670Z,1321128195.1067 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:03:15.10740Z,1321128195.1074 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T20:03:15.10740Z,1321128195.1074 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:03:15.10760Z,1321128195.1076 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T20:03:15.76950Z,1321128195.7695 [NAL9601](INFO): Powering up
2011-11-12T20:04:21.47970Z,1321128261.4797 [NAL9601](INFO): NAL9601 initialized
2011-11-12T20:04:41.22220Z,1321128281.2222 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=37355, MT Status=1, MTMSN=3155
2011-11-12T20:04:41.43960Z,1321128281.4396 [NAL9601](INFO): Sent 234 bytes from file Logs/20111112T173436/shore0015.lzma
2011-11-12T20:04:41.43990Z,1321128281.4399 [NAL9601](INFO): Packets left to send: 0
2011-11-12T20:04:41.44100Z,1321128281.441 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000022
2011-11-12T20:04:41.88690Z,1321128281.8869 [NAL9601](IMPORTANT): Initialized file: Config/Control.cfg
2011-11-12T20:04:41.88830Z,1321128281.8883 [NAL9601](IMPORTANT): More data left to go, at position 8E
2011-11-12T20:04:42.82370Z,1321128282.8237 [NAL9601](IMPORTANT): GPS fix at: 1321128289
2011-11-12T20:04:42.83690Z,1321128282.8369 [Default:GPS:Read_GPS] Stopped
2011-11-12T20:04:42.83720Z,1321128282.8372 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T20:04:42.83730Z,1321128282.8373 [Default:GPS] Stopped
2011-11-12T20:04:42.83740Z,1321128282.8374 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T20:04:42.83750Z,1321128282.8375 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T20:04:42.83760Z,1321128282.8376 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:04:43.23710Z,1321128283.2371 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T20:04:43.23720Z,1321128283.2372 [Default:CallGPS:A] Stopped
2011-11-12T20:04:43.23740Z,1321128283.2374 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T20:04:43.23750Z,1321128283.2375 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T20:04:43.23760Z,1321128283.2376 [Default:CallGPS] Stopped
2011-11-12T20:04:43.23780Z,1321128283.2378 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T20:04:43.69620Z,1321128283.6962 [Default:CallGPS] Running Loop=1
2011-11-12T20:04:43.69640Z,1321128283.6964 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T20:04:43.69650Z,1321128283.6965 [Default:CallGPS:A] Running Loop=1
2011-11-12T20:04:43.69670Z,1321128283.6967 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T20:04:44.03710Z,1321128284.0371 [Default:GPS] Running Loop=1
2011-11-12T20:04:44.03730Z,1321128284.0373 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T20:04:44.03740Z,1321128284.0374 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T20:04:44.03750Z,1321128284.0375 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:04:44.03770Z,1321128284.0377 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T20:04:44.03770Z,1321128284.0377 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:04:44.03840Z,1321128284.0384 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T20:04:44.03850Z,1321128284.0385 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:04:44.03860Z,1321128284.0386 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T20:04:55.43150Z,1321128295.4315 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=37356, MT Status=1, MTMSN=3156
2011-11-12T20:04:55.93520Z,1321128295.9352 [NAL9601](IMPORTANT): Added data to file: Config/Control.cfg
2011-11-12T20:04:59.92890Z,1321128299.9289 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4EBECFEA.part | gunzip -f -d | cat `cp Config/.svn/text-base/Control.cfg.svn-base Config/Control.cfg` | vim -e Config/Control.cfg
2011-11-12T20:05:00.01490Z,1321128300.0149 [CommandLine](IMPORTANT): ba209026d1ffe425acfc7dadddfc0dfa  Config/Control.cfg

2011-11-12T20:05:00.91470Z,1321128300.9147 [NAL9601](IMPORTANT): GPS fix at: 1321128307
2011-11-12T20:05:00.92830Z,1321128300.9283 [Default:GPS:Read_GPS] Stopped
2011-11-12T20:05:00.92870Z,1321128300.9287 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T20:05:00.92880Z,1321128300.9288 [Default:GPS] Stopped
2011-11-12T20:05:00.92890Z,1321128300.9289 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T20:05:00.92900Z,1321128300.929 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T20:05:00.92910Z,1321128300.9291 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:05:01.34610Z,1321128301.3461 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T20:05:01.34620Z,1321128301.3462 [Default:CallGPS:A] Stopped
2011-11-12T20:05:01.34640Z,1321128301.3464 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T20:05:01.34660Z,1321128301.3466 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T20:05:01.34670Z,1321128301.3467 [Default:CallGPS] Stopped
2011-11-12T20:05:01.34690Z,1321128301.3469 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T20:05:01.76930Z,1321128301.7693 [Default:CallGPS] Running Loop=1
2011-11-12T20:05:01.76940Z,1321128301.7694 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T20:05:01.76960Z,1321128301.7696 [Default:CallGPS:A] Running Loop=1
2011-11-12T20:05:01.76970Z,1321128301.7697 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T20:05:02.12470Z,1321128302.1247 [Default:GPS] Running Loop=1
2011-11-12T20:05:02.12490Z,1321128302.1249 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T20:05:02.12500Z,1321128302.125 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T20:05:02.12500Z,1321128302.125 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:05:02.12520Z,1321128302.1252 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T20:05:02.12530Z,1321128302.1253 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:05:02.12590Z,1321128302.1259 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T20:05:02.12600Z,1321128302.126 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:05:02.12610Z,1321128302.1261 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T20:05:20.69400Z,1321128320.694 [NAL9601](INFO): SBD MO Status=0, MOMSN=37357, MT Status=0, MTMSN=0
2011-11-12T20:05:21.91120Z,1321128321.9112 [NAL9601](IMPORTANT): GPS fix at: 1321128328
2011-11-12T20:05:21.92410Z,1321128321.9241 [Default:GPS:Read_GPS] Stopped
2011-11-12T20:05:21.92440Z,1321128321.9244 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T20:05:21.92450Z,1321128321.9245 [Default:GPS] Stopped
2011-11-12T20:05:21.92460Z,1321128321.9246 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T20:05:21.92470Z,1321128321.9247 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T20:05:21.92480Z,1321128321.9248 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:05:22.30900Z,1321128322.309 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T20:05:22.30910Z,1321128322.3091 [Default:CallGPS:A] Stopped
2011-11-12T20:05:22.30920Z,1321128322.3092 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T20:05:22.30940Z,1321128322.3094 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T20:05:22.30950Z,1321128322.3095 [Default:CallGPS] Stopped
2011-11-12T20:05:22.30960Z,1321128322.3096 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T20:05:22.70870Z,1321128322.7087 [Default:CallGPS] Running Loop=1
2011-11-12T20:05:22.70880Z,1321128322.7088 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T20:05:22.70900Z,1321128322.709 [Default:CallGPS:A] Running Loop=1
2011-11-12T20:05:22.70910Z,1321128322.7091 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T20:05:23.10020Z,1321128323.1002 [Default:GPS] Running Loop=1
2011-11-12T20:05:23.10040Z,1321128323.1004 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T20:05:23.10050Z,1321128323.1005 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T20:05:23.10060Z,1321128323.1006 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:05:23.10080Z,1321128323.1008 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T20:05:23.10080Z,1321128323.1008 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:05:23.10140Z,1321128323.1014 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T20:05:23.10150Z,1321128323.1015 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:05:23.10160Z,1321128323.1016 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T20:06:02.15000Z,1321128362.15 [NAL9601](INFO): SBD MO Status=2, MOMSN=37358, MT Status=2, MTMSN=0
2011-11-12T20:06:02.15020Z,1321128362.1502 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T20:06:03.35130Z,1321128363.3513 [NAL9601](IMPORTANT): GPS fix at: 1321128370
2011-11-12T20:06:03.36410Z,1321128363.3641 [Default:GPS:Read_GPS] Stopped
2011-11-12T20:06:03.36440Z,1321128363.3644 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T20:06:03.36450Z,1321128363.3645 [Default:GPS] Stopped
2011-11-12T20:06:03.36460Z,1321128363.3646 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T20:06:03.36470Z,1321128363.3647 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T20:06:03.36480Z,1321128363.3648 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:06:03.75550Z,1321128363.7555 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T20:06:03.75560Z,1321128363.7556 [Default:CallGPS:A] Stopped
2011-11-12T20:06:03.75570Z,1321128363.7557 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T20:06:03.75590Z,1321128363.7559 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T20:06:03.75600Z,1321128363.756 [Default:CallGPS] Stopped
2011-11-12T20:06:03.75610Z,1321128363.7561 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T20:06:04.16450Z,1321128364.1645 [Default:CallGPS] Running Loop=1
2011-11-12T20:06:04.16470Z,1321128364.1647 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T20:06:04.16480Z,1321128364.1648 [Default:CallGPS:A] Running Loop=1
2011-11-12T20:06:04.16490Z,1321128364.1649 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T20:06:04.56090Z,1321128364.5609 [Default:GPS] Running Loop=1
2011-11-12T20:06:04.56110Z,1321128364.5611 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T20:06:04.56120Z,1321128364.5612 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T20:06:04.56120Z,1321128364.5612 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:06:04.56140Z,1321128364.5614 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T20:06:04.56150Z,1321128364.5615 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:06:04.56210Z,1321128364.5621 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T20:06:04.56220Z,1321128364.5622 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:06:04.56230Z,1321128364.5623 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T20:06:14.41770Z,1321128374.4177 [NAL9601](INFO): SBD MO Status=1, MOMSN=37358, MT Status=0, MTMSN=0
2011-11-12T20:06:14.59560Z,1321128374.5956 [NAL9601](INFO): Sent 332 bytes from file Logs/20111112T173436/shore0016.lzma
2011-11-12T20:06:14.59580Z,1321128374.5958 [NAL9601](INFO): Packets left to send: 1
2011-11-12T20:06:14.59690Z,1321128374.5969 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000023
2011-11-12T20:06:22.46900Z,1321128382.469 [NAL9601](INFO): SBD MO Status=1, MOMSN=37359, MT Status=0, MTMSN=0
2011-11-12T20:06:22.67970Z,1321128382.6797 [NAL9601](INFO): Sent 118 bytes from file Logs/20111112T173436/shore0016.lzma
2011-11-12T20:06:22.67990Z,1321128382.6799 [NAL9601](INFO): Packets left to send: 0
2011-11-12T20:06:22.68100Z,1321128382.681 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000024
2011-11-12T20:06:30.87400Z,1321128390.874 [NAL9601](INFO): SBD MO Status=0, MOMSN=37360, MT Status=0, MTMSN=0
2011-11-12T20:06:31.08170Z,1321128391.0817 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T20:06:31.08210Z,1321128391.0821 [Default:Iridium](INFO): Completed Default:Iridium
2011-11-12T20:06:31.08220Z,1321128391.0822 [Default:Iridium] Stopped
2011-11-12T20:06:31.08230Z,1321128391.0823 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T20:06:31.08240Z,1321128391.0824 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T20:06:31.08250Z,1321128391.0825 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:06:31.28240Z,1321128391.2824 [Default:CallIridium:A](INFO): Completed Default:CallIridium:A
2011-11-12T20:06:31.28250Z,1321128391.2825 [Default:CallIridium:A] Stopped
2011-11-12T20:06:31.28260Z,1321128391.2826 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T20:06:31.28280Z,1321128391.2828 [Default:CallIridium](INFO): Completed Default:CallIridium
2011-11-12T20:06:31.28290Z,1321128391.2829 [Default:CallIridium] Stopped
2011-11-12T20:06:31.28330Z,1321128391.2833 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T20:06:32.09200Z,1321128392.092 [NAL9601](IMPORTANT): GPS fix at: 1321128399
2011-11-12T20:06:32.10480Z,1321128392.1048 [Default:GPS:Read_GPS] Stopped
2011-11-12T20:06:32.10520Z,1321128392.1052 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T20:06:32.10520Z,1321128392.1052 [Default:GPS] Stopped
2011-11-12T20:06:32.10540Z,1321128392.1054 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T20:06:32.10540Z,1321128392.1054 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T20:06:32.10550Z,1321128392.1055 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:06:32.52070Z,1321128392.5207 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T20:06:32.52080Z,1321128392.5208 [Default:CallGPS:A] Stopped
2011-11-12T20:06:32.52090Z,1321128392.5209 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T20:06:32.52110Z,1321128392.5211 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T20:06:32.52120Z,1321128392.5212 [Default:CallGPS] Stopped
2011-11-12T20:06:32.52130Z,1321128392.5213 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T20:06:52.64390Z,1321128412.6439 [NAL9601](INFO): Powering down
2011-11-12T20:11:32.63720Z,1321128692.6372 [Default:CallIridium] Running Loop=1
2011-11-12T20:11:32.63730Z,1321128692.6373 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2011-11-12T20:11:32.63750Z,1321128692.6375 [Default:CallIridium:A] Running Loop=1
2011-11-12T20:11:32.63760Z,1321128692.6376 [Default:CallIridium:A](INFO): Aggregate::initialize Default:CallIridium:A
2011-11-12T20:11:32.63780Z,1321128692.6378 [Default:CallGPS] Running Loop=1
2011-11-12T20:11:32.63790Z,1321128692.6379 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T20:11:32.63800Z,1321128692.638 [Default:CallGPS:A] Running Loop=1
2011-11-12T20:11:32.63810Z,1321128692.6381 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T20:11:37.62490Z,1321128697.6249 [Default:Iridium] Running Loop=1
2011-11-12T20:11:37.62510Z,1321128697.6251 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2011-11-12T20:11:37.62520Z,1321128697.6252 [Default:Iridium:A.SetSpeed] Running Loop=1
2011-11-12T20:11:37.62520Z,1321128697.6252 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:11:37.62540Z,1321128697.6254 [Default:Iridium:B.GoToSurface] Running Loop=1
2011-11-12T20:11:37.62550Z,1321128697.6255 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:11:37.62620Z,1321128697.6262 [Default:Iridium:B.GoToSurface] Stopped
2011-11-12T20:11:37.62620Z,1321128697.6262 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:11:37.62640Z,1321128697.6264 [Default:Iridium:Read_Iridium] Running Loop=1
2011-11-12T20:11:37.62660Z,1321128697.6266 [Default:GPS] Running Loop=1
2011-11-12T20:11:37.62680Z,1321128697.6268 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T20:11:37.62690Z,1321128697.6269 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T20:11:37.62690Z,1321128697.6269 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:11:37.62710Z,1321128697.6271 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T20:11:37.62720Z,1321128697.6272 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:11:37.62780Z,1321128697.6278 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T20:11:37.62790Z,1321128697.6279 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:11:37.62800Z,1321128697.628 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T20:11:38.29610Z,1321128698.2961 [NAL9601](INFO): Powering up
2011-11-12T20:12:44.00770Z,1321128764.0077 [NAL9601](INFO): NAL9601 initialized
2011-11-12T20:13:44.54180Z,1321128824.5418 [NAL9601](IMPORTANT): SBD MO Status=2, MOMSN=37361, MT Status=1, MTMSN=3157
2011-11-12T20:13:44.54200Z,1321128824.542 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2011-11-12T20:13:45.72760Z,1321128825.7276 [NAL9601](IMPORTANT): GPS fix at: 1321128833
2011-11-12T20:13:45.74030Z,1321128825.7403 [Default:GPS:Read_GPS] Stopped
2011-11-12T20:13:45.74070Z,1321128825.7407 [Default:GPS](INFO): Completed Default:GPS
2011-11-12T20:13:45.74080Z,1321128825.7408 [Default:GPS] Stopped
2011-11-12T20:13:45.74090Z,1321128825.7409 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T20:13:45.74100Z,1321128825.741 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T20:13:45.74110Z,1321128825.7411 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:13:46.13190Z,1321128826.1319 [Default:CallGPS:A](INFO): Completed Default:CallGPS:A
2011-11-12T20:13:46.13200Z,1321128826.132 [Default:CallGPS:A] Stopped
2011-11-12T20:13:46.13210Z,1321128826.1321 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T20:13:46.13230Z,1321128826.1323 [Default:CallGPS](INFO): Completed Default:CallGPS
2011-11-12T20:13:46.13240Z,1321128826.1324 [Default:CallGPS] Stopped
2011-11-12T20:13:46.13250Z,1321128826.1325 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T20:13:46.53580Z,1321128826.5358 [Default:CallGPS] Running Loop=1
2011-11-12T20:13:46.53600Z,1321128826.536 [Default:CallGPS](INFO): Aggregate::initialize Default:CallGPS
2011-11-12T20:13:46.53610Z,1321128826.5361 [Default:CallGPS:A] Running Loop=1
2011-11-12T20:13:46.53620Z,1321128826.5362 [Default:CallGPS:A](INFO): Aggregate::initialize Default:CallGPS:A
2011-11-12T20:13:46.93240Z,1321128826.9324 [Default:GPS] Running Loop=1
2011-11-12T20:13:46.93250Z,1321128826.9325 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2011-11-12T20:13:46.93260Z,1321128826.9326 [Default:GPS:A.SetSpeed] Running Loop=1
2011-11-12T20:13:46.93270Z,1321128826.9327 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2011-11-12T20:13:46.93290Z,1321128826.9329 [Default:GPS:B.GoToSurface] Running Loop=1
2011-11-12T20:13:46.93300Z,1321128826.933 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2011-11-12T20:13:46.93360Z,1321128826.9336 [Default:GPS:B.GoToSurface] Stopped
2011-11-12T20:13:46.93370Z,1321128826.9337 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:13:46.93390Z,1321128826.9339 [Default:GPS:Read_GPS] Running Loop=1
2011-11-12T20:14:04.39430Z,1321128844.3943 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=37361, MT Status=1, MTMSN=3157
2011-11-12T20:14:04.57160Z,1321128844.5716 [NAL9601](INFO): Sent 172 bytes from file Logs/20111112T173436/shore0017.lzma
2011-11-12T20:14:04.57180Z,1321128844.5718 [NAL9601](INFO): Packets left to send: 0
2011-11-12T20:14:04.57300Z,1321128844.573 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000025
2011-11-12T20:14:04.98870Z,1321128844.9887 [NAL9601](INFO): Received command:restart application
2011-11-12T20:14:04.99170Z,1321128844.9917 [CommandLine](IMPORTANT): got command restart application
2011-11-12T20:14:05.10720Z,1321128845.1072 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2011-11-12T20:14:05.27770Z,1321128845.2777 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2011-11-12T20:14:05.66010Z,1321128845.6601 [controlThread](DEBUG): Uninitializing ControlThread
2011-11-12T20:14:05.66070Z,1321128845.6607 [AHRS_sp3003D](INFO): Powering down
2011-11-12T20:14:05.74770Z,1321128845.7477 [AHRS_3DMGX3](INFO): Powering down
2011-11-12T20:14:05.74900Z,1321128845.749 [DVL_micro](INFO): Powering down
2011-11-12T20:14:05.74940Z,1321128845.7494 [NAL9601](INFO): Powering down
2011-11-12T20:14:05.75020Z,1321128845.7502 [DAT](INFO): Powering down
2011-11-12T20:14:05.75060Z,1321128845.7506 [WetLabsBB2FL](INFO): Powering down
2011-11-12T20:14:05.75130Z,1321128845.7513 [Bathymetry](DEBUG): Uninitialize Bathymetry Derivation.
2011-11-12T20:14:05.75310Z,1321128845.7531 [Default] Stopped
2011-11-12T20:14:05.75330Z,1321128845.7533 [Default](INFO): Aggregate::uninitialize Default
2011-11-12T20:14:05.75330Z,1321128845.7533 [Default:GPS] Stopped
2011-11-12T20:14:05.75350Z,1321128845.7535 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2011-11-12T20:14:05.75350Z,1321128845.7535 [Default:GPS:A.SetSpeed] Stopped
2011-11-12T20:14:05.75360Z,1321128845.7536 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:14:05.75370Z,1321128845.7537 [Default:GPS:Read_GPS] Stopped
2011-11-12T20:14:05.75370Z,1321128845.7537 [Default:Iridium] Stopped
2011-11-12T20:14:05.75390Z,1321128845.7539 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2011-11-12T20:14:05.75390Z,1321128845.7539 [Default:Iridium:A.SetSpeed] Stopped
2011-11-12T20:14:05.75400Z,1321128845.754 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:14:05.75410Z,1321128845.7541 [Default:Iridium:Read_Iridium] Stopped
2011-11-12T20:14:05.75410Z,1321128845.7541 [Default:CallGPS] Stopped
2011-11-12T20:14:05.75430Z,1321128845.7543 [Default:CallGPS](INFO): Aggregate::uninitialize Default:CallGPS
2011-11-12T20:14:05.75430Z,1321128845.7543 [Default:CallGPS:A] Stopped
2011-11-12T20:14:05.75450Z,1321128845.7545 [Default:CallGPS:A](INFO): Aggregate::uninitialize Default:CallGPS:A
2011-11-12T20:14:05.75450Z,1321128845.7545 [Default:CallIridium] Stopped
2011-11-12T20:14:05.75470Z,1321128845.7547 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2011-11-12T20:14:05.75470Z,1321128845.7547 [Default:CallIridium:A] Stopped
2011-11-12T20:14:05.75490Z,1321128845.7549 [Default:CallIridium:A](INFO): Aggregate::uninitialize Default:CallIridium:A
2011-11-12T20:14:05.75500Z,1321128845.755 [Default:E.SetSpeed] Stopped
2011-11-12T20:14:05.75500Z,1321128845.755 [Default:E.SetSpeed](DEBUG): Uninitialize.
2011-11-12T20:14:05.75520Z,1321128845.7552 [Default:F.GoToSurface] Stopped
2011-11-12T20:14:05.75520Z,1321128845.7552 [Default:F.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2011-11-12T20:14:05.75530Z,1321128845.7553 [Default:G.Wait] Stopped
2011-11-12T20:14:05.75540Z,1321128845.7554 [Default:G.Wait](DEBUG): Uninitialize Wait Component.
2011-11-12T20:14:05.75970Z,1321128845.7597 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2011-11-12T20:14:05.76000Z,1321128845.76 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2011-11-12T20:14:05.76030Z,1321128845.7603 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2011-11-12T20:14:05.76060Z,1321128845.7606 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2011-11-12T20:14:05.76100Z,1321128845.761 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2011-11-12T20:14:05.76130Z,1321128845.7613 [BuoyancyServo](INFO): Powering down
2011-11-12T20:14:05.76180Z,1321128845.7618 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2011-11-12T20:14:05.76190Z,1321128845.7619 [ElevatorServo](INFO): Powering down
2011-11-12T20:14:05.76230Z,1321128845.7623 [MassServo](DEBUG): Uninitialize Mass Servo.
2011-11-12T20:14:05.76240Z,1321128845.7624 [MassServo](INFO): Powering down
2011-11-12T20:14:05.76270Z,1321128845.7627 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2011-11-12T20:14:05.76280Z,1321128845.7628 [RudderServo](INFO): Powering down
2011-11-12T20:14:05.76330Z,1321128845.7633 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2011-11-12T20:14:05.76340Z,1321128845.7634 [ThrusterServo](INFO): Powering down
2011-11-12T20:14:05.76380Z,1321128845.7638 [SBIT](DEBUG): Uninitialize SBIT Component.
2011-11-12T20:14:05.76410Z,1321128845.7641 [IBIT](DEBUG): Uninitialize IBIT Component.
2011-11-12T20:14:05.76440Z,1321128845.7644 [CBIT](DEBUG): Uninitialize CBIT Component.
