2013-10-31T21:06:52.017Z,1383253612.017 [Supervisor](DEBUG): Initializing supervisor.
2013-10-31T21:06:52.020Z,1383253612.020 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-10-31T21:06:52.020Z,1383253612.020 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-10-31T21:06:52.021Z,1383253612.021 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-10-31T21:06:52.026Z,1383253612.026 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-10-31T21:06:52.038Z,1383253612.038 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-10-31T21:06:52.039Z,1383253612.039 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-10-31T21:06:52.040Z,1383253612.040 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-10-31T21:06:52.041Z,1383253612.041 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-10-31T21:06:52.042Z,1383253612.042 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-10-31T21:06:52.043Z,1383253612.043 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-10-31T21:06:52.389Z,1383253612.389 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-10-31T21:06:52.390Z,1383253612.390 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-10-31T21:06:52.580Z,1383253612.580 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-10-31T21:06:52.581Z,1383253612.581 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-10-31T21:06:52.667Z,1383253612.667 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-10-31T21:06:52.668Z,1383253612.668 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-10-31T21:06:52.785Z,1383253612.785 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-10-31T21:06:52.786Z,1383253612.786 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-10-31T21:06:52.928Z,1383253612.928 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-10-31T21:06:52.929Z,1383253612.929 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-10-31T21:06:53.179Z,1383253613.179 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-10-31T21:06:53.180Z,1383253613.180 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-10-31T21:06:53.347Z,1383253613.347 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-10-31T21:06:53.347Z,1383253613.347 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-10-31T21:06:53.645Z,1383253613.645 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-10-31T21:06:53.646Z,1383253613.646 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-10-31T21:06:53.776Z,1383253613.776 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-10-31T21:06:53.777Z,1383253613.777 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-10-31T21:06:54.207Z,1383253614.207 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-10-31T21:06:54.208Z,1383253614.208 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-10-31T21:06:54.325Z,1383253614.325 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-10-31T21:06:54.326Z,1383253614.326 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-10-31T21:06:54.413Z,1383253614.413 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-10-31T21:06:54.414Z,1383253614.414 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-10-31T21:06:54.518Z,1383253614.518 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-10-31T21:06:54.647Z,1383253614.647 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-10-31T21:06:54.744Z,1383253614.744 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-10-31T21:06:54.855Z,1383253614.855 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-10-31T21:06:54.952Z,1383253614.952 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-10-31T21:06:55.069Z,1383253615.069 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-10-31T21:06:55.169Z,1383253615.169 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-10-31T21:06:55.256Z,1383253615.256 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-10-31T21:06:55.257Z,1383253615.257 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-10-31T21:06:55.258Z,1383253615.258 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-10-31T21:06:55.429Z,1383253615.429 [InternalSim] Loaded
2013-10-31T21:06:55.429Z,1383253615.429 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-10-31T21:06:55.430Z,1383253615.430 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-10-31T21:06:55.430Z,1383253615.430 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-10-31T21:06:55.521Z,1383253615.521 [SBIT](DEBUG): Construct Startup Built In Test.
2013-10-31T21:06:55.551Z,1383253615.551 [SBIT] Loaded
2013-10-31T21:06:55.551Z,1383253615.551 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-10-31T21:06:55.552Z,1383253615.552 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-10-31T21:06:55.581Z,1383253615.581 [IBIT] Loaded
2013-10-31T21:06:55.582Z,1383253615.582 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-10-31T21:06:55.584Z,1383253615.584 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-10-31T21:06:55.705Z,1383253615.705 [CBIT] Loaded
2013-10-31T21:06:55.705Z,1383253615.705 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-10-31T21:06:55.705Z,1383253615.705 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-10-31T21:06:55.706Z,1383253615.706 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-10-31T21:06:55.881Z,1383253615.881 [BuoyancyServo] Loaded
2013-10-31T21:06:55.881Z,1383253615.881 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-10-31T21:06:55.893Z,1383253615.893 [ElevatorServo] Loaded
2013-10-31T21:06:55.893Z,1383253615.893 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-10-31T21:06:55.905Z,1383253615.905 [MassServo] Loaded
2013-10-31T21:06:55.905Z,1383253615.905 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-10-31T21:06:55.919Z,1383253615.919 [RudderServo] Loaded
2013-10-31T21:06:55.919Z,1383253615.919 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-10-31T21:06:55.930Z,1383253615.930 [ThrusterServo] Loaded
2013-10-31T21:06:55.931Z,1383253615.931 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-10-31T21:06:55.931Z,1383253615.931 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-10-31T21:06:55.932Z,1383253615.932 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-10-31T21:06:55.970Z,1383253615.970 [DepthRateCalculator] Loaded
2013-10-31T21:06:55.970Z,1383253615.970 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-10-31T21:06:58.827Z,1383253618.827 [HFRadarModelCalc] Loaded
2013-10-31T21:06:58.827Z,1383253618.827 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-10-31T21:06:58.844Z,1383253618.844 [NavChart] Loaded
2013-10-31T21:06:58.844Z,1383253618.844 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-10-31T21:06:58.850Z,1383253618.850 [PitchRateCalculator] Loaded
2013-10-31T21:06:58.850Z,1383253618.850 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-10-31T21:06:58.861Z,1383253618.861 [SpeedCalculator] Loaded
2013-10-31T21:06:58.861Z,1383253618.861 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-10-31T21:06:58.878Z,1383253618.878 [TempGradientCalculator] Loaded
2013-10-31T21:06:58.878Z,1383253618.878 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-10-31T21:06:58.884Z,1383253618.884 [YawRateCalculator] Loaded
2013-10-31T21:06:58.884Z,1383253618.884 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-10-31T21:06:58.931Z,1383253618.931 [Navigation] Loaded
2013-10-31T21:06:58.932Z,1383253618.932 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-10-31T21:06:58.932Z,1383253618.932 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-10-31T21:06:58.933Z,1383253618.933 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-10-31T21:06:59.185Z,1383253619.185 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-10-31T21:06:59.186Z,1383253619.186 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-10-31T21:06:59.210Z,1383253619.210 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-10-31T21:06:59.210Z,1383253619.210 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-10-31T21:06:59.260Z,1383253619.260 [VerticalControl](DEBUG): Construct VerticalControl.
2013-10-31T21:06:59.356Z,1383253619.356 [VerticalControl] Loaded
2013-10-31T21:06:59.356Z,1383253619.356 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-10-31T21:06:59.357Z,1383253619.357 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-10-31T21:06:59.415Z,1383253619.415 [HorizontalControl] Loaded
2013-10-31T21:06:59.415Z,1383253619.415 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-10-31T21:06:59.416Z,1383253619.416 [SpeedControl](DEBUG): Construct SpeedControl.
2013-10-31T21:06:59.417Z,1383253619.417 [SpeedControl] Loaded
2013-10-31T21:06:59.418Z,1383253619.418 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-10-31T21:06:59.418Z,1383253619.418 [LoopControl](DEBUG): Construct LoopControl.
2013-10-31T21:06:59.419Z,1383253619.419 [LoopControl] Loaded
2013-10-31T21:06:59.419Z,1383253619.419 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-10-31T21:06:59.420Z,1383253619.420 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-10-31T21:06:59.420Z,1383253619.420 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-10-31T21:06:59.426Z,1383253619.426 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-10-31T21:06:59.431Z,1383253619.431 [AsyncPiEstimator] Loaded
2013-10-31T21:06:59.431Z,1383253619.431 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-10-31T21:06:59.433Z,1383253619.433 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-10-31T21:06:59.433Z,1383253619.433 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-10-31T21:06:59.434Z,1383253619.434 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-10-31T21:06:59.652Z,1383253619.652 [AHRS_sp3003D] Loaded
2013-10-31T21:06:59.652Z,1383253619.652 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-10-31T21:06:59.666Z,1383253619.666 [Depth_Keller] Loaded
2013-10-31T21:06:59.667Z,1383253619.667 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-10-31T21:06:59.856Z,1383253619.856 [DVL_micro] Loaded
2013-10-31T21:06:59.856Z,1383253619.856 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-10-31T21:06:59.857Z,1383253619.857 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406D64E0
2013-10-31T21:06:59.948Z,1383253619.948 [NAL9602] Loaded
2013-10-31T21:06:59.948Z,1383253619.948 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-10-31T21:06:59.990Z,1383253619.990 [Onboard] Loaded
2013-10-31T21:06:59.990Z,1383253619.990 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-10-31T21:06:59.997Z,1383253619.997 [Radio_Freewave] Loaded
2013-10-31T21:06:59.997Z,1383253619.997 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-10-31T21:07:00.146Z,1383253620.146 [DAT] Loaded
2013-10-31T21:07:00.146Z,1383253620.146 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-10-31T21:07:00.147Z,1383253620.147 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-10-31T21:07:00.147Z,1383253620.147 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-10-31T21:07:00.252Z,1383253620.252 [CTD_NeilBrown] Loaded
2013-10-31T21:07:00.252Z,1383253620.252 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-10-31T21:07:00.254Z,1383253620.254 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407334E0
2013-10-31T21:07:00.287Z,1383253620.287 [WetLabsBB2FL] Loaded
2013-10-31T21:07:00.287Z,1383253620.287 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-10-31T21:07:00.288Z,1383253620.288 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407634E0
2013-10-31T21:07:00.289Z,1383253620.289 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-10-31T21:07:00.291Z,1383253620.291 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-10-31T21:07:00.292Z,1383253620.292 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-10-31T21:07:00.300Z,1383253620.300 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-10-31T21:07:00.301Z,1383253620.301 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407934E0
2013-10-31T21:07:00.305Z,1383253620.305 [Supervisor](DEBUG): Running supervisor.
2013-10-31T21:07:00.307Z,1383253620.307 [CommandLine](INFO): Thread ID is 7292
2013-10-31T21:07:00.309Z,1383253620.309 [controlThread](INFO): Thread ID is 7291
2013-10-31T21:07:00.309Z,1383253620.309 [controlThread](DEBUG): Initializing ControlThread
2013-10-31T21:07:00.310Z,1383253620.310 [CycleStarter](INFO): Thread ID is 7290
2013-10-31T21:07:00.310Z,1383253620.310 [InternalSim](DEBUG):  InternalSim initializing...
2013-10-31T21:07:00.347Z,1383253620.347 [logger](INFO): Thread ID is 7293
2013-10-31T21:07:00.375Z,1383253620.375 [SBIT](INFO): Initialize SBIT Component.
2013-10-31T21:07:00.376Z,1383253620.376 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:10711
2013-10-31T21:07:00.376Z,1383253620.376 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-10-31T21:07:00.376Z,1383253620.376 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-10-31T21:07:00.377Z,1383253620.377 [IBIT](INFO): Initialize IBIT Component.
2013-10-31T21:07:00.378Z,1383253620.378 [CBIT](DEBUG): Initialize CBIT Component.
2013-10-31T21:07:00.378Z,1383253620.378 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-10-31T21:07:00.391Z,1383253620.391 [AsyncPiEstimator](INFO): Thread ID is 7354
2013-10-31T21:07:00.391Z,1383253620.391 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-10-31T21:07:00.403Z,1383253620.403 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-31T21:07:00.404Z,1383253620.404 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-10-31T21:07:00.404Z,1383253620.404 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-10-31T21:07:00.404Z,1383253620.404 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-10-31T21:07:00.405Z,1383253620.405 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-10-31T21:07:00.405Z,1383253620.405 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-10-31T21:07:00.406Z,1383253620.406 [Navigation](DEBUG): Initializing Navigation.
2013-10-31T21:07:00.406Z,1383253620.406 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-10-31T21:07:00.408Z,1383253620.408 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-10-31T21:07:00.409Z,1383253620.409 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-10-31T21:07:00.409Z,1383253620.409 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-10-31T21:07:00.416Z,1383253620.416 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-10-31T21:07:00.422Z,1383253620.422 [DVL_micro](INFO): Thread ID is 7355
2013-10-31T21:07:00.431Z,1383253620.431 [DVL_micro](INFO): Initializing
2013-10-31T21:07:00.432Z,1383253620.432 [DVL_micro](INFO): start:Powering up
2013-10-31T21:07:00.432Z,1383253620.432 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-10-31T21:07:00.433Z,1383253620.433 [DVL_micro](INFO): Cycling power to configure device.
2013-10-31T21:07:00.448Z,1383253620.448 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-31T21:07:00.452Z,1383253620.452 [CTD_NeilBrown](INFO): Thread ID is 7356
2013-10-31T21:07:00.452Z,1383253620.452 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-10-31T21:07:00.474Z,1383253620.474 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-10-31T21:07:00.475Z,1383253620.475 [WetLabsBB2FL](INFO): Thread ID is 7357
2013-10-31T21:07:00.476Z,1383253620.476 [WetLabsBB2FL](INFO): Powering down
2013-10-31T21:07:00.510Z,1383253620.510 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2013-10-31T21:07:00.511Z,1383253620.511 [NavChartDb](INFO): Thread ID is 7358
2013-10-31T21:07:00.513Z,1383253620.513 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-10-31T21:07:00.515Z,1383253620.514 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-10-31T21:07:00.515Z,1383253620.515 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-10-31T21:07:00.515Z,1383253620.515 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-10-31T21:07:00.515Z,1383253620.515 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-10-31T21:07:00.516Z,1383253620.516 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-10-31T21:07:00.516Z,1383253620.516 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-10-31T21:07:00.516Z,1383253620.516 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-10-31T21:07:00.516Z,1383253620.516 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-10-31T21:07:00.531Z,1383253620.531 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-10-31T21:07:00.631Z,1383253620.631 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-10-31T21:07:00.633Z,1383253620.633 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-10-31T21:07:00.636Z,1383253620.636 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-31T21:07:00.677Z,1383253620.677 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-10-31T21:07:00.688Z,1383253620.688 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-31T21:07:00.703Z,1383253620.703 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-10-31T21:07:00.720Z,1383253620.720 [Default:D.SetSpeed](DEBUG): Construct.
2013-10-31T21:07:00.724Z,1383253620.724 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-10-31T21:07:00.741Z,1383253620.741 [Default:F.Wait](DEBUG): Construct Wait.
2013-10-31T21:07:00.744Z,1383253620.744 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS" >

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2013-10-31T21:07:00.748Z,1383253620.748 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-10-31T21:07:00.819Z,1383253620.819 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-10-31T21:07:00.834Z,1383253620.834 [Depth_Keller](ERROR): Pressure reading out of range: 915.671448 decibar
2013-10-31T21:07:00.943Z,1383253620.943 [Radio_Freewave](INFO): Powering up
2013-10-31T21:07:00.980Z,1383253620.980 [DAT](INFO): Powering up
2013-10-31T21:07:00.981Z,1383253620.981 [DAT](DEBUG): Initializing DAT.
2013-10-31T21:07:01.184Z,1383253621.184 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-10-31T21:07:01.191Z,1383253621.191 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-10-31T21:07:01.198Z,1383253621.198 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-10-31T21:07:01.200Z,1383253621.200 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-10-31T21:07:01.222Z,1383253621.222 [MassServo](DEBUG): Initializing EZServoServo.
2013-10-31T21:07:01.232Z,1383253621.232 [MassServo](DEBUG): Initializing MassServo.
2013-10-31T21:07:01.237Z,1383253621.237 [RudderServo](DEBUG): Initializing EZServoServo.
2013-10-31T21:07:01.244Z,1383253621.244 [RudderServo](DEBUG): Initializing RudderServo.
2013-10-31T21:07:01.270Z,1383253621.270 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-10-31T21:07:01.275Z,1383253621.275 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-10-31T21:07:02.570Z,1383253622.570 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-10-31T21:07:02.570Z,1383253622.570 [DVL_micro](INFO): Querying output modes
2013-10-31T21:07:02.570Z,1383253622.570 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-10-31T21:07:02.581Z,1383253622.581 [DVL_micro](DEBUG): cmdResponse: 01
2013-10-31T21:07:02.582Z,1383253622.582 [DVL_micro](INFO): NQ1 output enabled
2013-10-31T21:07:02.582Z,1383253622.582 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-10-31T21:07:02.593Z,1383253622.593 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-10-31T21:07:02.599Z,1383253622.599 [DVL_micro](INFO): pause:Powering down
2013-10-31T21:07:05.135Z,1383253625.135 [NAL9602](INFO): Powering up NAL9602
2013-10-31T21:07:15.618Z,1383253635.618 [NAL9602](INFO): NAL9602 initialized
2013-10-31T21:07:16.137Z,1383253636.137 [SBIT](IMPORTANT): Beginning Startup BIT
2013-10-31T21:07:16.139Z,1383253636.139 [CBIT](IMPORTANT): Beginning GF scan
2013-10-31T21:07:21.346Z,1383253641.346 [DAT](INFO): Powering down
2013-10-31T21:07:40.966Z,1383253660.966 [NAL9602](IMPORTANT): GPS fix at: 1383253682.00
2013-10-31T21:07:43.217Z,1383253663.217 [CBIT](IMPORTANT): No ground fault detected
2013-10-31T21:07:48.461Z,1383253668.461 [NAL9602](INFO): Powering down
2013-10-31T21:08:10.184Z,1383253690.184 [SBIT](IMPORTANT): SBIT PASSED
2013-10-31T21:08:10.575Z,1383253690.575 [MissionManager](IMPORTANT): Started mission Startup
2013-10-31T21:08:10.575Z,1383253690.575 [Startup] Running Loop=1
2013-10-31T21:08:10.575Z,1383253690.575 [Startup](INFO): Aggregate::initialize Startup
2013-10-31T21:08:10.575Z,1383253690.575 [Startup:A.GoToSurface] Running Loop=1
2013-10-31T21:08:10.575Z,1383253690.575 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:08:10.581Z,1383253690.581 [Startup:StartupSatComms] Running Loop=1
2013-10-31T21:08:10.581Z,1383253690.581 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-10-31T21:08:10.581Z,1383253690.581 [Startup:StartupSatComms:A] Running Loop=1
2013-10-31T21:08:10.978Z,1383253690.978 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-31T21:08:11.365Z,1383253691.365 [NAL9602](INFO): Powering up
2013-10-31T21:08:21.981Z,1383253701.981 [NAL9602](INFO): NAL9602 initialized
2013-10-31T21:08:41.064Z,1383253721.064 [NAL9602](IMPORTANT): GPS fix at: 1383253742.00
2013-10-31T21:08:41.078Z,1383253721.078 [Startup:StartupSatComms:A] Stopped
2013-10-31T21:08:41.078Z,1383253721.078 [Startup:StartupSatComms:B] Running Loop=1
2013-10-31T21:08:41.485Z,1383253721.485 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-31T21:09:04.441Z,1383253744.441 [NAL9602](INFO): SBD MO Status=1, MOMSN=20438, MT Status=0, MTMSN=0
2013-10-31T21:09:04.499Z,1383253744.499 [NAL9602](INFO): Sent 60 bytes from file Logs/20131031T202835/Courier0020.lzma
2013-10-31T21:09:04.499Z,1383253744.499 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:09:04.501Z,1383253744.501 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T202835/Courier0020.lzma.parts/0000.sbd
2013-10-31T21:09:12.976Z,1383253752.976 [NAL9602](INFO): SBD MO Status=1, MOMSN=20439, MT Status=0, MTMSN=0
2013-10-31T21:09:13.024Z,1383253753.024 [NAL9602](INFO): Sent 206 bytes from file Logs/20131031T210651/Courier0000.lzma
2013-10-31T21:09:13.024Z,1383253753.024 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:09:13.026Z,1383253753.026 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Courier0000.lzma.parts/0000.sbd
2013-10-31T21:09:23.640Z,1383253763.640 [NAL9602](INFO): SBD MO Status=1, MOMSN=20440, MT Status=0, MTMSN=0
2013-10-31T21:09:23.696Z,1383253763.696 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T202835/Express0021.lzma
2013-10-31T21:09:23.697Z,1383253763.697 [NAL9602](INFO): Packets left to send: 1
2013-10-31T21:09:23.698Z,1383253763.698 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T202835/Express0021.lzma.parts/0001.sbd
2013-10-31T21:09:35.777Z,1383253775.777 [NAL9602](INFO): SBD MO Status=1, MOMSN=20441, MT Status=0, MTMSN=0
2013-10-31T21:09:35.827Z,1383253775.827 [NAL9602](INFO): Sent 146 bytes from file Logs/20131031T202835/Express0021.lzma
2013-10-31T21:09:35.827Z,1383253775.827 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:09:35.828Z,1383253775.829 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T202835/Express0021.lzma.parts/0000.sbd
2013-10-31T21:09:41.091Z,1383253781.091 [Startup:StartupSatComms:B](INFO): Timed out from 2013-10-31T21:08:41.1Z
2013-10-31T21:09:41.091Z,1383253781.091 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-10-31T21:09:41.091Z,1383253781.091 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-10-31T21:09:41.091Z,1383253781.091 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-10-31T21:09:41.091Z,1383253781.091 [Startup:StartupSatComms:B] Stopped
2013-10-31T21:09:41.091Z,1383253781.091 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-10-31T21:09:41.092Z,1383253781.092 [Startup:StartupSatComms] Stopped
2013-10-31T21:09:41.092Z,1383253781.092 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-10-31T21:09:41.092Z,1383253781.092 [Startup](INFO): Completed Startup
2013-10-31T21:09:41.093Z,1383253781.093 [Startup] Stopped
2013-10-31T21:09:41.093Z,1383253781.093 [Startup](INFO): Aggregate::uninitialize Startup
2013-10-31T21:09:41.093Z,1383253781.093 [Startup:A.GoToSurface] Stopped
2013-10-31T21:09:41.093Z,1383253781.093 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:09:41.490Z,1383253781.490 [MissionManager](IMPORTANT): Started mission Default
2013-10-31T21:09:41.490Z,1383253781.490 [Default] Running Loop=1
2013-10-31T21:09:41.491Z,1383253781.491 [Default](INFO): Aggregate::initialize Default
2013-10-31T21:09:41.491Z,1383253781.491 [Default:D.SetSpeed] Running Loop=1
2013-10-31T21:09:41.491Z,1383253781.491 [Default:D.SetSpeed](DEBUG): Initialize.
2013-10-31T21:09:41.491Z,1383253781.491 [Default:E.GoToSurface] Running Loop=1
2013-10-31T21:09:41.491Z,1383253781.491 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:09:41.491Z,1383253781.491 [Default:Iridium] Running Loop=1
2013-10-31T21:09:41.491Z,1383253781.491 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-10-31T21:09:41.492Z,1383253781.492 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-31T21:09:41.492Z,1383253781.492 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:09:41.492Z,1383253781.492 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-10-31T21:09:41.492Z,1383253781.492 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:09:41.492Z,1383253781.492 [Default:E.GoToSurface] Running Loop=1
2013-10-31T21:09:41.498Z,1383253781.498 [Default:D.SetSpeed] Running Loop=1
2013-10-31T21:09:41.503Z,1383253781.503 [Default:CallIridium] Running Loop=1
2013-10-31T21:09:41.503Z,1383253781.503 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-10-31T21:09:41.503Z,1383253781.503 [Default:CallIridium:A] Running Loop=1
2013-10-31T21:09:41.505Z,1383253781.505 [Default:CallIridium:A] Stopped
2013-10-31T21:09:41.505Z,1383253781.505 [Default:CallIridium:B] Running Loop=1
2013-10-31T21:09:41.505Z,1383253781.505 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-10-31T21:09:41.511Z,1383253781.511 [Default:Iridium:B.GoToSurface] Stopped
2013-10-31T21:09:41.511Z,1383253781.511 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:09:41.511Z,1383253781.511 [Default:Iridium:Read_Iridium] Running Loop=1
2013-10-31T21:09:41.511Z,1383253781.511 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-31T21:09:41.516Z,1383253781.516 [Default:GPS] Running Loop=1
2013-10-31T21:09:41.516Z,1383253781.516 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-10-31T21:09:41.516Z,1383253781.516 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-31T21:09:41.516Z,1383253781.516 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:09:41.516Z,1383253781.516 [Default:GPS:B.GoToSurface] Running Loop=1
2013-10-31T21:09:41.516Z,1383253781.516 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:09:41.522Z,1383253781.522 [Default:GPS:B.GoToSurface] Stopped
2013-10-31T21:09:41.522Z,1383253781.522 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:09:41.522Z,1383253781.522 [Default:GPS:Read_GPS] Running Loop=1
2013-10-31T21:09:41.522Z,1383253781.522 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-31T21:09:41.923Z,1383253781.923 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-10-31T21:09:41.926Z,1383253781.926 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-10-31T21:09:49.534Z,1383253789.534 [NAL9602](INFO): SBD MO Status=1, MOMSN=20442, MT Status=0, MTMSN=0
2013-10-31T21:09:49.593Z,1383253789.593 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0001.lzma
2013-10-31T21:09:49.593Z,1383253789.593 [NAL9602](INFO): Packets left to send: 3
2013-10-31T21:09:49.594Z,1383253789.594 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0001.lzma.parts/0003.sbd
2013-10-31T21:10:03.332Z,1383253803.332 [NAL9602](INFO): SBD MO Status=1, MOMSN=20443, MT Status=0, MTMSN=0
2013-10-31T21:10:03.386Z,1383253803.386 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0001.lzma
2013-10-31T21:10:03.386Z,1383253803.386 [NAL9602](INFO): Packets left to send: 2
2013-10-31T21:10:03.387Z,1383253803.387 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0001.lzma.parts/0002.sbd
2013-10-31T21:10:16.296Z,1383253816.296 [NAL9602](INFO): SBD MO Status=1, MOMSN=20444, MT Status=0, MTMSN=0
2013-10-31T21:10:16.346Z,1383253816.346 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0001.lzma
2013-10-31T21:10:16.346Z,1383253816.346 [NAL9602](INFO): Packets left to send: 1
2013-10-31T21:10:16.347Z,1383253816.347 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0001.lzma.parts/0001.sbd
2013-10-31T21:10:27.235Z,1383253827.235 [NAL9602](INFO): SBD MO Status=1, MOMSN=20445, MT Status=0, MTMSN=0
2013-10-31T21:10:27.287Z,1383253827.287 [NAL9602](INFO): Sent 220 bytes from file Logs/20131031T210651/Express0001.lzma
2013-10-31T21:10:27.287Z,1383253827.287 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:10:27.288Z,1383253827.288 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0001.lzma.parts/0000.sbd
2013-10-31T21:10:38.206Z,1383253838.206 [NAL9602](INFO): SBD MO Status=0, MOMSN=20446, MT Status=0, MTMSN=0
2013-10-31T21:10:41.879Z,1383253841.879 [Default:Iridium:Read_Iridium] Stopped
2013-10-31T21:10:41.879Z,1383253841.879 [Default:Iridium](INFO): Completed Default:Iridium
2013-10-31T21:10:41.879Z,1383253841.879 [Default:Iridium] Stopped
2013-10-31T21:10:41.880Z,1383253841.880 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-10-31T21:10:41.880Z,1383253841.880 [Default:Iridium:A.SetSpeed] Stopped
2013-10-31T21:10:41.880Z,1383253841.880 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:10:41.880Z,1383253841.880 [Default:F.Wait] Running Loop=1
2013-10-31T21:10:41.880Z,1383253841.880 [Default:F.Wait](DEBUG): Initialize Wait Component.
2013-10-31T21:10:42.343Z,1383253842.343 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2013-10-31T21:10:42.343Z,1383253842.343 [Default:CallIridium:B] Stopped
2013-10-31T21:10:42.343Z,1383253842.343 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-10-31T21:10:42.343Z,1383253842.343 [Default:CallIridium](INFO): Completed Default:CallIridium
2013-10-31T21:10:42.343Z,1383253842.343 [Default:CallIridium] Stopped
2013-10-31T21:10:42.343Z,1383253842.343 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-10-31T21:10:43.129Z,1383253843.129 [NAL9602](IMPORTANT): GPS fix at: 1383253864.00
2013-10-31T21:10:43.146Z,1383253843.146 [Default:GPS:Read_GPS] Stopped
2013-10-31T21:10:43.146Z,1383253843.146 [Default:GPS:D] Running Loop=1
2013-10-31T21:10:43.573Z,1383253843.573 [Default:GPS:D] Stopped
2013-10-31T21:10:43.573Z,1383253843.573 [Default:GPS](INFO): Completed Default:GPS
2013-10-31T21:10:43.574Z,1383253843.574 [Default:GPS] Stopped
2013-10-31T21:10:43.574Z,1383253843.574 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-10-31T21:10:43.574Z,1383253843.574 [Default:GPS:A.SetSpeed] Stopped
2013-10-31T21:10:43.574Z,1383253843.574 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:11:04.028Z,1383253864.028 [NAL9602](INFO): Powering down
2013-10-31T21:15:39.034Z,1383254139.034 [Default:CallIridium] Running Loop=1
2013-10-31T21:15:39.034Z,1383254139.034 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-10-31T21:15:39.034Z,1383254139.034 [Default:CallIridium:A] Running Loop=1
2013-10-31T21:15:39.034Z,1383254139.034 [Default:CallIridium:A] Stopped
2013-10-31T21:15:39.035Z,1383254139.035 [Default:CallIridium:B] Running Loop=1
2013-10-31T21:15:39.035Z,1383254139.035 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-10-31T21:15:44.033Z,1383254144.033 [Default:Iridium] Running Loop=1
2013-10-31T21:15:44.033Z,1383254144.033 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-10-31T21:15:44.034Z,1383254144.034 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-31T21:15:44.034Z,1383254144.034 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:15:44.034Z,1383254144.034 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-10-31T21:15:44.034Z,1383254144.034 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:15:44.035Z,1383254144.035 [Default:Iridium:B.GoToSurface] Stopped
2013-10-31T21:15:44.035Z,1383254144.035 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:15:44.035Z,1383254144.035 [Default:Iridium:Read_Iridium] Running Loop=1
2013-10-31T21:15:44.035Z,1383254144.035 [Default:GPS] Running Loop=1
2013-10-31T21:15:44.035Z,1383254144.035 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-10-31T21:15:44.035Z,1383254144.035 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-31T21:15:44.036Z,1383254144.036 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:15:44.036Z,1383254144.036 [Default:GPS:B.GoToSurface] Running Loop=1
2013-10-31T21:15:44.036Z,1383254144.036 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:15:44.036Z,1383254144.036 [Default:GPS:B.GoToSurface] Stopped
2013-10-31T21:15:44.037Z,1383254144.037 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:15:44.037Z,1383254144.037 [Default:GPS:Read_GPS] Running Loop=1
2013-10-31T21:15:44.836Z,1383254144.836 [NAL9602](INFO): Powering up
2013-10-31T21:15:55.299Z,1383254155.299 [NAL9602](INFO): NAL9602 initialized
2013-10-31T21:16:12.833Z,1383254172.833 [NAL9602](INFO): SBD MO Status=1, MOMSN=20447, MT Status=0, MTMSN=0
2013-10-31T21:16:12.883Z,1383254172.883 [NAL9602](INFO): Sent 60 bytes from file Logs/20131031T210651/Courier0004.lzma
2013-10-31T21:16:12.883Z,1383254172.883 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:16:12.885Z,1383254172.885 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Courier0004.lzma.parts/0000.sbd
2013-10-31T21:16:22.740Z,1383254182.740 [NAL9602](INFO): SBD MO Status=1, MOMSN=20448, MT Status=0, MTMSN=0
2013-10-31T21:16:22.798Z,1383254182.798 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0005.lzma
2013-10-31T21:16:22.798Z,1383254182.798 [NAL9602](INFO): Packets left to send: 2
2013-10-31T21:16:22.800Z,1383254182.800 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0005.lzma.parts/0002.sbd
2013-10-31T21:16:33.359Z,1383254193.359 [NAL9602](INFO): SBD MO Status=1, MOMSN=20449, MT Status=0, MTMSN=0
2013-10-31T21:16:33.407Z,1383254193.407 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0005.lzma
2013-10-31T21:16:33.407Z,1383254193.407 [NAL9602](INFO): Packets left to send: 1
2013-10-31T21:16:33.408Z,1383254193.408 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0005.lzma.parts/0001.sbd
2013-10-31T21:16:45.143Z,1383254205.143 [NAL9602](INFO): SBD MO Status=1, MOMSN=20450, MT Status=0, MTMSN=0
2013-10-31T21:16:45.197Z,1383254205.197 [NAL9602](INFO): Sent 112 bytes from file Logs/20131031T210651/Express0005.lzma
2013-10-31T21:16:45.197Z,1383254205.197 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:16:45.201Z,1383254205.201 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0005.lzma.parts/0000.sbd
2013-10-31T21:16:57.376Z,1383254217.376 [NAL9602](INFO): SBD MO Status=0, MOMSN=20451, MT Status=0, MTMSN=0
2013-10-31T21:17:01.002Z,1383254221.002 [Default:Iridium:Read_Iridium] Stopped
2013-10-31T21:17:01.003Z,1383254221.003 [Default:Iridium](INFO): Completed Default:Iridium
2013-10-31T21:17:01.003Z,1383254221.003 [Default:Iridium] Stopped
2013-10-31T21:17:01.003Z,1383254221.003 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-10-31T21:17:01.003Z,1383254221.003 [Default:Iridium:A.SetSpeed] Stopped
2013-10-31T21:17:01.003Z,1383254221.003 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:17:01.472Z,1383254221.472 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2013-10-31T21:17:01.472Z,1383254221.472 [Default:CallIridium:B] Stopped
2013-10-31T21:17:01.473Z,1383254221.473 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-10-31T21:17:01.473Z,1383254221.473 [Default:CallIridium](INFO): Completed Default:CallIridium
2013-10-31T21:17:01.473Z,1383254221.473 [Default:CallIridium] Stopped
2013-10-31T21:17:01.473Z,1383254221.473 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-10-31T21:17:02.243Z,1383254222.243 [NAL9602](IMPORTANT): GPS fix at: 1383254243.00
2013-10-31T21:17:02.275Z,1383254222.275 [Default:GPS:Read_GPS] Stopped
2013-10-31T21:17:02.275Z,1383254222.275 [Default:GPS:D] Running Loop=1
2013-10-31T21:17:02.677Z,1383254222.677 [Default:GPS:D] Stopped
2013-10-31T21:17:02.677Z,1383254222.677 [Default:GPS](INFO): Completed Default:GPS
2013-10-31T21:17:02.677Z,1383254222.677 [Default:GPS] Stopped
2013-10-31T21:17:02.677Z,1383254222.677 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-10-31T21:17:02.677Z,1383254222.677 [Default:GPS:A.SetSpeed] Stopped
2013-10-31T21:17:02.678Z,1383254222.678 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:17:23.114Z,1383254243.114 [NAL9602](INFO): Powering down
2013-10-31T21:21:58.115Z,1383254518.115 [Default:CallIridium] Running Loop=1
2013-10-31T21:21:58.115Z,1383254518.115 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-10-31T21:21:58.115Z,1383254518.115 [Default:CallIridium:A] Running Loop=1
2013-10-31T21:21:58.116Z,1383254518.116 [Default:CallIridium:A] Stopped
2013-10-31T21:21:58.116Z,1383254518.116 [Default:CallIridium:B] Running Loop=1
2013-10-31T21:21:58.116Z,1383254518.116 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-10-31T21:22:03.122Z,1383254523.122 [Default:Iridium] Running Loop=1
2013-10-31T21:22:03.122Z,1383254523.122 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-10-31T21:22:03.122Z,1383254523.122 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-31T21:22:03.122Z,1383254523.122 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:22:03.122Z,1383254523.122 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-10-31T21:22:03.122Z,1383254523.122 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:22:03.123Z,1383254523.123 [Default:Iridium:B.GoToSurface] Stopped
2013-10-31T21:22:03.123Z,1383254523.123 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:22:03.123Z,1383254523.123 [Default:Iridium:Read_Iridium] Running Loop=1
2013-10-31T21:22:03.123Z,1383254523.123 [Default:GPS] Running Loop=1
2013-10-31T21:22:03.123Z,1383254523.123 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-10-31T21:22:03.124Z,1383254523.124 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-31T21:22:03.124Z,1383254523.124 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:22:03.124Z,1383254523.124 [Default:GPS:B.GoToSurface] Running Loop=1
2013-10-31T21:22:03.124Z,1383254523.124 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:22:03.125Z,1383254523.125 [Default:GPS:B.GoToSurface] Stopped
2013-10-31T21:22:03.125Z,1383254523.125 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:22:03.125Z,1383254523.125 [Default:GPS:Read_GPS] Running Loop=1
2013-10-31T21:22:03.901Z,1383254523.901 [NAL9602](INFO): Powering up
2013-10-31T21:22:14.375Z,1383254534.375 [NAL9602](INFO): NAL9602 initialized
2013-10-31T21:22:37.063Z,1383254557.063 [NAL9602](INFO): SBD MO Status=1, MOMSN=20452, MT Status=0, MTMSN=0
2013-10-31T21:22:37.110Z,1383254557.110 [NAL9602](INFO): Sent 58 bytes from file Logs/20131031T210651/Courier0008.lzma
2013-10-31T21:22:37.111Z,1383254557.111 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:22:37.112Z,1383254557.112 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Courier0008.lzma.parts/0000.sbd
2013-10-31T21:23:04.607Z,1383254584.607 [NAL9602](INFO): SBD MO Status=2, MOMSN=20453, MT Status=0, MTMSN=0
2013-10-31T21:23:04.608Z,1383254584.608 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-10-31T21:23:04.608Z,1383254584.608 [NAL9602](INFO): XMIT Failed. Starting over.
2013-10-31T21:23:05.803Z,1383254585.803 [NAL9602](IMPORTANT): GPS fix at: 1383254607.00
2013-10-31T21:23:05.819Z,1383254585.819 [Default:GPS:Read_GPS] Stopped
2013-10-31T21:23:05.819Z,1383254585.819 [Default:GPS:D] Running Loop=1
2013-10-31T21:23:06.228Z,1383254586.228 [Default:GPS:D] Stopped
2013-10-31T21:23:06.229Z,1383254586.229 [Default:GPS](INFO): Completed Default:GPS
2013-10-31T21:23:06.229Z,1383254586.229 [Default:GPS] Stopped
2013-10-31T21:23:06.229Z,1383254586.229 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-10-31T21:23:06.229Z,1383254586.229 [Default:GPS:A.SetSpeed] Stopped
2013-10-31T21:23:06.229Z,1383254586.229 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:23:17.659Z,1383254597.659 [NAL9602](INFO): SBD MO Status=1, MOMSN=20453, MT Status=0, MTMSN=0
2013-10-31T21:23:17.709Z,1383254597.709 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0009.lzma
2013-10-31T21:23:17.710Z,1383254597.710 [NAL9602](INFO): Packets left to send: 1
2013-10-31T21:23:17.711Z,1383254597.711 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0009.lzma.parts/0001.sbd
2013-10-31T21:23:27.063Z,1383254607.063 [NAL9602](INFO): SBD MO Status=1, MOMSN=20454, MT Status=0, MTMSN=0
2013-10-31T21:23:27.112Z,1383254607.112 [NAL9602](INFO): Sent 238 bytes from file Logs/20131031T210651/Express0009.lzma
2013-10-31T21:23:27.112Z,1383254607.112 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:23:27.113Z,1383254607.113 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0009.lzma.parts/0000.sbd
2013-10-31T21:23:38.459Z,1383254618.459 [NAL9602](INFO): SBD MO Status=0, MOMSN=20455, MT Status=0, MTMSN=0
2013-10-31T21:23:42.207Z,1383254622.207 [Default:Iridium:Read_Iridium] Stopped
2013-10-31T21:23:42.207Z,1383254622.207 [Default:Iridium](INFO): Completed Default:Iridium
2013-10-31T21:23:42.207Z,1383254622.207 [Default:Iridium] Stopped
2013-10-31T21:23:42.208Z,1383254622.208 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-10-31T21:23:42.208Z,1383254622.208 [Default:Iridium:A.SetSpeed] Stopped
2013-10-31T21:23:42.208Z,1383254622.208 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:23:42.688Z,1383254622.688 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2013-10-31T21:23:42.688Z,1383254622.688 [Default:CallIridium:B] Stopped
2013-10-31T21:23:42.688Z,1383254622.688 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-10-31T21:23:42.688Z,1383254622.688 [Default:CallIridium](INFO): Completed Default:CallIridium
2013-10-31T21:23:42.688Z,1383254622.688 [Default:CallIridium] Stopped
2013-10-31T21:23:42.689Z,1383254622.689 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-10-31T21:23:52.626Z,1383254632.626 [NAL9602](INFO): Powering down
2013-10-31T21:28:42.638Z,1383254922.638 [Default:CallIridium] Running Loop=1
2013-10-31T21:28:42.638Z,1383254922.638 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-10-31T21:28:42.638Z,1383254922.638 [Default:CallIridium:A] Running Loop=1
2013-10-31T21:28:42.639Z,1383254922.639 [Default:CallIridium:A] Stopped
2013-10-31T21:28:42.639Z,1383254922.639 [Default:CallIridium:B] Running Loop=1
2013-10-31T21:28:42.639Z,1383254922.639 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-10-31T21:28:47.644Z,1383254927.644 [Default:Iridium] Running Loop=1
2013-10-31T21:28:47.645Z,1383254927.645 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-10-31T21:28:47.645Z,1383254927.645 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-10-31T21:28:47.645Z,1383254927.645 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:28:47.645Z,1383254927.645 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-10-31T21:28:47.645Z,1383254927.645 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:28:47.646Z,1383254927.646 [Default:Iridium:B.GoToSurface] Stopped
2013-10-31T21:28:47.646Z,1383254927.646 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:28:47.646Z,1383254927.646 [Default:Iridium:Read_Iridium] Running Loop=1
2013-10-31T21:28:47.646Z,1383254927.646 [Default:GPS] Running Loop=1
2013-10-31T21:28:47.646Z,1383254927.646 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-10-31T21:28:47.647Z,1383254927.647 [Default:GPS:A.SetSpeed] Running Loop=1
2013-10-31T21:28:47.647Z,1383254927.647 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-10-31T21:28:47.647Z,1383254927.647 [Default:GPS:B.GoToSurface] Running Loop=1
2013-10-31T21:28:47.647Z,1383254927.647 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-10-31T21:28:47.648Z,1383254927.648 [Default:GPS:B.GoToSurface] Stopped
2013-10-31T21:28:47.648Z,1383254927.648 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:28:47.648Z,1383254927.648 [Default:GPS:Read_GPS] Running Loop=1
2013-10-31T21:28:48.424Z,1383254928.424 [NAL9602](INFO): Powering up
2013-10-31T21:28:58.882Z,1383254938.882 [NAL9602](INFO): NAL9602 initialized
2013-10-31T21:29:13.908Z,1383254953.908 [NAL9602](INFO): SBD MO Status=1, MOMSN=20456, MT Status=0, MTMSN=0
2013-10-31T21:29:13.960Z,1383254953.960 [NAL9602](INFO): Sent 60 bytes from file Logs/20131031T210651/Courier0012.lzma
2013-10-31T21:29:13.961Z,1383254953.961 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:29:13.963Z,1383254953.963 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Courier0012.lzma.parts/0000.sbd
2013-10-31T21:29:25.009Z,1383254965.009 [NAL9602](INFO): SBD MO Status=1, MOMSN=20457, MT Status=0, MTMSN=0
2013-10-31T21:29:25.064Z,1383254965.064 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0013.lzma
2013-10-31T21:29:25.064Z,1383254965.064 [NAL9602](INFO): Packets left to send: 1
2013-10-31T21:29:25.066Z,1383254965.066 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0013.lzma.parts/0001.sbd
2013-10-31T21:29:45.405Z,1383254985.405 [NAL9602](INFO): SBD MO Status=1, MOMSN=20458, MT Status=0, MTMSN=0
2013-10-31T21:29:45.461Z,1383254985.461 [NAL9602](INFO): Sent 329 bytes from file Logs/20131031T210651/Express0013.lzma
2013-10-31T21:29:45.461Z,1383254985.461 [NAL9602](INFO): Packets left to send: 0
2013-10-31T21:29:45.463Z,1383254985.463 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0013.lzma.parts/0000.sbd
2013-10-31T21:30:05.163Z,1383255005.163 [NAL9602](INFO): SBD MO Status=2, MOMSN=20459, MT Status=2, MTMSN=0
2013-10-31T21:30:05.163Z,1383255005.163 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-10-31T21:30:05.163Z,1383255005.163 [NAL9602](INFO): XMIT Failed. Starting over.
2013-10-31T21:30:06.359Z,1383255006.359 [NAL9602](IMPORTANT): GPS fix at: 1383255027.00
2013-10-31T21:30:06.375Z,1383255006.375 [Default:GPS:Read_GPS] Stopped
2013-10-31T21:30:06.375Z,1383255006.375 [Default:GPS:D] Running Loop=1
2013-10-31T21:30:06.770Z,1383255006.770 [Default:GPS:D] Stopped
2013-10-31T21:30:06.770Z,1383255006.770 [Default:GPS](INFO): Completed Default:GPS
2013-10-31T21:30:06.771Z,1383255006.771 [Default:GPS] Stopped
2013-10-31T21:30:06.771Z,1383255006.771 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-10-31T21:30:06.771Z,1383255006.771 [Default:GPS:A.SetSpeed] Stopped
2013-10-31T21:30:06.771Z,1383255006.771 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:30:28.658Z,1383255028.658 [NAL9602](INFO): SBD MO Status=2, MOMSN=20459, MT Status=2, MTMSN=0
2013-10-31T21:30:28.658Z,1383255028.658 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-10-31T21:30:28.658Z,1383255028.658 [NAL9602](INFO): XMIT Failed. Starting over.
2013-10-31T21:30:34.815Z,1383255034.815 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:30:37.824Z,1383255037.824 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:30:42.044Z,1383255042.044 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:30:45.105Z,1383255045.105 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:30:49.247Z,1383255049.247 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:30:52.255Z,1383255052.255 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:30:56.590Z,1383255056.590 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:30:59.548Z,1383255059.548 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:03.718Z,1383255063.718 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:06.652Z,1383255066.652 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:15.265Z,1383255075.265 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:23.828Z,1383255083.828 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:32.473Z,1383255092.473 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:36.651Z,1383255096.651 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:45.673Z,1383255105.673 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:54.660Z,1383255114.660 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:31:58.838Z,1383255118.838 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-10-31T21:32:25.096Z,1383255145.096 [NAL9602](INFO): SBD MO Status=2, MOMSN=20459, MT Status=2, MTMSN=0
2013-10-31T21:32:25.096Z,1383255145.096 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2013-10-31T21:32:25.096Z,1383255145.096 [NAL9602](INFO): XMIT Failed. Starting over.
2013-10-31T21:32:35.673Z,1383255155.673 [NAL9602](INFO): SBD MO Status=0, MOMSN=20459, MT Status=0, MTMSN=0
2013-10-31T21:32:39.345Z,1383255159.345 [Default:Iridium:Read_Iridium] Stopped
2013-10-31T21:32:39.346Z,1383255159.346 [Default:Iridium](INFO): Completed Default:Iridium
2013-10-31T21:32:39.346Z,1383255159.346 [Default:Iridium] Stopped
2013-10-31T21:32:39.346Z,1383255159.346 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-10-31T21:32:39.346Z,1383255159.346 [Default:Iridium:A.SetSpeed] Stopped
2013-10-31T21:32:39.346Z,1383255159.346 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:32:39.809Z,1383255159.809 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2013-10-31T21:32:39.809Z,1383255159.809 [Default:CallIridium:B] Stopped
2013-10-31T21:32:39.810Z,1383255159.810 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-10-31T21:32:39.810Z,1383255159.810 [Default:CallIridium](INFO): Completed Default:CallIridium
2013-10-31T21:32:39.810Z,1383255159.810 [Default:CallIridium] Stopped
2013-10-31T21:32:39.810Z,1383255159.810 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-10-31T21:32:49.793Z,1383255169.793 [NAL9602](INFO): Powering down
2013-10-31T21:33:56.284Z,1383255236.284 [CommandLine](IMPORTANT): got command show variable NAL9602
2013-10-31T21:33:56.290Z,1383255236.290 [CommandLine](INFO): NAL9602.sendDataToShore (bool)
2013-10-31T21:33:56.291Z,1383255236.291 [CommandLine](INFO): NAL9602.loadControl (none)
2013-10-31T21:33:56.291Z,1383255236.291 [CommandLine](INFO): NAL9602.uart (none)
2013-10-31T21:33:56.292Z,1383255236.292 [CommandLine](INFO): NAL9602.baud (bit_per_second)
2013-10-31T21:33:56.298Z,1383255236.298 [CommandLine](INFO): NAL9602.gpsFailTimeout (minute)
2013-10-31T21:33:56.298Z,1383255236.298 [CommandLine](INFO): NAL9602.requestGGA (bool)
2013-10-31T21:33:56.298Z,1383255236.298 [CommandLine](INFO): NAL9602.loadAtStartup (bool)
2013-10-31T21:33:56.299Z,1383255236.299 [CommandLine](INFO): NAL9602.simulateHardware (bool)
2013-10-31T21:33:56.299Z,1383255236.299 [CommandLine](INFO): NAL9602.power (watt)
2013-10-31T21:33:56.300Z,1383255236.300 [CommandLine](INFO): NAL9602.power_platform_communications (watt)
2013-10-31T21:33:56.322Z,1383255236.322 [CommandLine](INFO): NAL9602.sigQuality (count)
2013-10-31T21:33:56.322Z,1383255236.322 [CommandLine](INFO): NAL9602.goodFix (bool)
2013-10-31T21:33:56.330Z,1383255236.330 [CommandLine](INFO): NAL9602.SNRSatellite_0 (count)
2013-10-31T21:33:56.330Z,1383255236.330 [CommandLine](INFO): NAL9602.SNRSatellite_1 (count)
2013-10-31T21:33:56.330Z,1383255236.330 [CommandLine](INFO): NAL9602.SNRSatellite_2 (count)
2013-10-31T21:33:56.331Z,1383255236.331 [CommandLine](INFO): NAL9602.SNRSatellite_3 (count)
2013-10-31T21:33:56.331Z,1383255236.331 [CommandLine](INFO): NAL9602.SNRSatellite_4 (count)
2013-10-31T21:33:56.332Z,1383255236.332 [CommandLine](INFO): NAL9602.SNRSatellite_5 (count)
2013-10-31T21:33:56.332Z,1383255236.332 [CommandLine](INFO): NAL9602.SNRSatellite_6 (count)
2013-10-31T21:33:56.332Z,1383255236.332 [CommandLine](INFO): NAL9602.SNRSatellite_7 (count)
2013-10-31T21:33:56.333Z,1383255236.333 [CommandLine](INFO): NAL9602.SNRSatellite_8 (count)
2013-10-31T21:33:56.333Z,1383255236.333 [CommandLine](INFO): NAL9602.SNRSatellite_9 (count)
2013-10-31T21:33:56.334Z,1383255236.334 [CommandLine](INFO): NAL9602.SNRSatellite_10 (count)
2013-10-31T21:33:56.334Z,1383255236.334 [CommandLine](INFO): NAL9602.SNRSatellite_11 (count)
2013-10-31T21:33:56.334Z,1383255236.334 [CommandLine](INFO): NAL9602.numSatellites (count)
2013-10-31T21:33:56.335Z,1383255236.335 [CommandLine](INFO): NAL9602.SOG (knot)
2013-10-31T21:33:56.335Z,1383255236.335 [CommandLine](INFO): NAL9602.COG (degree)
2013-10-31T21:33:56.336Z,1383255236.336 [CommandLine](INFO): NAL9602.time_fix (second)
2013-10-31T21:33:56.336Z,1383255236.336 [CommandLine](INFO): NAL9602.latitude_fix (degree)
2013-10-31T21:33:56.336Z,1383255236.336 [CommandLine](INFO): NAL9602.longitude_fix (degree)
2013-10-31T21:33:56.337Z,1383255236.337 [CommandLine](INFO): NAL9602.platform_communications (bool)
2013-10-31T21:33:56.341Z,1383255236.341 [CommandLine](INFO): NAL9602.durationOfLastRun (second)
2013-10-31T21:33:56.345Z,1383255236.345 [CommandLine](INFO): NAL9602.component_voltage (volt)
2013-10-31T21:33:56.346Z,1383255236.346 [CommandLine](INFO): NAL9602.component_avgVoltage (volt)
2013-10-31T21:33:56.346Z,1383255236.346 [CommandLine](INFO): NAL9602.component_current (milliampere)
2013-10-31T21:33:56.347Z,1383255236.347 [CommandLine](INFO): NAL9602.component_avgCurrent (milliampere)
2013-10-31T21:34:19.580Z,1383255259.580 [CommandLine](IMPORTANT): got command restart application
2013-10-31T21:34:20.773Z,1383255260.773 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-10-31T21:34:20.773Z,1383255260.773 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-10-31T21:34:20.953Z,1383255260.953 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-10-31T21:34:21.334Z,1383255261.334 [WetLabsBB2FL](INFO): Powering down
2013-10-31T21:34:21.354Z,1383255261.354 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-10-31T21:34:21.543Z,1383255261.543 [CTD_NeilBrown](INFO): Powering down
2013-10-31T21:34:21.554Z,1383255261.554 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-10-31T21:34:21.567Z,1383255261.567 [DVL_micro](INFO): uninitialize:Powering down
2013-10-31T21:34:21.574Z,1383255261.574 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-10-31T21:34:21.727Z,1383255261.727 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-10-31T21:34:21.736Z,1383255261.736 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-10-31T21:34:21.755Z,1383255261.755 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-10-31T21:34:21.757Z,1383255261.757 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-10-31T21:34:24.359Z,1383255264.359 [controlThread](DEBUG): Uninitializing ControlThread
2013-10-31T21:34:24.360Z,1383255264.360 [AHRS_sp3003D](INFO): Powering down
2013-10-31T21:34:24.447Z,1383255264.447 [NAL9602](INFO): Powering down
2013-10-31T21:34:24.449Z,1383255264.449 [DAT](INFO): Powering down
2013-10-31T21:34:24.450Z,1383255264.450 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-10-31T21:34:24.450Z,1383255264.450 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-10-31T21:34:24.451Z,1383255264.451 [Default] Stopped
2013-10-31T21:34:24.452Z,1383255264.452 [Default](INFO): Aggregate::uninitialize Default
2013-10-31T21:34:24.452Z,1383255264.452 [Default:D.SetSpeed] Stopped
2013-10-31T21:34:24.452Z,1383255264.452 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-10-31T21:34:24.452Z,1383255264.452 [Default:E.GoToSurface] Stopped
2013-10-31T21:34:24.452Z,1383255264.452 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-10-31T21:34:24.452Z,1383255264.452 [Default:F.Wait] Stopped
2013-10-31T21:34:24.452Z,1383255264.452 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2013-10-31T21:34:24.456Z,1383255264.456 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-10-31T21:34:24.457Z,1383255264.457 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-10-31T21:34:24.457Z,1383255264.457 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-10-31T21:34:24.457Z,1383255264.457 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-10-31T21:34:24.458Z,1383255264.458 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-10-31T21:34:24.458Z,1383255264.458 [BuoyancyServo](INFO): Powering down
2013-10-31T21:34:24.471Z,1383255264.471 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-10-31T21:34:24.471Z,1383255264.471 [ElevatorServo](INFO): Powering down
2013-10-31T21:34:24.472Z,1383255264.472 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-10-31T21:34:24.472Z,1383255264.472 [MassServo](INFO): Powering down
2013-10-31T21:34:24.473Z,1383255264.473 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-10-31T21:34:24.473Z,1383255264.473 [RudderServo](INFO): Powering down
2013-10-31T21:34:24.474Z,1383255264.474 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-10-31T21:34:24.474Z,1383255264.474 [ThrusterServo](INFO): Powering down
2013-10-31T21:34:24.475Z,1383255264.475 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-10-31T21:34:24.475Z,1383255264.475 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-10-31T21:34:24.475Z,1383255264.475 [CBIT](DEBUG): Uninitialize CBIT Component.